Forum: NGINX md5 fastcgi cache collisions

Was looking at my error log and noticed a whole bunch of errors like 
this:

2012/09/22 15:52:26 [crit] 641#0: *4896016 cache file
"/var/lib/nginx/fastcgicache/3/21/32d5a44032aadeeed2b1d027314ba213" has
md5 collision, client: x.x.x.x, server: www.example.com, request: "GET
/cr/denzelwashington/ HTTP/1.1", host: "www.example.com"

My fastcgi cache is setup as follows:

fastcgi_cache_path /var/lib/nginx/fastcgicache levels=1:2
keys_zone=MYCACHE:5m inactive=2h max_size=1g loader_files=1000
loader_threshold=2000;
map $http_cookie $no_cache { default 0; ~SESS 1; }
fastcgi_cache_key "$scheme$request_method$host$request_uri";
add_header X-My-Cache $upstream_cache_status;

/cr is actually a php file called like this in the nginx.conf from a
thread years ago:

location ~ ^/cr(/.*$|$) {
rewrite ^/cr(/.*$|$) /$1.php?mypath=$2 last;
}

Site's working fine...just wondering what's causing all the collisions.

Thanks.

Hello!

On Sat, Sep 22, 2012 at 04:39:47PM -0400, Ian M. Evans wrote:

> Was looking at my error log and noticed a whole bunch of errors like this:
>
> 2012/09/22 15:52:26 [crit] 641#0: *4896016 cache file
> "/var/lib/nginx/fastcgicache/3/21/32d5a44032aadeeed2b1d027314ba213" has
> md5 collision, client: x.x.x.x, server: www.example.com, request: "GET
> /cr/denzelwashington/ HTTP/1.1", host: "www.example.com"

Is the file reported is the same in all errors?

> thread years ago:
>
> location ~ ^/cr(/.*$|$) {
> rewrite ^/cr(/.*$|$) /$1.php?mypath=$2 last;
> }
>
> Site's working fine...just wondering what's causing all the collisions.

Most likely it's a corrupted cache file.  Looking into the cache
file should be enough to see if it's indeed corrupted.

Intresting question is to find out how the file was corrupted.
This may be either something "normal" like filesystem corruption
after power failure, or something in nginx.  The later case might
need investigation.

If you just want to get rid of the messages you may try to remove
the cache file, it should fix things.  Normal nginx behaviour is
to replace such currupted cache files with new responses, but it
looks like it doesn't work in your case, likely because responses
aren't cacheable.

Maxim Dounin

On 24/09/2012 8:27 PM, Maxim Dounin wrote:

> Is the file reported is the same in all errors?

Yes in the sense that the "cr" in /cr/nameofperson is an extensionless
php file.

> Most likely it's a corrupted cache file.  Looking into the cache
> file should be enough to see if it's indeed corrupted.

just did a 'more cachefilename' and it looks fine but the log reported a
collision.

> aren't cacheable.
I went to one of the pages. The error log reported an md5 collision. I
removed the file, cleared my cache and requested it again. Another md5
collision in the error log, but again the file looked fine.

Hello!

On Mon, Sep 24, 2012 at 11:07:14PM -0400, Ian Evans wrote:

> On 24/09/2012 8:27 PM, Maxim Dounin wrote:
>
> >Is the file reported is the same in all errors?
>
> Yes in the sense that the "cr" in /cr/nameofperson is an
> extensionless php file.

I mean to ask about cache file, as reported in the error message
provided.  But you may want to just provide several error messages
to show variations possible.

> >Most likely it's a corrupted cache file.  Looking into the cache
> >file should be enough to see if it's indeed corrupted.
>
> just did a 'more cachefilename' and it looks fine but the log
> reported a collision.

Fine - as a cache file, with binary header, "KEY: ..." line and so
on?

>
> I went to one of the pages. The error log reported an md5 collision.
> I removed the file, cleared my cache and requested it again. Another
> md5 collision in the error log, but again the file looked fine.

You mean - md5 collision is reported on first request after you've
removed the cache file?  Or on second request, when another cache
file is already created by first request?

What does nginx -V show?

And could you please provide hd/xxd of several first bytes of a
cache file, up to and including "KEY: " line?

It would be also good to look at config and debug log of two
requests after the cache file removal.

Maxim Dounin

On 25/09/2012 1:01 AM, Maxim Dounin wrote:
> I mean to ask about cache file, as reported in the error message
> provided.  But you may want to just provide several error messages
> to show variations possible.

2012/09/24 22:15:03 [crit] 641#0: *5061221 cache file
"/var/lib/nginx/fastcgicache/3/04/41c3d443a1763965e630855f45c2b043" has
md5 collision, client: x.x.x.x, server: www.example.com, request: "GET
/cr/tomselleck/ HTTP/1.1", host: "www.example.com"
2012/09/24 22:41:52 [crit] 641#0: *5062571 cache file
"/var/lib/nginx/fastcgicache/3/4d/c02f0ccb51ecff32ce8f8576384a54d3" has
md5 collision, client: x.x.x.x, server: www.example.com, request: "GET
/cr/katdennings/gallery HTTP/1.1", host: "www.example.com"
2012/09/24 22:53:31 [crit] 641#0: *5063073 cache file
"/var/lib/nginx/fastcgicache/4/1f/3be079f5446cf74fbdcc64c6400301f4" has
md5 collision, client: x.x.x.x, server: www.example.com, request: "GET
/cr/drewbarrymore/ HTTP/1.1", host: "www.example.com"

