search

apache / incubator-pagespeed-ngx

Automatic PageSpeed optimization module for Nginx
http://ngxpagespeed.com/
Apache License 2.0
4.37k stars 364 forks source link

Problems with firefox ? #330

Closed ghost closed 11 years ago

ghost commented 11 years ago

I've tested ngx_pagespeed on multiples configurations and found that on about 50% of instances (randomly) encountered a problem with firefox on www.pratique.fr :

http://www.webpagetest.org/result/130503_1E_DKC/1/details/

I've never been able to reproduce the problem with Chrome.

It seems that time-outs happen when loading the page.

Any idea?

oschaaf commented 11 years ago

Looking at the response headers, it seems like you are running an experiment right? Maybe that explains the randomness of the timeouts: Could firefox run in to trouble with one of the groups in the experiment?

ghost commented 11 years ago

hello oschaaf. The experiment started today. We have had the problem since installing ngx_pagespeed a few days ago.

jeffkaufman commented 11 years ago

I got this to reproduce on chrome with the developer-tools networking tab open. It shows the html download as failed:

tmp pratique

Looking at the response body, it appears to have only downloaded part of the html, cutting off after:

<span class="prahr 45CBCBC02D1F1FCCCCCC19C0C14ACB46CAC3431944C11F4342484A46C143C11EC0464342431945CB4E

Trying again it cuts off in a different place:

Location meublée </span></li><li><span class="prahr 45CBCB

Is there anything unusual in your server logs?

You html is on the large side (200k) and it's full of large base16 classes (ex 45CBCBC02D1F1FCCCCCC19C0C14ACB46CAC3431944C11F484F424ACB464F491E4E43C3414843431E424A4BC1431E4DC3C1464B46CAC3431945CB4E48) but those shouldn't break ngx_pagespeed.

Aha! I can reproduce this with curl as well, but only if I give -H Accept-Encoding:gzip:

$ curl -s -H Accept-Encoding:gzip http://www.pratique.fr/1-patronal.html > tmp.html
$ cat tmp.html | gunzip
...
<span class="prahr 45CBCBC02D1F1FCCCCCC19C0C14ACB46CAC3431944C11FC2C341C44349CB464F49C21E4A494A4
gzip: stdin: unexpected end of file

I'm seeing failures only some of the time.

try 3: after byte 16384
try 6: after byte 18426
try 13: after byte 16384
try 15: after byte 16384
try 22: after byte 16384

Trying http://www.pratique.fr/1-patronal.html?ModPagespeed=off 20 times I can't get this to repeat, so it's definitely an ngx_pagespeed bug.

Downloading the html and testing on jefftk.com I see the same problem:

 http://www.jefftk.com/test/tmp.patronal

Here's the error log at debug:

