What conditions lead to a combined JS URL missing some content?

[Jason Stangroome]

Hi,

On a site that I manage with nginx 1.7.10 and mod_pagespeed 1.9.32.3 I see an HTML document served with a rewritten <script src>. The URL is essentially the following (anonymised):

http://www.example.com/_javascript,_cart.js+javascript,_livequery.js+javascript,_placeholder.js.pagespeed.jc.a36bFbp4lK.js

Normally, the response from requesting the URL looks like (function bodies truncated):

var mod_pagespeed_h34FaPZrlq = "(function(){...})();";

var mod_pagespeed_YcCOJapaa1 = "(function(){...})();";

var mod_pagespeed_ju6Vanmeqi = "(function(){...})();";

However, a little too often the response for the same URL is served (as a 200 OK) but with only the first two lines present (corresponding to two of the files). The third line, corresponding to the contents of the third file, is missing. Naturally this leads to JavaScript errors on the page.

Our pagespeed configuration is using the SERF proxy to retrieve the resources from a remote origin.

What conditions lead mod_pagespeed to successfully serve a request for a URL specifying three included files but only respond with the content of two?

What mod_pagespeed log entries or fetch logs should we be looking for to understand why this is occurring?

Regards,

Jason

[Maksim Orlovich]

That's definitely a "should not happen" sort of thing; and looking at the code I can't seem to find a path that would make us do that, either. So the variable is entirely missing (and not empty or wrong)? 

Any error/warning type messages from us that you can involving these files at all?

--
You received this message because you are subscribed to the Google Groups "ngx-pagespeed-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to ngx-pagespeed-di...@googlegroups.com.
Visit this group at http://groups.google.com/group/ngx-pagespeed-discuss.
For more options, visit https://groups.google.com/d/optout.

[Jason Stangroome]

Hi Maksim,

The variable is entirely missing. There is only 2 occurences of `var mod_pagespeed_` in the response instead of 3.

There are no issues reported in the pagespeed messages for these files. There are some Warnings reported for some HTML pages but at very different times to when we see the partial JS response. Everything else is Info entries that seem uninteresting.

The access logs for SERF fetching from the origin show that whenever any of the three involved files are requested from the origin we get a 200 OK response.

There is a lot of traffic through the pagespeed proxy servers so correlating the logs can be quite arduous so I was hoping there could be something specific to look for.

Regards,

Jason

To unsubscribe from this group and stop receiving emails from it, send an email to ngx-pagespeed-discuss+unsub...@googlegroups.com.

[Jason Stangroome]

Hi again,

We've found that when disabling the combine_* filters but still using the extend_cache filter, we would get intermittent 404 responses on arbitrary *.pagespeed.* urls. 

There not be any corresponding 404s from the origin (nor was there any corresponding fetch). There will also be 200 responses for the same pagespeed resource moments before and after the 404 on the same server.

We were able to capture our pagespeed message logs and nginx logs on some recent occurences and found what we believe is the problem and potentially undesirable Pagespeed behaviour.

I've included the relevant log entries below but my interpretation is that we are exceeding the background fetch queue size and Pagespeed is dropping some queue items. However, when dropping the queued item, a cache entry is also being recorded stating that the resource is "not-found". And this leads to a 404 when a non-background request is made for the resource. Further, by setting `pagespeed RateLimitBackgroundFetches off` we immediately see these intermittent 404s (usually every few minutes) disappear entirely.

I'd appreciate some feedback on my understand of this behaviour.

Logs:

I[Tue, 01 Dec 2015 01:42:01 GMT] [Info] [1069] Dropping request for http://www.example.com/logo.png
I[Tue, 01 Dec 2015 01:42:01 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 9 seconds.
I[Tue, 01 Dec 2015 01:42:01 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 9 seconds.
I[Tue, 01 Dec 2015 01:42:01 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 9 seconds.
I[Tue, 01 Dec 2015 01:42:01 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 9 seconds.
I[Tue, 01 Dec 2015 01:42:01 GMT] [Info] [1070] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 9 seconds.
I[Tue, 01 Dec 2015 01:42:02 GMT] [Info] [1070] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 8 seconds.
I[Tue, 01 Dec 2015 01:42:02 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 8 seconds.
I[Tue, 01 Dec 2015 01:42:03 GMT] [Info] [1070] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 7 seconds.
I[Tue, 01 Dec 2015 01:42:03 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 7 seconds.
I[Tue, 01 Dec 2015 01:42:03 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 7 seconds.
I[Tue, 01 Dec 2015 01:42:03 GMT] [Info] [1070] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 7 seconds.
I[Tue, 01 Dec 2015 01:42:05 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 5 seconds.
I[Tue, 01 Dec 2015 01:42:05 GMT] [Info] [1070] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 5 seconds.
I[Tue, 01 Dec 2015 01:42:05 GMT] [Info] [1070] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 5 seconds.
2015/12/01 01:42:05 [warn] 1070#0: [ngx_pagespeed 1.9.32.3-4448] logo.png:0:Resource based on http://www.example.com/logo.png but cannot access the original
I[Tue, 01 Dec 2015 01:42:10 GMT] [Info] [1069] HTTPCache key=http://www.example.com/logo.png fragment=example.com: remembering not-found status for 0 seconds.
2015/12/01 01:42:10 [warn] 1069#0: [ngx_pagespeed 1.9.32.3-4448] logo.png:0:Resource based on http://www.example.com/logo.png but cannot access the original
I[Tue, 01 Dec 2015 01:42:11 GMT] [Info] [1069] Cache entry is expired: http://www.example.com/logo.png (fragment=example.com)

[Maksim Orlovich]

Yeah, that sounds like a bug, and this is enough info to look for it:
we are supposed to be disregarding these sort of cache entries when
serving .pagespeed. URLs.
Looking into it (though this code changed a lot in trunk... better
look at it in branch first, I guess). Are the original URLs just
pagespeed.ce., or something else, too?

>>>> an email to ngx-pagespeed-di...@googlegroups.com.

>>>> Visit this group at
>>>> http://groups.google.com/group/ngx-pagespeed-discuss.
>>>> For more options, visit https://groups.google.com/d/optout.
>>>
>>>

> --
> You received this message because you are subscribed to the Google Groups
> "ngx-pagespeed-discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an

> email to ngx-pagespeed-di...@googlegroups.com.

[Jeff Kaufman]

(And thanks so much for the thorough debugging!)

[Maksim Orlovich]

Hmm, we are actually trying to be clever and failing at it. From
CacheableResourceBase::LoadHttpCacheCallback::Done:

case HTTPCache::kRecentFailure:
// (snip comment discussing the issue that's kind of out-of-date
since I rearranged some stuff)
if (not_cacheable_policy_ == Resource::kLoadEvenIfNotCacheable &&
(find_result.failure_details == kFetchStatusUncacheable200 ||
find_result.failure_details == kFetchStatusUncacheableError ||
find_result.failure_details == kFetchStatusEmpty)) {
resource_->recent_uncacheables_miss_->Add(1);
LoadAndSaveToCache();
} else {

This should clearly also handle kFetchStatusDropped, but the other
cases here should probably be included, too --- e.g.
kFetchStatusOtherError might be a 503 or something that was
intermittent. Maybe we should just always go to LoadAndSaveToCache in
kLoadEvenIfNotCacheable case (especially if we consider backporting,
since that doesn't keep track of failure cause reliably anyway)?
There is quite a bit of overlap between loadEvenIfNotCacheable and
!is_background_fetch, too.

[Jason Stangroome]

Maksim,

Yes, the original URLs are just *.pagespeed.ce.*

>>>> an email to ngx-pagespeed-discuss+unsub...@googlegroups.com.

>>>> Visit this group at
>>>> http://groups.google.com/group/ngx-pagespeed-discuss.
>>>> For more options, visit https://groups.google.com/d/optout.
>>>
>>>
> --
> You received this message because you are subscribed to the Google Groups
> "ngx-pagespeed-discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an

> email to ngx-pagespeed-discuss+unsub...@googlegroups.com.

[Jeff Kaufman]

Update: we have a draft fix for this that we're evaluating now.

>> >>>> an email to ngx-pagespeed-di...@googlegroups.com.

>> >>>> Visit this group at
>> >>>> http://groups.google.com/group/ngx-pagespeed-discuss.
>> >>>> For more options, visit https://groups.google.com/d/optout.
>> >>>
>> >>>
>> > --
>> > You received this message because you are subscribed to the Google
>> > Groups
>> > "ngx-pagespeed-discuss" group.
>> > To unsubscribe from this group and stop receiving emails from it, send
>> > an

>> > email to ngx-pagespeed-di...@googlegroups.com.

>> > Visit this group at
>> > http://groups.google.com/group/ngx-pagespeed-discuss.
>> > For more options, visit https://groups.google.com/d/optout.
>
> --
> You received this message because you are subscribed to the Google Groups
> "ngx-pagespeed-discuss" group.
> To unsubscribe from this group and stop receiving emails from it, send an

> email to ngx-pagespeed-di...@googlegroups.com.