> Fine - as a cache file, with binary header, "KEY: ..." line and so
> on?

No they appear to be clean text files...no binary stuff or KEY: line in
them.

> You mean - md5 collision is reported on first request after you've
> removed the cache file?  Or on second request, when another cache
> file is already created by first request?

It was on the first request after I deleted it.

>
> What does nginx -V show?

nginx version: nginx/1.2.2
built by gcc 4.1.2 20080704 (Red Hat 4.1.2-52)
TLS SNI support disabled
configure arguments: --with-http_stub_status_module
--with-http_ssl_module --with-debug --with-http_gzip_static_module
--with-cc-opt='-I /usr/include' --with-ld-opt='-L /usr/lib'

>
> And could you please provide hd/xxd of several first bytes of a
> cache file, up to and including "KEY: " line?

As above, the fastcgi cache files are just plain html...is that wrong
>
> It would be also good to look at config and debug log of two
> requests after the cache file removal.

Right now, like a watched kettle that doesn't boil it's not happening as
I type this email...but it has happened in the last hour.

Hello!

On Tue, Sep 25, 2012 at 01:58:17AM -0400, Ian Evans wrote:

> "/var/lib/nginx/fastcgicache/3/4d/c02f0ccb51ecff32ce8f8576384a54d3"
> has md5 collision, client: x.x.x.x, server: www.example.com,
> request: "GET /cr/katdennings/gallery HTTP/1.1", host:
> "www.example.com"
> 2012/09/24 22:53:31 [crit] 641#0: *5063073 cache file
> "/var/lib/nginx/fastcgicache/4/1f/3be079f5446cf74fbdcc64c6400301f4"
> has md5 collision, client: x.x.x.x, server: www.example.com,
> request: "GET /cr/drewbarrymore/ HTTP/1.1", host: "www.example.com"

Ok, so there are different cache files affected.

> >Fine - as a cache file, with binary header, "KEY: ..." line and so
> >on?
>
> No they appear to be clean text files...no binary stuff or KEY: line
> in them.

This is the problem.

> >You mean - md5 collision is reported on first request after you've
> >removed the cache file?  Or on second request, when another cache
> >file is already created by first request?
>
> It was on the first request after I deleted it.

That's strange, as there shouldn't be the cache file to read from
(as you've just deleted it).

Are you using open_file_cache?  This might explain why there is a
lag between cache file removal and disappear of error messages.

> >What does nginx -V show?
>
> nginx version: nginx/1.2.2
> built by gcc 4.1.2 20080704 (Red Hat 4.1.2-52)
> TLS SNI support disabled
> configure arguments: --with-http_stub_status_module
> --with-http_ssl_module --with-debug --with-http_gzip_static_module
> --with-cc-opt='-I /usr/include' --with-ld-opt='-L /usr/lib'

Looks fine.

> >And could you please provide hd/xxd of several first bytes of a
> >cache file, up to and including "KEY: " line?
>
> As above, the fastcgi cache files are just plain html...is that wrong

Yes, it's wrong.  It's not something that should happen, cache
file header was lost somehow.

> >It would be also good to look at config and debug log of two
> >requests after the cache file removal.
>
> Right now, like a watched kettle that doesn't boil it's not
> happening as I type this email...but it has happened in the last
> hour.

If you are indeed using open_file_cache - please disable it and
try with another resource which reports the error from scratch.

--
Maxim Dounin
http://nginx.com/support.html

On 25/09/2012 9:16 AM, Maxim Dounin wrote:
> Are you using open_file_cache?  This might explain why there is a
> lag between cache file removal and disappear of error messages.

Don't have that in my nginx.conf

> If you are indeed using open_file_cache - please disable it and
> try with another resource which reports the error from scratch.
>

As above.

On 25/09/2012 9:16 AM, Maxim Dounin wrote:
>> "/var/lib/nginx/fastcgicache/3/04/41c3d443a1763965e630855f45c2b043"
>> request: "GET /cr/drewbarrymore/ HTTP/1.1", host: "www.example.com"
>
> lag between cache file removal and disappear of error messages.
> Looks fine.
>
>>> And could you please provide hd/xxd of several first bytes of a
>>> cache file, up to and including "KEY: " line?
>>
>> As above, the fastcgi cache files are just plain html...is that wrong
>
> Yes, it's wrong.  It's not something that should happen, cache
> file header was lost somehow.

Update...was randomly looking at some of the cache files. Found one that
is one of the /cr files in question:

aPpIaPd
KEY: httpGETwww.example.com/cr/brucewillis/


So that's interesting...