2013/05/03 18:13:47 [debug] 8137#0: epoll: fd:6 ev:0001 d:0000000001BA6350
2013/05/03 18:13:47 [debug] 8137#0: accept on 0.0.0.0:80, ready: 0
2013/05/03 18:13:47 [debug] 8137#0: posix_memalign: 0000000001C21140:256 @16
2013/05/03 18:13:47 [debug] 8137#0: *2 accept: 66.102.14.24 fd:3
2013/05/03 18:13:47 [debug] 8137#0: *2 event timer add: 3: 60000:1367619287981
2013/05/03 18:13:47 [debug] 8137#0: *2 reusable connection: 1
2013/05/03 18:13:47 [debug] 8137#0: *2 epoll add event: fd:3 op:1 ev:80000001
2013/05/03 18:13:47 [debug] 8137#0: timer delta: 6111
2013/05/03 18:13:47 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:13:47 [debug] 8137#0: worker cycle
2013/05/03 18:13:47 [debug] 8137#0: epoll timer: 60000
2013/05/03 18:13:47 [debug] 8137#0: epoll: fd:3 ev:0001 d:0000000001BA64C1
2013/05/03 18:13:47 [debug] 8137#0: *2 http wait request handler
2013/05/03 18:13:47 [debug] 8137#0: *2 posix_memalign: 0000000001C27F00:256 @16
2013/05/03 18:13:47 [debug] 8137#0: *2 malloc: 0000000001C28350:1024
2013/05/03 18:13:47 [debug] 8137#0: *2 recv: fd:3 205 of 1024
2013/05/03 18:13:47 [debug] 8137#0: *2 reusable connection: 0
2013/05/03 18:13:47 [debug] 8137#0: *2 posix_memalign: 0000000001C1FC30:4096 @16
2013/05/03 18:13:47 [debug] 8137#0: *2 http process request line
2013/05/03 18:13:47 [debug] 8137#0: *2 http request line: "GET /test/tmp.patronal HTTP/1.1"
2013/05/03 18:13:47 [debug] 8137#0: *2 http uri: "/test/tmp.patronal"
2013/05/03 18:13:47 [debug] 8137#0: *2 http args: ""
2013/05/03 18:13:47 [debug] 8137#0: *2 http exten: "patronal"
2013/05/03 18:13:47 [debug] 8137#0: *2 http process request header line
2013/05/03 18:13:47 [debug] 8137#0: *2 http header: "User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"
2013/05/03 18:13:47 [debug] 8137#0: *2 http header: "Host: www.jefftk.com"
2013/05/03 18:13:47 [debug] 8137#0: *2 http header: "Accept: */*"
2013/05/03 18:13:47 [debug] 8137#0: *2 http header: "Accept-Encoding: gzip"
2013/05/03 18:13:47 [debug] 8137#0: *2 http header done
2013/05/03 18:13:47 [debug] 8137#0: *2 event timer del: 3: 1367619287981
2013/05/03 18:13:47 [debug] 8137#0: *2 rewrite phase: 0
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: "/"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: "wsgi"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: "50x.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: ~ "\.html$"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: ~ "^/?\+$"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: ~ "^/ngx_pagespeed_static/"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: ~ "^/ngx_pagespeed_beacon$"
2013/05/03 18:13:47 [debug] 8137#0: *2 test location: ~ "\.jpg$"
2013/05/03 18:13:47 [debug] 8137#0: *2 using configuration "/"
2013/05/03 18:13:47 [debug] 8137#0: *2 http cl:-1 max:1048576
2013/05/03 18:13:47 [debug] 8137#0: *2 rewrite phase: 2
2013/05/03 18:13:47 [debug] 8137#0: *2 post rewrite phase: 3
2013/05/03 18:13:47 [debug] 8137#0: *2 generic phase: 4
2013/05/03 18:13:47 [debug] 8137#0: *2 generic phase: 5
2013/05/03 18:13:47 [debug] 8137#0: *2 access phase: 6
2013/05/03 18:13:47 [debug] 8137#0: *2 access phase: 7
2013/05/03 18:13:47 [debug] 8137#0: *2 post access phase: 8
2013/05/03 18:13:47 [debug] 8137#0: *2 generic phase: 9
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed handler "/test/tmp.patronal"
2013/05/03 18:13:47 [debug] 8137#0: *2 Passing on content handling for non-pagespeed resource 'http://www.jefftk.com/test/tmp.patronal'
2013/05/03 18:13:47 [debug] 8137#0: *2 try files phase: 10
2013/05/03 18:13:47 [debug] 8137#0: *2 http script var: "/test/tmp.patronal"
2013/05/03 18:13:47 [debug] 8137#0: *2 http script copy: ".html"
2013/05/03 18:13:47 [debug] 8137#0: *2 trying to use file: "/test/tmp.patronal.html" "/var/www/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 try file uri: "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 content phase: 11
2013/05/03 18:13:47 [debug] 8137#0: *2 content phase: 12
2013/05/03 18:13:47 [debug] 8137#0: *2 content phase: 13
2013/05/03 18:13:47 [debug] 8137#0: *2 http filename: "/var/www/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 add cleanup: 0000000001C20B98
2013/05/03 18:13:47 [debug] 8137#0: *2 http static fd: 11
2013/05/03 18:13:47 [debug] 8137#0: *2 http set discard body
2013/05/03 18:13:47 [debug] 8137#0: *2 posix_memalign: 0000000001C1E110:4096 @16
2013/05/03 18:13:47 [debug] 8137#0: *2 epoll add event: fd:12 op:1 ev:00000001
2013/05/03 18:13:47 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/181347:VERBOSE1:proxy_fetch.cc(496)] Setting user-agent to curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
2013/05/03 18:13:47 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/181347:VERBOSE1:proxy_fetch.cc(510)] Attaching RewriteDriver 0x1c230d0 to HtmlRewriter 0x1c26fa0
2013/05/03 18:13:47 [debug] 8137#0: *2 http cleanup add: 0000000001C20BF8
2013/05/03 18:13:47 [debug] 8137#0: *2 HTTP/1.1 200 OK
Server: nginx/1.4.0
Date: Fri, 03 May 2013 22:13:47 GMT
Content-Type: text/html
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding
Cache-Control: max-age=0, no-cache
X-Page-Speed: 1.5.27.2-2912
Content-Encoding: gzip

