Invalid signature in optimized resource URLs

[mbunzel]

We noticed that a new install of ngx_pagespeed (nginx 1.10.0 with ngx_pagespeed 1.11.33.2-stable on CentOS7) started serving an image with an invalid signature after a few hours of low traffic. UrlSigningKey was configured from the start and that particular image was definitely served correctly for a few hours. We purged the cache (local file cache with default shm metadata cache), restarted nginx for good measure and the image was working again until the problem recurred a few hours later. Another cache purge and nginx restart fixed the signature on this image, but over night a different image started showing the exact same problem.

Log entries:

Invalid resource signature for https://www.example.com/assets/img/redacted/logo.png.pagespeed.ce.eiOUFVYmzJIGaPzlladh.png provided. Expected qnW5iVzCbz Received IGaPzlladh Invalid resource signature for https://www.example.com/redacted/x3-pcs-redacted-product-name-69-0-2-12345.jpg.pagespeed.ic.GKxXl6W_kw-mm20F9cI9.jpg provided. Expected QgrusbOxZv Received -mm20F9cI9

I manually generated the HMAC-SHA1 signatures of the URLs to confirm that the "Expected" signature is correct. Both times I could find entries for an unrelated file matching the "Received" signature in the file cache (one jpeg and one css file), for example:

./rname/ce_RJT-PIosmieVi9iwDb/https,3A/,2Fwww.example.com/size/x3-pcs-redacted-product-name-69-0-2-12345.jpg.pagespeed.ic.NluRGUzKx8IGaPzlladh.jpg,40,40_, [...] ./prop_page/https,3A/,2Fwww.example.com/assets/img/redacted/logo.png.pagespeed.ce.eiOUFVYmzJIGaPzlladh_n79Ig3zfO6,40Desktop,40beacon_cohort,

We've not been able to reliably reproduce the issue, since it has only affected two images out of a few thousand so far and seems to happen randomly. The only thing both images have in common is that they appear twice on some pages, once near the top and once near the bottom, but so do other images that are unaffected.

[crowell]

that's really weird. are the rewritten urls in different directories when accepted and rejected?

Do you have an example url in the logs for when the correct qnW5iVzCbz signature is there?

[crowell]

also, are the images not showing up on the page when you visit, or are you just seeing this in the logs?

is it possible that there are just clients requesting an old url that is no longer valid (changed signing key and users are requesting the old url for example.)

[mbunzel]

are the rewritten urls in different directories when accepted and rejected?

Always the same url and file (local fs via LoadFromFile), and always the same hash. The same file with different hash contains the correct signature. But I'm not sure if any conclusions can be drawn from that, since only 2 files were affected as of yet.

Do you have an example url in the logs for when the correct qnW5iVzCbz signature is there?

According to our logs, the correct signature was served for a few hours until the first occurrence of the invalid signature. From that moment, nearly all requests contained the invalid signature until we restarted nginx and the metadata cache was cleared.

also, are the images not showing up on the page when you visit, or are you just seeing this in the logs?

The url with the broken signature was served to all clients (including, but not only, our web designers who noticed it first) until the nginx restart fixed it. There is no intermediary proxy or caching layer that could have served stale data. The signing key was in place the first time nginx was started (this was a fresh install) and never changed.

I tried looking through the source to see if I can find out more, but it'd take me quite a while to become familiar with how requests are processed. If I had to take a wild guess, I'd say that somehow the wrong signature (most likely one from an entirely different file that gets processed within the same request) is stored in the (shm?) cache for a particular cache key (url) and hash combination and reused from that moment forward.

[mbunzel]

Good news: I was able to reliably reproduce the issue. Bad news: The whole thing gets even weirder.

This shell script starts requesting the same (static) page over and over and after a while, the error_log will contain a line like this:

2016/05/27 18:43:31 [info] 19219#19233: [ngx_pagespeed 1.11.33.2-0] Invalid resource signature for http://www.example.com/assets/img/redacted/xtouch-icon.png.pagespeed.ic.Mnuro-NRey-DLqEIhm9e.png provided. Expected fDunWXYmQr Received -DLqEIhm9e

Note that all requests were made using curl and all resources were loaded from the local file system, so no HTTP request was ever made to xtouch-icon.png.pagespeed.ic.Mnuro-NRey-DLqEIhm9e.png.

From this point forward, the url will always be served with the invalid signature until the cache is purged. Again, there is always some other resource in the file cache that contains the invalid signature, which is valid for that file.

In rare cases the invalid signature the log entry complained about will actually become valid (i.e. only the url in the log entry works), and the expected signature will result in a 404.

I can't really share my full test case with you, but let me know if you want me to try something. I also managed to log an occurrence with a debug build if you're interested.

[crowell]

thanks for the info. additional logging would be helpful.

if you'd like to send it off-list you can send it to jcrowell@google.com I'll try to see if I can reproduce this locally.

Can you share the contents of the static page too, just so that i can have an easier time matching your setup?

[mbunzel]

if you'd like to send it off-list you can send it to jcrowell@google.com I'll try to see if I can reproduce this locally.

Thanks, just sent it.

Can you share the contents of the static page too, just so that i can have an easier time matching your setup?

That won't be possible atm but I'll try to reduce the static page to a minimal test case that I can share.