2013/05/03 18:13:47 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C1E3B0, pos 0000000001C1E3B0, size: 266 file: 0, size: 0
2013/05/03 18:13:47 [debug] 8137#0: *2 http write filter: l:0 f:0 s:266
2013/05/03 18:13:47 [debug] 8137#0: *2 http output filter "/test/tmp.patronal.html?"
2013/05/03 18:13:47 [debug] 8137#0: *2 http copy filter: "/test/tmp.patronal.html?"
2013/05/03 18:13:47 [debug] 8137#0: *2 malloc: 0000000001C29410:32768
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 32768, 0
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/181347:VERBOSE1:proxy_fetch.cc(555)] Parse successfully started.
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 32768, 32768
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 32768, 65536
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 32768, 98304
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 32768, 131072
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 32768, 163840
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: *2 read: 11, 0000000001C29410, 12649, 196608
2013/05/03 18:13:47 [debug] 8137#0: *2 http postpone filter "/test/tmp.patronal.html?" 0000000001C1E5A8
2013/05/03 18:13:47 [debug] 8137#0: *2 http pagespeed filter "/test/tmp.patronal.html"
2013/05/03 18:13:47 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/181347:VERBOSE1:proxy_fetch.cc(931)] Fetch result:1 http://www.jefftk.com/test/tmp.patronal : 200
2013/05/03 18:13:47 [debug] 8137#0: *2 http copy filter: -2 "/test/tmp.patronal.html?"
2013/05/03 18:13:47 [debug] 8137#0: *2 http finalize request: -2, "/test/tmp.patronal.html?" a:1, c:1
2013/05/03 18:13:47 [debug] 8137#0: *2 event timer add: 3: 60000:1367619287981
2013/05/03 18:13:47 [debug] 8137#0: timer delta: 0
2013/05/03 18:13:47 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:13:47 [debug] 8137#0: worker cycle
2013/05/03 18:13:47 [debug] 8137#0: epoll timer: 60000
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://css.pratique.fr/sites/default/files/css/cdn_css_464b7d0076413d1215ec5f51d0574379.css'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://css.pratique.fr/sites/default/files/css/cdn_css_464b7d0076413d1215ec5f51d0574379.css'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://css.pratique.fr/sites/default/files/css/cdn_css_464b7d0076413d1215ec5f51d0574379.css'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:30:Found script with src http://js.pratique.fr/sites/all/themes/kluh/js/dynamic-font-resize.js
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/all/themes/kluh/js/dynamic-font-resize.js'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:116:Found script with src http://adnext.fr/richmedia.adv?id=97558&tag=1&s=all
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://adnext.fr/richmedia.adv?id=97558&tag=1&s=all'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:476:Found script with src http://adnext.fr/richmedia.adv?popunderid=97558&tag=3&s=big
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://adnext.fr/richmedia.adv?popunderid=97558&tag=3&s=big'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/all/themes/kluh/js/dynamic-font-resize.js'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://adnext.fr/richmedia.adv?id=97558&tag=1&s=all'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://adnext.fr/richmedia.adv?popunderid=97558&tag=3&s=big'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/themes/kluh/images3/logo-pratique.png'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/themes/kluh/images3/accueil.png'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/modules/contrib/print/icons/print_icon.gif'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/modules/contrib/print/icons/mail_icon.gif'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/default/files/imagecache/dossier_main/articles/1-pourcent-patronal.jpg'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://css.pratique.fr/sites/default/files/css/cdn_css_464b7d0076413d1215ec5f51d0574379.css'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/all/themes/kluh/js/dynamic-font-resize.js'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/themes/kluh/images3/logo-pratique.png'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://adnext.fr/richmedia.adv?id=97558&tag=1&s=all'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/themes/kluh/images3/accueil.png'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/modules/contrib/print/icons/print_icon.gif'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/all/modules/contrib/print/icons/mail_icon.gif'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://cdn.pratique.fr/sites/default/files/imagecache/dossier_main/articles/1-pourcent-patronal.jpg'
2013/05/03 18:13:47 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://adnext.fr/richmedia.adv?popunderid=97558&tag=3&s=big'
2013/05/03 18:13:48 [debug] 8137#0: epoll: fd:12 ev:0001 d:0000000001BA6579
2013/05/03 18:13:48 [debug] 8137#0: *2 pagespeed update: 0000000001C1E9C8, done: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http gzip filter
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C6B3B0:270336
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip alloc: n:1 s:5936 a:8192 p:0000000001C6B3B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip alloc: n:32768 s:2 a:65536 p:0000000001C6D3B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip alloc: n:32768 s:2 a:65536 p:0000000001C7D3B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip alloc: n:32768 s:2 a:65536 p:0000000001C8D3B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip alloc: n:16384 s:4 a:65536 p:0000000001C9D3B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C1E9E8
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1E5B8 ni:0000000001C1E608 ai:957
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C31420:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C1E608 no:0000000001C31420 ai:957 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C1E9C5 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1E5B8 pos:0000000001C1E608
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: *2 http pagespeed connection read handler rc: -2
2013/05/03 18:13:48 [debug] 8137#0: timer delta: 49
2013/05/03 18:13:48 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: worker cycle
2013/05/03 18:13:48 [debug] 8137#0: epoll timer: 59951
2013/05/03 18:13:48 [debug] 8137#0: epoll: fd:12 ev:0001 d:0000000001BA6579
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C32430:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C34440:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C36450:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C38460:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C3A470:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C3C480:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C3E490:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C404A0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C424B0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C444C0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C464D0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C484E0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C4A4F0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C4C500:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C4E510:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 posix_memalign: 0000000001C50520:4096 @16
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C51530:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C53540:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C55550:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C57560:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C59570:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C5B580:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C5D590:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C5F5A0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C615B0:6891
2013/05/03 18:13:48 [debug] 8137#0: *2 pagespeed update: 0000000001C1EAB8, done: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http gzip filter
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50910
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EA58 ni:0000000001C32430 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C32430 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C34430 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EA58 pos:0000000001C32430
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50920
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EAC8 ni:0000000001C34440 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C34440 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C36440 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EAC8 pos:0000000001C34440
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50930
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EB38 ni:0000000001C36450 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C36450 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C38450 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EB38 pos:0000000001C36450
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50940
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EBA8 ni:0000000001C38460 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C38460 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C3A460 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EBA8 pos:0000000001C38460
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50950
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EC18 ni:0000000001C3A470 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C3A470 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C3C470 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EC18 pos:0000000001C3A470
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50960
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EC88 ni:0000000001C3C480 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C3C480 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C3E480 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EC88 pos:0000000001C3C480
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50970
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1ECF8 ni:0000000001C3E490 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C3E490 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C40490 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1ECF8 pos:0000000001C3E490
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50980
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1ED68 ni:0000000001C404A0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C404A0 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C424A0 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1ED68 pos:0000000001C404A0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50990
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EDD8 ni:0000000001C424B0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C424B0 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C444B0 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EDD8 pos:0000000001C424B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C509A0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EE48 ni:0000000001C444C0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C444C0 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C464C0 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EE48 pos:0000000001C444C0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C509B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EEB8 ni:0000000001C464D0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C464D0 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C484D0 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EEB8 pos:0000000001C464D0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C509C0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EF28 ni:0000000001C484E0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C484E0 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C4A4E0 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EF28 pos:0000000001C484E0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C509D0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EF98 ni:0000000001C4A4F0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C4A4F0 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:604:Found script with src http://pagead2.googlesyndication.com/pagead/show_ads.js
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C4C4F0 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://pagead2.googlesyndication.com/pagead/show_ads.js'
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1EF98 pos:0000000001C4A4F0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C509E0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1F008 ni:0000000001C4C500 ai:8192
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:679:Found script with src http://js.pratique.fr/sites/default/files/js/js_e6dcbb56ff858f8eaf040dd342cf7c1c.js
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C4C500 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/default/files/js/js_e6dcbb56ff858f8eaf040dd342cf7c1c.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:686:Found script with src http://www.google.com/jsapi
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://www.google.com/jsapi'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:687:Found script with src http://js.pratique.fr/sites/all/themes/kluh/js/pratique_hr_evolution.js
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/all/themes/kluh/js/pratique_hr_evolution.js'
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C4E500 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] http://www.jefftk.com/test/tmp.patronal:689:Found script with src http://connect.facebook.net/fr_FR/all.js
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1F008 pos:0000000001C4C500
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C509F0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1F078 ni:0000000001C4E510 ai:8192
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://connect.facebook.net/fr_FR/all.js'
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C4E510 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C50510 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C1F078 pos:0000000001C4E510
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A00
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50540 ni:0000000001C51530 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C51530 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://pagead2.googlesyndication.com/pagead/show_ads.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/default/files/js/js_e6dcbb56ff858f8eaf040dd342cf7c1c.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://www.google.com/jsapi'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/all/themes/kluh/js/pratique_hr_evolution.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://connect.facebook.net/fr_FR/all.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://pagead2.googlesyndication.com/pagead/show_ads.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/default/files/js/js_e6dcbb56ff858f8eaf040dd342cf7c1c.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://www.google.com/jsapi'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://js.pratique.fr/sites/all/themes/kluh/js/pratique_hr_evolution.js'
2013/05/03 18:13:48 [info] 8137#0: [ngx_pagespeed 1.5.27.2-2912] No permission to rewrite 'http://connect.facebook.net/fr_FR/all.js'
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C53530 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50540 pos:0000000001C51530
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A10
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50590 ni:0000000001C53540 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C53540 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C55540 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50590 pos:0000000001C53540
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A20
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50600 ni:0000000001C55550 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C55550 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C57550 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50600 pos:0000000001C55550
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A30
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50670 ni:0000000001C57560 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C57560 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C59560 no:0000000001C31420 ai:0 ao:4096 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50670 pos:0000000001C57560
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A40
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 ni:0000000001C59570 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C59570 no:0000000001C31420 ai:8192 ao:4096 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C32420 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C59570
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C630B0:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C630B0 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C640B0 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C640C0:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C640C0 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C650C0 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C650D0:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C650D0 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C660D0 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C660E0:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C660E0 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C670E0 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C670F0:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C670F0 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C680F0 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C68100:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C68100 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B1B3 no:0000000001C69100 ai:957 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C69110:4096
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B1B3 no:0000000001C69110 ai:957 ao:4096 fl:0 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5B570 no:0000000001C69B3E ai:0 ao:1490 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C506E0 pos:0000000001C5B1B3
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A50
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50750 ni:0000000001C5B580 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5B580 no:0000000001C69B3E ai:8192 ao:1490 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5D580 no:0000000001C69B3E ai:0 ao:1490 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50750 pos:0000000001C5B580
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A60
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C507C0 ni:0000000001C5D590 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5D590 no:0000000001C69B3E ai:8192 ao:1490 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C5F590 no:0000000001C69B3E ai:0 ao:1490 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C507C0 pos:0000000001C5D590
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A70
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50830 ni:0000000001C5F5A0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C5F5A0 no:0000000001C69B3E ai:8192 ao:1490 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C615A0 no:0000000001C69B3E ai:0 ao:1490 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50830 pos:0000000001C5F5A0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50A80
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C508A0 ni:0000000001C615B0 ai:6891
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001C615B0 no:0000000001C69B3E ai:6891 ao:1490 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001C6309B no:0000000001C69B3E ai:0 ao:1490 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C508A0 pos:0000000001C615B0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 10
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 write old buf t:1 f:0 0000000001C1E3B0, pos 0000000001C1E3B0, size: 266 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C50EE0, pos 0000000001C50EE0, size: 6 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:0 f:0 0000000000000000, pos 00000000011CBA88, size: 10 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C31420, pos 0000000001C31420, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C630B0, pos 0000000001C630B0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C640C0, pos 0000000001C640C0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C650D0, pos 0000000001C650D0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C660E0, pos 0000000001C660E0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C670F0, pos 0000000001C670F0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C68100, pos 0000000001C68100, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:0 f:0 0000000000000000, pos 0000000000C41CFD, size: 2 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http write filter: l:0 f:1 s:28956
2013/05/03 18:13:48 [debug] 8137#0: *2 http write filter limit 0
2013/05/03 18:13:48 [debug] 8137#0: *2 writev: 18824
2013/05/03 18:13:48 [debug] 8137#0: *2 http write filter 0000000001C50FB8
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: *2 http pagespeed connection read handler rc: -2
2013/05/03 18:13:48 [debug] 8137#0: timer delta: 9
2013/05/03 18:13:48 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: worker cycle
2013/05/03 18:13:48 [debug] 8137#0: epoll timer: 59942
2013/05/03 18:13:48 [debug] 8137#0: epoll: fd:12 ev:0011 d:0000000001BA6579
2013/05/03 18:13:48 [debug] 8137#0: epoll_wait() error on fd:12 ev:0011
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001CAD3C0:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001CAF3D0:6982
2013/05/03 18:13:48 [debug] 8137#0: *2 pagespeed update: 0000000001C50DF0, done: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http gzip filter
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50E30
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50FF8 ni:0000000001CAD3C0 ai:8192
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001CAD3C0 no:0000000001C69B3E ai:8192 ao:1490 fl:0 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001CAF3C0 no:0000000001C69B3E ai:0 ao:1490 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C50FF8 pos:0000000001CAD3C0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50E20
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C51058 ni:0000000001CAF3D0 ai:6982
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000001CAF3D0 no:0000000001C69B3E ai:6982 ao:1490 fl:4 redo:0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000001CB0F16 no:0000000001C6A110 ai:0 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C51058 pos:0000000001CAF3D0
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000000000000 no:0000000001C650D0 ai:0 ao:4096 fl:4 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000000000000 no:0000000001C660D0 ai:0 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C51058 pos:0000000001CB0F16
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000000000000 no:0000000001C640C0 ai:0 ao:4096 fl:4 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000000000000 no:0000000001C650C0 ai:0 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C51058 pos:0000000001CB0F16
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000000000000 no:0000000001C630B0 ai:0 ao:4096 fl:4 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000000000000 no:0000000001C640B0 ai:0 ao:0 rc:0
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C51058 pos:0000000001CB0F16
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate in: ni:0000000000000000 no:0000000001C31420 ai:0 ao:4096 fl:4 redo:1
2013/05/03 18:13:48 [debug] 8137#0: *2 deflate out: ni:0000000000000000 no:0000000001C315FF ai:0 ao:3617 rc:1
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in_buf:0000000001C51058 pos:0000000001CB0F16
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C6B3B0
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 4096
2013/05/03 18:13:48 [debug] 8137#0: *2 http chunk: 487
2013/05/03 18:13:48 [debug] 8137#0: *2 write old buf t:1 f:0 0000000001C660E0, pos 0000000001C6694E, size: 1938 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write old buf t:1 f:0 0000000001C670F0, pos 0000000001C670F0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write old buf t:1 f:0 0000000001C68100, pos 0000000001C68100, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write old buf t:0 f:0 0000000000000000, pos 0000000000C41CFD, size: 2 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C50EE0, pos 0000000001C50EE0, size: 6 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C69110, pos 0000000001C69110, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C650D0, pos 0000000001C650D0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C640C0, pos 0000000001C640C0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C630B0, pos 0000000001C630B0, size: 4096 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:1 f:0 0000000001C31420, pos 0000000001C31420, size: 487 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 write new buf t:0 f:0 0000000000000000, pos 0000000000C41CF8, size: 7 file: 0, size: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http write filter: l:1 f:1 s:27016
2013/05/03 18:13:48 [debug] 8137#0: *2 http write filter limit 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http write filter 0000000001C50FB8
2013/05/03 18:13:48 [debug] 8137#0: *2 http pagespeed connection read handler rc: -2
2013/05/03 18:13:48 [debug] 8137#0: timer delta: 12
2013/05/03 18:13:48 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: worker cycle
2013/05/03 18:13:48 [debug] 8137#0: epoll timer: 59930
2013/05/03 18:13:48 [debug] 8137#0: epoll: fd:12 ev:0010 d:0000000001BA6579
2013/05/03 18:13:48 [debug] 8137#0: epoll_wait() error on fd:12 ev:0010
2013/05/03 18:13:48 [debug] 8137#0: *2 pagespeed update: 0000000000000000, done: 1
2013/05/03 18:13:48 [debug] 8137#0: *2 http pagespeed connection read handler rc: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 epoll del event: fd:12 op:2 ev:00000000
2013/05/03 18:13:48 [debug] 8137#0: *2 http finalize request: -4, "/test/tmp.patronal.html?" a:1, c:1
2013/05/03 18:13:48 [debug] 8137#0: *2 set http keepalive handler
2013/05/03 18:13:48 [debug] 8137#0: *2 http close request
2013/05/03 18:13:48 [debug] 8137#0: *2 reusable connection: 0
2013/05/03 18:13:48 [debug] 8137#0: *2 http log handler
2013/05/03 18:13:48 [debug] 8137#0: *2 run cleanup: 0000000001C20B98
2013/05/03 18:13:48 [debug] 8137#0: *2 file cleanup: fd:11
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001CAF3D0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001CAD3C0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C69110
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C68100
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C670F0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C660E0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C650D0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C640C0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C630B0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C615B0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C5F5A0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C5D590
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C5B580
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C59570
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C57560
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C55550
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C53540
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C51530
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C4E510
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C4C500
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C4A4F0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C484E0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C464D0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C444C0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C424B0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C404A0
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C3E490
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C3C480
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C3A470
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C38460
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C36450
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C34440
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C32430
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C31420
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C29410
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C1FC30, unused: 15
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C1E110, unused: 8
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C50520, unused: 676
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C28350
2013/05/03 18:13:48 [debug] 8137#0: *2 hc free: 0000000000000000 0
2013/05/03 18:13:48 [debug] 8137#0: *2 hc busy: 0000000000000000 0
2013/05/03 18:13:48 [debug] 8137#0: *2 tcp_nodelay
2013/05/03 18:13:48 [debug] 8137#0: *2 reusable connection: 1
2013/05/03 18:13:48 [debug] 8137#0: *2 event timer add: 3: 65000:1367619293053
2013/05/03 18:13:48 [debug] 8137#0: *2 post event 0000000001BD4430
2013/05/03 18:13:48 [debug] 8137#0: timer delta: 2
2013/05/03 18:13:48 [debug] 8137#0: posted events 0000000001BD4430
2013/05/03 18:13:48 [debug] 8137#0: posted event 0000000001BD4430
2013/05/03 18:13:48 [debug] 8137#0: *2 delete posted event 0000000001BD4430
2013/05/03 18:13:48 [debug] 8137#0: *2 http keepalive handler
2013/05/03 18:13:48 [debug] 8137#0: *2 malloc: 0000000001C28350:1024
2013/05/03 18:13:48 [debug] 8137#0: *2 recv: fd:3 -1 of 1024
2013/05/03 18:13:48 [debug] 8137#0: *2 recv() not ready (11: Resource temporarily unavailable)
2013/05/03 18:13:48 [debug] 8137#0: *2 free: 0000000001C28350
2013/05/03 18:13:48 [debug] 8137#0: posted event 0000000000000000
2013/05/03 18:13:48 [debug] 8137#0: worker cycle
2013/05/03 18:13:48 [debug] 8137#0: epoll timer: 59928

I think there aren't any other requests intermingled, but I'm not completely sure.

Strangely enough, I also see this problem when trying to download the error log itself over http:

$ telnet www.jefftk.com 80
GET /test/tmp.patronal.errorlog HTTP/1.1
...
2013/05/03 18:13:48 [debug] 8137#0: *2 gzip in: 0000000001C50950
2013/05/03 18:13:48 [debug] 8137#0: *2 gzi

Bizarrely, this time it does work with gzip:

$curl -H 'Accept-Encoding: gzip' http://www.jefftk.com/test/tmp.patronal.errorlog

The error log from when download the error log fails is:

2013/05/03 18:25:41 [debug] 8137#0: epoll: fd:6 ev:0001 d:0000000001BA6350
2013/05/03 18:25:41 [debug] 8137#0: accept on 0.0.0.0:80, ready: 0
2013/05/03 18:25:41 [debug] 8137#0: posix_memalign: 00007FE3400EBB40:256 @16
2013/05/03 18:25:41 [debug] 8137#0: *66 accept: 66.102.14.24 fd:3
2013/05/03 18:25:41 [debug] 8137#0: *66 event timer add: 3: 60000:1367620001724
2013/05/03 18:25:41 [debug] 8137#0: *66 reusable connection: 1
2013/05/03 18:25:41 [debug] 8137#0: *66 epoll add event: fd:3 op:1 ev:80000001
2013/05/03 18:25:41 [debug] 8137#0: timer delta: 12178
2013/05/03 18:25:41 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:25:41 [debug] 8137#0: worker cycle
2013/05/03 18:25:41 [debug] 8137#0: epoll timer: 60000
2013/05/03 18:25:41 [debug] 8137#0: epoll: fd:3 ev:0001 d:0000000001BA66E9
2013/05/03 18:25:41 [debug] 8137#0: *66 http wait request handler
2013/05/03 18:25:41 [debug] 8137#0: *66 posix_memalign: 00007FE3400E8780:256 @16
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE34000B7B0:1024
2013/05/03 18:25:41 [debug] 8137#0: *66 recv: fd:3 192 of 1024
2013/05/03 18:25:41 [debug] 8137#0: *66 reusable connection: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 posix_memalign: 00007FE3400AAEC0:4096 @16
2013/05/03 18:25:41 [debug] 8137#0: *66 http process request line
2013/05/03 18:25:41 [debug] 8137#0: *66 http request line: "GET /test/tmp.patronal.errorlog HTTP/1.1"
2013/05/03 18:25:41 [debug] 8137#0: *66 http uri: "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 http args: ""
2013/05/03 18:25:41 [debug] 8137#0: *66 http exten: "errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 http process request header line
2013/05/03 18:25:41 [debug] 8137#0: *66 http header: "User-Agent: curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3"
2013/05/03 18:25:41 [debug] 8137#0: *66 http header: "Host: www.jefftk.com"
2013/05/03 18:25:41 [debug] 8137#0: *66 http header: "Accept: */*"
2013/05/03 18:25:41 [debug] 8137#0: *66 http header done
2013/05/03 18:25:41 [debug] 8137#0: *66 event timer del: 3: 1367620001724
2013/05/03 18:25:41 [debug] 8137#0: *66 rewrite phase: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: "/"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: "wsgi"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: "50x.html"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: ~ "\.html$"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: ~ "^/?\+$"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: ~ "\.pagespeed\.([a-z]\.)?[a-z]{2}\.[^.]{10}\.[^.]+"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: ~ "^/ngx_pagespeed_static/"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: ~ "^/ngx_pagespeed_beacon$"
2013/05/03 18:25:41 [debug] 8137#0: *66 test location: ~ "\.jpg$"
2013/05/03 18:25:41 [debug] 8137#0: *66 using configuration "/"
2013/05/03 18:25:41 [debug] 8137#0: *66 http cl:-1 max:1048576
2013/05/03 18:25:41 [debug] 8137#0: *66 rewrite phase: 2
2013/05/03 18:25:41 [debug] 8137#0: *66 post rewrite phase: 3
2013/05/03 18:25:41 [debug] 8137#0: *66 generic phase: 4
2013/05/03 18:25:41 [debug] 8137#0: *66 generic phase: 5
2013/05/03 18:25:41 [debug] 8137#0: *66 access phase: 6
2013/05/03 18:25:41 [debug] 8137#0: *66 access phase: 7
2013/05/03 18:25:41 [debug] 8137#0: *66 post access phase: 8
2013/05/03 18:25:41 [debug] 8137#0: *66 generic phase: 9
2013/05/03 18:25:41 [debug] 8137#0: *66 http pagespeed handler "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 Passing on content handling for non-pagespeed resource 'http://www.jefftk.com/test/tmp.patronal.errorlog'
2013/05/03 18:25:41 [debug] 8137#0: *66 try files phase: 10
2013/05/03 18:25:41 [debug] 8137#0: *66 http script var: "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 http script copy: ".html"
2013/05/03 18:25:41 [debug] 8137#0: *66 trying to use file: "/test/tmp.patronal.errorlog.html" "/var/www/test/tmp.patronal.errorlog.html"
2013/05/03 18:25:41 [debug] 8137#0: *66 http script var: "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 trying to use file: "/test/tmp.patronal.errorlog" "/var/www/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 try file uri: "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 content phase: 11
2013/05/03 18:25:41 [debug] 8137#0: *66 content phase: 12
2013/05/03 18:25:41 [debug] 8137#0: *66 content phase: 13
2013/05/03 18:25:41 [debug] 8137#0: *66 http filename: "/var/www/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 add cleanup: 00007FE3400ABE20
2013/05/03 18:25:41 [debug] 8137#0: *66 http static fd: 11
2013/05/03 18:25:41 [debug] 8137#0: *66 http set discard body
2013/05/03 18:25:41 [debug] 8137#0: *66 posix_memalign: 00007FE3400AC170:4096 @16
2013/05/03 18:25:41 [debug] 8137#0: *66 epoll add event: fd:12 op:1 ev:00000001
2013/05/03 18:25:41 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/182541:VERBOSE1:proxy_fetch.cc(496)] Setting user-agent to curl/7.22.0 (x86_64-pc-linux-gnu) libcurl/7.22.0 OpenSSL/1.0.1 zlib/1.2.3.4 libidn/1.23 librtmp/2.3
2013/05/03 18:25:41 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/182541:VERBOSE1:proxy_fetch.cc(510)] Attaching RewriteDriver 0x1c230d0 to HtmlRewriter 0x7fe3400abf10
2013/05/03 18:25:41 [debug] 8137#0: *66 http cleanup add: 00007FE3400ABE80
2013/05/03 18:25:41 [debug] 8137#0: *66 HTTP/1.1 200 OK
Server: nginx/1.4.0
Date: Fri, 03 May 2013 22:25:41 GMT
Content-Type: text/html
Transfer-Encoding: chunked
Connection: keep-alive
Vary: Accept-Encoding
Cache-Control: max-age=0, no-cache
X-Page-Speed: 1.5.27.2-2912

2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE3400AC2F8, pos 00007FE3400AC2F8, size: 242 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 http write filter: l:0 f:0 s:242
2013/05/03 18:25:41 [debug] 8137#0: *66 http output filter "/test/tmp.patronal.errorlog?"
2013/05/03 18:25:41 [debug] 8137#0: *66 http copy filter: "/test/tmp.patronal.errorlog?"
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE3400B0B40:32768
2013/05/03 18:25:41 [debug] 8137#0: *66 read: 11, 00007FE3400B0B40, 32768, 0
2013/05/03 18:25:41 [debug] 8137#0: *66 http postpone filter "/test/tmp.patronal.errorlog?" 00007FE3400AC4D8
2013/05/03 18:25:41 [debug] 8137#0: *66 http pagespeed filter "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: *66 read: 11, 00007FE3400B0B40, 13150, 32768
2013/05/03 18:25:41 [debug] 8137#0: *66 http postpone filter "/test/tmp.patronal.errorlog?" 00007FE3400AC4D8
2013/05/03 18:25:41 [debug] 8137#0: *66 http pagespeed filter "/test/tmp.patronal.errorlog"
2013/05/03 18:25:41 [debug] 8137#0: [ngx_pagespeed 1.5.27.2-2912] [0503/182541:VERBOSE1:proxy_fetch.cc(931)] Fetch result:1 http://www.jefftk.com/test/tmp.patronal.errorlog : 200
2013/05/03 18:25:41 [debug] 8137#0: *66 http copy filter: -2 "/test/tmp.patronal.errorlog?"
2013/05/03 18:25:41 [debug] 8137#0: *66 http finalize request: -2, "/test/tmp.patronal.errorlog?" a:1, c:1
2013/05/03 18:25:41 [debug] 8137#0: *66 event timer add: 3: 60000:1367620001724
2013/05/03 18:25:41 [debug] 8137#0: timer delta: 0
2013/05/03 18:25:41 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:25:41 [debug] 8137#0: worker cycle
2013/05/03 18:25:41 [debug] 8137#0: epoll timer: 60000
2013/05/03 18:25:41 [debug] 8137#0: epoll: fd:12 ev:0011 d:0000000001BA6858
2013/05/03 18:25:41 [debug] 8137#0: epoll_wait() error on fd:12 ev:0011
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE3400B8B50:8192
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE3400E58D0:8192
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE340000D10:8192
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE340002D20:8192
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE340004D30:8192
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE340006D40:4958
2013/05/03 18:25:41 [debug] 8137#0: *66 pagespeed update: 00007FE3400AC548, done: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 http chunk: 8192
2013/05/03 18:25:41 [debug] 8137#0: *66 http chunk: 8192
2013/05/03 18:25:41 [debug] 8137#0: *66 http chunk: 8192
2013/05/03 18:25:41 [debug] 8137#0: *66 http chunk: 8192
2013/05/03 18:25:41 [debug] 8137#0: *66 http chunk: 8192
2013/05/03 18:25:41 [debug] 8137#0: *66 http chunk: 4958
2013/05/03 18:25:41 [debug] 8137#0: *66 write old buf t:1 f:0 00007FE3400AC2F8, pos 00007FE3400AC2F8, size: 242 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE3400AC848, pos 00007FE3400AC848, size: 6 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE3400B8B50, pos 00007FE3400B8B50, size: 8192 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE3400E58D0, pos 00007FE3400E58D0, size: 8192 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE340000D10, pos 00007FE340000D10, size: 8192 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE340002D20, pos 00007FE340002D20, size: 8192 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE340004D30, pos 00007FE340004D30, size: 8192 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:1 f:0 00007FE340006D40, pos 00007FE340006D40, size: 4958 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 write new buf t:0 f:0 0000000000000000, pos 0000000000C41CF8, size: 7 file: 0, size: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 http write filter: l:1 f:0 s:46173
2013/05/03 18:25:41 [debug] 8137#0: *66 http write filter limit 0
2013/05/03 18:25:41 [debug] 8137#0: *66 writev: 18824
2013/05/03 18:25:41 [debug] 8137#0: *66 http write filter 00007FE3400AC8F0
2013/05/03 18:25:41 [debug] 8137#0: *66 http pagespeed connection read handler rc: -2
2013/05/03 18:25:41 [debug] 8137#0: timer delta: 1
2013/05/03 18:25:41 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:25:41 [debug] 8137#0: worker cycle
2013/05/03 18:25:41 [debug] 8137#0: epoll timer: 59999
2013/05/03 18:25:41 [debug] 8137#0: epoll: fd:12 ev:0011 d:0000000001BA6858
2013/05/03 18:25:41 [debug] 8137#0: epoll_wait() error on fd:12 ev:0011
2013/05/03 18:25:41 [debug] 8137#0: *66 pagespeed update: 0000000000000000, done: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 http pagespeed connection read handler rc: -2
2013/05/03 18:25:41 [debug] 8137#0: timer delta: 1
2013/05/03 18:25:41 [debug] 8137#0: posted events 0000000000000000
2013/05/03 18:25:41 [debug] 8137#0: worker cycle
2013/05/03 18:25:41 [debug] 8137#0: epoll timer: 59998
2013/05/03 18:25:41 [debug] 8137#0: epoll: fd:12 ev:0010 d:0000000001BA6858
2013/05/03 18:25:41 [debug] 8137#0: epoll_wait() error on fd:12 ev:0010
2013/05/03 18:25:41 [debug] 8137#0: *66 pagespeed update: 0000000000000000, done: 1
2013/05/03 18:25:41 [debug] 8137#0: *66 http pagespeed connection read handler rc: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 epoll del event: fd:12 op:2 ev:00000000
2013/05/03 18:25:41 [debug] 8137#0: *66 http finalize request: -4, "/test/tmp.patronal.errorlog?" a:1, c:1
2013/05/03 18:25:41 [debug] 8137#0: *66 set http keepalive handler
2013/05/03 18:25:41 [debug] 8137#0: *66 http close request
2013/05/03 18:25:41 [debug] 8137#0: *66 reusable connection: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 http log handler
2013/05/03 18:25:41 [debug] 8137#0: *66 run cleanup: 00007FE3400ABE20
2013/05/03 18:25:41 [debug] 8137#0: *66 file cleanup: fd:11
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE340006D40
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE340004D30
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE340002D20
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE340000D10
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE3400E58D0
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE3400B8B50
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE3400B0B40
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE3400AAEC0, unused: 0
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE3400AC170, unused: 1859
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE34000B7B0
2013/05/03 18:25:41 [debug] 8137#0: *66 hc free: 0000000000000000 0
2013/05/03 18:25:41 [debug] 8137#0: *66 hc busy: 0000000000000000 0
2013/05/03 18:25:41 [debug] 8137#0: *66 tcp_nodelay
2013/05/03 18:25:41 [debug] 8137#0: *66 reusable connection: 1
2013/05/03 18:25:41 [debug] 8137#0: *66 event timer add: 3: 65000:1367620006726
2013/05/03 18:25:41 [debug] 8137#0: *66 post event 0000000001BD4568
2013/05/03 18:25:41 [debug] 8137#0: timer delta: 0
2013/05/03 18:25:41 [debug] 8137#0: posted events 0000000001BD4568
2013/05/03 18:25:41 [debug] 8137#0: posted event 0000000001BD4568
2013/05/03 18:25:41 [debug] 8137#0: *66 delete posted event 0000000001BD4568
2013/05/03 18:25:41 [debug] 8137#0: *66 http keepalive handler
2013/05/03 18:25:41 [debug] 8137#0: *66 malloc: 00007FE34000B7B0:1024
2013/05/03 18:25:41 [debug] 8137#0: *66 recv: fd:3 -1 of 1024
2013/05/03 18:25:41 [debug] 8137#0: *66 recv() not ready (11: Resource temporarily unavailable)
2013/05/03 18:25:41 [debug] 8137#0: *66 free: 00007FE34000B7B0
2013/05/03 18:25:41 [debug] 8137#0: posted event 0000000000000000
2013/05/03 18:25:41 [debug] 8137#0: worker cycle
2013/05/03 18:25:41 [debug] 8137#0: epoll timer: 59998

I am extremely confused.

oschaaf commented 11 years ago

I just got an idea: when we reordered our module to run in front of the gzip module, we ran in to trouble when passing on NULL cl's, remember? Maybe that code is worth having a look at regarding this problem. I can't do that right now, but I should be able to do so this evening.

ghost commented 11 years ago

On our logs we have that kind of errors:

NgxBaseFetch::RequestCollection: Broken pipe NgxBaseFetch::RequestCollection: Broken pipe NgxBaseFetch::RequestCollection: Broken pipe NgxBaseFetch::RequestCollection: Broken pipe NgxBaseFetch::RequestCollection: Broken pipe

And some

2013/05/04 10:25:48 [alert] 9296#0: [ngx_pagespeed 1.5.27.2-2912] [0504/102548:FATAL:proxy_fetch.cc(79)] Check failed: outstanding_proxyfetches.empty(). Backtrace: nginx: worker process() [0x4c6001] nginx: worker process() [0x4c2838] nginx: worker process() [0x4f3d56] nginx: worker process() [0x4a98c4] nginx: worker process() [0x41312e] nginx: worker process() [0x4311a3] nginx: worker process() [0x431305]

oschaaf commented 11 years ago

I am able to reproduce it as well now, and it looks like we hang when a NULL cl is involved when done equals true in ps_update (in that case returning NGX_OK). I see that when requesting 1-patronal.html locally using curl, without an accept encoding header.

oschaaf commented 11 years ago

while it seems that https://github.com/pagespeed/ngx_pagespeed/pull/333 fixes this, it possibly introduces another problem (see @eleshar's comment at: https://github.com/pagespeed/ngx_pagespeed/issues/298#issuecomment-17431935)

jeffkaufman commented 11 years ago

@mitch75 This should be fixed in current master; can you confirm that it works now if you build from master?

ghost commented 11 years ago

Hello Jeff. I've thoroughly tested the site under various configurations and so far found no bugs... it seems that everything is fine.

Thanks for your help

jeffkaufman commented 11 years ago

Released in 1.5.27.3