Z_BUF_ERROR nginx 0.8.53

Server NGINX
1

Hi,

I have a lot errors about
*1281 deflate() failed: 2, -5 while reading upstream, … blah…
blah… blah
I’ve checked what -5 means and this is just empty buffer for deflate
(Z_BUF_ERROR):
checked how other software handling this error and found very simple
solution:
http://gcc.gnu.org/ml/java-patches/2000-q4/msg00263.html
http://zlib.net/zlib_how.html
so I’ve created patch and it solved this problem, all messages gone,
please find patch attached and tell what do you think about it.

2

Sorry, sent wrong file, nginx have code for buffer size check, and
without disabling it, this patch doesn’t have any effect, sending patch
again.

3

Made more clear version of patch.

4

I’m proxying few cites with low bandwidth, looks like sometimes on slow
connections possible to get from mod_upstream empty buffer, this will
stop all processing, but on next step you’ll get normal gazip data.

5

Hello!

On Thu, Nov 18, 2010 at 11:32:51AM -0800, Roman V. wrote:

I have a lot errors about
*1281 deflate() failed: 2, -5 while reading upstream, … blah…
blah… blah
I’ve checked what -5 means and this is just empty buffer for deflate
(Z_BUF_ERROR):

This shouldn’t happen and indicate bug either in gzip module or
somewhere before it. You may want to focus on conditions why it
happens, not how to handle this deflate() error.

Maxim D.

6

Just want to add that disabling gzip solving problem, so for now I’ve
disabled gzip compression on all our servers, and our service
stabilized.

gzip off;

Using gzip compression in nginx can lost your data.

7

Hello!

On Thu, Nov 18, 2010 at 02:04:20PM -0800, Roman V. wrote:

I’m proxying few cites with low bandwidth, looks like sometimes on
slow connections possible to get from mod_upstream empty buffer,

Again: it shouldn’t be possible. And this is the problem which
should be analyzed and fixed.

Maxim D.

8

Hello!

On Thu, Nov 18, 2010 at 02:45:22PM -0800, Roman V. wrote:

I’ve reproduced this problem with debuging.
Let me attach error log with debug, I’m not clearly understanding
nginx modules chain

[…]

2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream process non
buffered upstream

[…]

2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody in
2010/11/18 14:42:23 [alert] 24622#0: *206 deflate() failed: 2, -5
while reading upstream, client: 10.222.16.2, server: hss, request:
“GET /?ar=1290119308 HTTP/1.1”, upstream:
“http://74.125.19.103:80/?ar=1290119308”, host: “news.google.com”,
referrer: “http://news.google.com/”

Ah, ok, the problem is clear: due to use of proxy_buffered off;
buffer had flush flag set. All data from it was eaten by gunzip
filter, and special flush buffer was passed along filter chain
instead.

The only way to reproduce this problem without third party modules
(i.e. gunzip filter and your local modifications to it in your
case) seems to use $r->flush() twice from embedded perl, see test
case here:

http://mdounin.ru/hg/nginx-tests/rev/e8546edb0267

Correct patch to the problem attached.

It basically lines up gzip filter to what is already done in
gunzip filter - allows Z_BUF_ERROR as non-fatal and makes sure
special flush buffer will be passed if there is no output in
Z_SYNC_FLUSH case.

Maxim D.

9

Hello,

Tested your patch, everything is fine, 2 hours my server working without
any messages in log about deflate problems.

NGINX the best :slight_smile:

Just in case want to ask about one variable, nginx have $host variable,
but it using resolver, in my case I don’t need it because I already have
this info in NAT table (my traffic goes to nginx from rdr pf rule).
So the question is, what do you think about having var like $nat_ip
which will get dest ip using
ioctl(dev, DIOCNATLOOK, &nl)? In my case it will decrease extra
dependency from named.

10

I’ve reproduced this problem with debuging.
Let me attach error log with debug, I’m not clearly understanding nginx
modules chain

2010/11/18 14:42:23 [debug] 24622#0: post event 00000000055ADDD0
2010/11/18 14:42:23 [debug] 24622#0: delete posted event
00000000055ADDD0
2010/11/18 14:42:23 [debug] 24622#0: accept on 0.0.0.0:80, ready: 1
2010/11/18 14:42:23 [debug] 24622#0: posix_memalign:
000000000555BDA0:256 @16
2010/11/18 14:42:23 [debug] 24622#0: *204 accept: 10.222.16.2 fd:26
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer add: 26:
60000:1290120203255
2010/11/18 14:42:23 [debug] 24622#0: *204 epoll add event: fd:26 op:1
ev:80000001
2010/11/18 14:42:23 [debug] 24622#0: accept() not ready (11: Resource
temporarily unavailable)
2010/11/18 14:42:23 [debug] 24622#0: *204 post event 00000000055AE318
2010/11/18 14:42:23 [debug] 24622#0: *204 delete posted event
00000000055AE318
2010/11/18 14:42:23 [debug] 24622#0: *204 malloc: 00000000056C0770:1248
2010/11/18 14:42:23 [debug] 24622#0: *204 posix_memalign:
000000000555BEB0:256 @16
2010/11/18 14:42:23 [debug] 24622#0: *204 malloc: 0000000001242220:32768
2010/11/18 14:42:23 [debug] 24622#0: *204 posix_memalign:
000000000555AA60:4096 @16
2010/11/18 14:42:23 [debug] 24622#0: *204 http process request line
2010/11/18 14:42:23 [debug] 24622#0: *204 recv: fd:26 440 of 32768
2010/11/18 14:42:23 [debug] 24622#0: *204 http request line: “GET
/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955 HTTP/1.1”
2010/11/18 14:42:23 [debug] 24622#0: *204 http uri: “/csi”
2010/11/18 14:42:23 [debug] 24622#0: *204 http args:
“v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http exten: “”
2010/11/18 14:42:23 [debug] 24622#0: *204 http process request header
line
2010/11/18 14:42:23 [debug] 24622#0: 204 http header: “Host:
csi.gstatic.com”
2010/11/18 14:42:23 [debug] 24622#0: 204 http header: “User-Agent:
Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14) Gecko/20101022
Firefox/3.5.14”
2010/11/18 14:42:23 [debug] 24622#0: 204 http header: "Accept:
image/png,image/;q=0.8,/;q=0.5"
2010/11/18 14:42:23 [debug] 24622#0: *204 http header: “Accept-Language:
en-us,en;q=0.5”
2010/11/18 14:42:23 [debug] 24622#0: *204 http header: “Accept-Encoding:
gzip,deflate”
2010/11/18 14:42:23 [debug] 24622#0: 204 http header: "Accept-Charset:
ISO-8859-1,utf-8;q=0.7,;q=0.7"
2010/11/18 14:42:23 [debug] 24622#0: *204 http header: “Keep-Alive: 300”
2010/11/18 14:42:23 [debug] 24622#0: *204 http header: “Connection:
keep-alive”
2010/11/18 14:42:23 [debug] 24622#0: *204 http header: “Referer:
http://news.google.com/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *204 http header done
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer del: 26:
1290120203255
2010/11/18 14:42:23 [debug] 24622#0: *204 rewrite phase: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 http script complex value
2010/11/18 14:42:23 [debug] 24622#0: *204 http script copy: “http://”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“csi.gstatic.com”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script set $af_proxy_addr
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“http://csi.gstatic.com/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script regex:
“facebook.com/extern/login_status.php”
2010/11/18 14:42:23 [notice] 24622#0: *204
“facebook.com/extern/login_status.php” does not match
“http://csi.gstatic.com/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”,
client: 10.222.16.2, server: hss, request: “GET
/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955 HTTP/1.1”,
host: “csi.gstatic.com”, referrer:
“http://news.google.com/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var: “Mozilla/5.0
(X11; U; FreeBSD i386; en-US; rv:1.9.1.14) Gecko/20101022
Firefox/3.5.14”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script regex: “Torrent”
2010/11/18 14:42:23 [notice] 24622#0: *204 “Torrent” does not match
“Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14) Gecko/20101022
Firefox/3.5.14”, client: 10.222.16.2, server: hss, request: “GET
/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955 HTTP/1.1”,
host: “csi.gstatic.com”, referrer:
“http://news.google.com/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“csi.gstatic.com”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script regex:
“northcountrygazette.org”
2010/11/18 14:42:23 [notice] 24622#0: *204 “northcountrygazette.org”
does not match “csi.gstatic.com”, client: 10.222.16.2, server: hss,
request: “GET /csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955
HTTP/1.1”, host: “csi.gstatic.com”, referrer:
“http://news.google.com/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *204 test location: “/”
2010/11/18 14:42:23 [debug] 24622#0: *204 using configuration “/”
2010/11/18 14:42:23 [debug] 24622#0: *204 http cl:-1 max:1048576
2010/11/18 14:42:23 [debug] 24622#0: *204 rewrite phase: 2
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var: “GET”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script value: “HEAD”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script equal
2010/11/18 14:42:23 [debug] 24622#0: *204 http script equal: no
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if
2010/11/18 14:42:23 [debug] 24622#0: *204 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *204 post rewrite phase: 3
2010/11/18 14:42:23 [debug] 24622#0: *204 generic phase: 4
2010/11/18 14:42:23 [debug] 24622#0: *204 generic phase: 5
2010/11/18 14:42:23 [debug] 24622#0: *204 access phase: 6
2010/11/18 14:42:23 [debug] 24622#0: *204 access: 0210DE0A 000000FF
0000000A
2010/11/18 14:42:23 [debug] 24622#0: *204 access phase: 7
2010/11/18 14:42:23 [debug] 24622#0: *204 post access phase: 8
2010/11/18 14:42:23 [debug] 24622#0: *204 posix_memalign:
00000000006D9740:4096 @16
2010/11/18 14:42:23 [debug] 24622#0: *204 http script copy: “http://”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“csi.gstatic.com”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http init upstream, client
timer: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 epoll add event: fd:26 op:3
ev:80000005
2010/11/18 14:42:23 [debug] 24622#0: *204 http script copy: “Host: "
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“csi.gstatic.com”
2010/11/18 14:42:23 [debug] 24622#0: *204 http script copy: "
"
2010/11/18 14:42:23 [debug] 24622#0: 204 http script copy: "Connection:
close
"
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header:
“User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14)
Gecko/20101022 Firefox/3.5.14”
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header: "Accept:
image/png,image/;q=0.8,/;q=0.5”
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header:
“Accept-Language: en-us,en;q=0.5”
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header:
“Accept-Encoding: gzip,deflate”
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header:
"Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.7"
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header: “Referer:
http://news.google.com/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: 204 http proxy header:
"GET /csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955 HTTP/1.0
Host: csi.gstatic.com
Connection: close
User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14)
Gecko/20101022 Firefox/3.5.14
Accept: image/png,image/;q=0.8,/;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.7
Referer: http://news.google.com/?ar=1290119308

"
2010/11/18 14:42:23 [debug] 24622#0: *204 http script var:
“68.68.108.251”
2010/11/18 14:42:23 [debug] 24622#0: *204 http cleanup add:
00000000006D9F50
2010/11/18 14:42:23 [debug] 24622#0: *204 name was resolved to
72.14.213.138
2010/11/18 14:42:23 [debug] 24622#0: *204 name was resolved to
72.14.213.139
2010/11/18 14:42:23 [debug] 24622#0: *204 name was resolved to
72.14.213.100
2010/11/18 14:42:23 [debug] 24622#0: *204 name was resolved to
72.14.213.101
2010/11/18 14:42:23 [debug] 24622#0: *204 name was resolved to
72.14.213.102
2010/11/18 14:42:23 [debug] 24622#0: *204 name was resolved to
72.14.213.113
2010/11/18 14:42:23 [debug] 24622#0: *204 get rr peer, try: 6
2010/11/18 14:42:23 [debug] 24622#0: *204 get rr peer, current: 5 1
2010/11/18 14:42:23 [debug] 24622#0: *204 socket 28
2010/11/18 14:42:23 [debug] 24622#0: *204 epoll add connection: fd:28
ev:80000005
2010/11/18 14:42:23 [debug] 24622#0: *204 connect to 72.14.213.113:80,
fd:28 #205
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream connect: -2
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer add: 28:
60000:1290120203263
2010/11/18 14:42:23 [debug] 24622#0: *204 http finalize request: -4,
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955” a:1, c:2
2010/11/18 14:42:23 [debug] 24622#0: *204 http request count:2 blk:0
2010/11/18 14:42:23 [debug] 24622#0: *204 post event 00000000010EE6B8
2010/11/18 14:42:23 [debug] 24622#0: *204 delete posted event
00000000010EE6B8
2010/11/18 14:42:23 [debug] 24622#0: *204 http run request:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream check client,
write event:1, “/csi”
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream recv(): -1 (11:
Resource temporarily unavailable)
2010/11/18 14:42:23 [debug] 24622#0: *204 post event 00000000010EE378
2010/11/18 14:42:23 [debug] 24622#0: *204 delete posted event
00000000010EE378
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream request:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream send request
handler
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream send request
2010/11/18 14:42:23 [debug] 24622#0: *204 chain writer buf fl:1 s:418
2010/11/18 14:42:23 [debug] 24622#0: *204 chain writer in:
00000000006DA2E8
2010/11/18 14:42:23 [debug] 24622#0: *204 writev: 418
2010/11/18 14:42:23 [debug] 24622#0: *204 chain writer out:
0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer del: 28:
1290120203263
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer add: 28:
60000:1290120203290
2010/11/18 14:42:23 [debug] 24622#0: *183 event timer del: 14:
1290120143355
2010/11/18 14:42:23 [debug] 24622#0: *183 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *183 close http connection: 14
2010/11/18 14:42:23 [debug] 24622#0: *183 free: 00000000056B5E10
2010/11/18 14:42:23 [debug] 24622#0: *183 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *183 free: 0000000005174080,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *183 free: 0000000004E88BD0,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *204 post event 00000000055ADFD8
2010/11/18 14:42:23 [debug] 24622#0: *204 post event 00000000010EE378
2010/11/18 14:42:23 [debug] 24622#0: *204 delete posted event
00000000010EE378
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream request:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream dummy handler
2010/11/18 14:42:23 [debug] 24622#0: *204 delete posted event
00000000055ADFD8
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream request:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream process header
2010/11/18 14:42:23 [debug] 24622#0: *204 malloc: 000000000124A230:65536
2010/11/18 14:42:23 [debug] 24622#0: *204 recv: fd:28 215 of 65536
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy status 204 “204 No
Content”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header:
“Content-Length: 0”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header: “Date: Wed,
21 Jan 2004 19:51:30 GMT”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header: “Pragma:
no-cache”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header:
“Cache-Control: private, no-cache”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header: “Expires:
Wed, 17 Sep 1975 21:32:10 GMT”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header:
“Content-Type: text/html”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header: “Server:
Golfe”
2010/11/18 14:42:23 [debug] 24622#0: *204 http proxy header done
2010/11/18 14:42:23 [debug] 24622#0: *204 http afheader in
2010/11/18 14:42:23 [debug] 24622#0: *204 HTTP/1.1 204 No Content
Server: nginx/0.8.53
Date: Thu, 18 Nov 2010 22:42:23 GMT
Content-Type: text/html
Connection: keep-alive
Content-Length: 0
Pragma: no-cache
Cache-Control: private, no-cache
Expires: Wed, 17 Sep 1975 21:32:10 GMT

2010/11/18 14:42:23 [debug] 24622#0: *204 write new buf t:1 f:0
00000000006DA608, pos 00000000006DA608, size: 246 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 http write filter: l:0 f:0
s:246
2010/11/18 14:42:23 [debug] 24622#0: *204 tcp_nodelay
2010/11/18 14:42:23 [debug] 24622#0: *204 posix_memalign:
0000000005558930:4096 @16
2010/11/18 14:42:23 [debug] 24622#0: *204 http output filter
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http copy filter:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http afbody in
2010/11/18 14:42:23 [debug] 24622#0: *204 http postpone filter
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
00007FFF41986BA0
2010/11/18 14:42:23 [debug] 24622#0: *204 write old buf t:1 f:0
00000000006DA608, pos 00000000006DA608, size: 246 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 http write filter: l:0 f:1
s:246
2010/11/18 14:42:23 [debug] 24622#0: *204 http write filter limit 0
2010/11/18 14:42:23 [debug] 24622#0: *204 writev: 246
2010/11/18 14:42:23 [debug] 24622#0: *204 http write filter
0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *204 http copy filter: 0
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http upstream process non
buffered upstream
2010/11/18 14:42:23 [debug] 24622#0: *204 finalize http upstream
request: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 finalize http proxy request
2010/11/18 14:42:23 [debug] 24622#0: *204 free rr peer 6 0
2010/11/18 14:42:23 [debug] 24622#0: *204 close http upstream
connection: 28
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer del: 28:
1290120203290
2010/11/18 14:42:23 [debug] 24622#0: *204 http output filter
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http copy filter:
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http afbody in
2010/11/18 14:42:23 [debug] 24622#0: *204 http postpone filter
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
00007FFF41986B20
2010/11/18 14:42:23 [debug] 24622#0: *204 write new buf t:0 f:0
0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 http write filter: l:1 f:0 s:0
2010/11/18 14:42:23 [debug] 24622#0: *204 http copy filter: 0
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955”
2010/11/18 14:42:23 [debug] 24622#0: *204 http finalize request: 0,
“/csi?v=3&s=news&action=hp&e=null&rt=bol.403,ol.600,aft.955” a:1, c:1
2010/11/18 14:42:23 [debug] 24622#0: *204 set http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *204 http close request
2010/11/18 14:42:23 [debug] 24622#0: *204 http log handler
2010/11/18 14:42:23 [debug] 24622#0: *204 free: 000000000124A230
2010/11/18 14:42:23 [debug] 24622#0: *204 free: 000000000555AA60,
unused: 0
2010/11/18 14:42:23 [debug] 24622#0: *204 free: 00000000006D9740,
unused: 32
2010/11/18 14:42:23 [debug] 24622#0: *204 free: 0000000005558930,
unused: 3800
2010/11/18 14:42:23 [debug] 24622#0: *204 event timer add: 26:
1000:1290120144362
2010/11/18 14:42:23 [debug] 24622#0: *204 free: 00000000056C0770
2010/11/18 14:42:23 [debug] 24622#0: *204 free: 0000000001242220
2010/11/18 14:42:23 [debug] 24622#0: *204 hc free: 0000000000000000 0
2010/11/18 14:42:23 [debug] 24622#0: *204 hc busy: 0000000000000000 0
2010/11/18 14:42:23 [debug] 24622#0: *204 post event 00000000055AE318
2010/11/18 14:42:23 [debug] 24622#0: *204 delete posted event
00000000055AE318
2010/11/18 14:42:23 [debug] 24622#0: *204 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *204 malloc: 00000000056B5E10:32768
2010/11/18 14:42:23 [debug] 24622#0: *204 recv: fd:26 -1 of 32768
2010/11/18 14:42:23 [debug] 24622#0: *204 recv() not ready (11: Resource
temporarily unavailable)
2010/11/18 14:42:23 [debug] 24622#0: *186 event timer del: 20:
1290120143612
2010/11/18 14:42:23 [debug] 24622#0: *186 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *186 close http connection: 20
2010/11/18 14:42:23 [debug] 24622#0: *186 free: 00000000012021A0
2010/11/18 14:42:23 [debug] 24622#0: *186 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *186 free: 0000000004E88DF0,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *186 free: 0000000004E88F00,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *188 event timer del: 24:
1290120143623
2010/11/18 14:42:23 [debug] 24622#0: *188 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *188 close http connection: 24
2010/11/18 14:42:23 [debug] 24622#0: *188 free: 000000000120A1B0
2010/11/18 14:42:23 [debug] 24622#0: *188 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *188 free: 0000000004E89010,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *188 free: 000000000555C590,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: post event 00000000055ADDD0
2010/11/18 14:42:23 [debug] 24622#0: delete posted event
00000000055ADDD0
2010/11/18 14:42:23 [debug] 24622#0: accept on 0.0.0.0:80, ready: 1
2010/11/18 14:42:23 [debug] 24622#0: posix_memalign:
0000000005174080:256 @16
2010/11/18 14:42:23 [debug] 24622#0: *206 accept: 10.222.16.2 fd:14
2010/11/18 14:42:23 [debug] 24622#0: *206 event timer add: 14:
60000:1290120203647
2010/11/18 14:42:23 [debug] 24622#0: *206 epoll add event: fd:14 op:1
ev:80000001
2010/11/18 14:42:23 [debug] 24622#0: accept() not ready (11: Resource
temporarily unavailable)
2010/11/18 14:42:23 [debug] 24622#0: *206 post event 00000000055AE520
2010/11/18 14:42:23 [debug] 24622#0: *206 delete posted event
00000000055AE520
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc: 00000000056C0060:1248
2010/11/18 14:42:23 [debug] 24622#0: *206 posix_memalign:
0000000004E88BD0:256 @16
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc: 00000000011FA190:32768
2010/11/18 14:42:23 [debug] 24622#0: *206 posix_memalign:
00000000006D9740:4096 @16
2010/11/18 14:42:23 [debug] 24622#0: *206 http process request line
2010/11/18 14:42:23 [debug] 24622#0: *206 recv: fd:14 750 of 32768
2010/11/18 14:42:23 [debug] 24622#0: *206 http request line: “GET
/?ar=1290119308 HTTP/1.1”
2010/11/18 14:42:23 [debug] 24622#0: *206 http uri: “/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http args: “ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http exten: “”
2010/11/18 14:42:23 [debug] 24622#0: *206 http process request header
line
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Host:
news.google.com”
2010/11/18 14:42:23 [debug] 24622#0: 206 http header: “User-Agent:
Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14) Gecko/20101022
Firefox/3.5.14”
2010/11/18 14:42:23 [debug] 24622#0: 206 http header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8"
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Accept-Language:
en-us,en;q=0.5”
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Accept-Encoding:
gzip,deflate”
2010/11/18 14:42:23 [debug] 24622#0: 206 http header: "Accept-Charset:
ISO-8859-1,utf-8;q=0.7,;q=0.7"
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Keep-Alive: 300”
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Connection:
keep-alive”
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Referer:
http://news.google.com/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Cookie:
PREF=ID=6525926552b9e494:U=93cb6d5927e9b698:TM=1275696172:LM=1276718201:GM=1:S=UgVptM_ctrBVeN_L;
NID=40=OpJOX_yqI5wRZrfKaluyXdnDmAhNyrmCrKVwiAMJjJLG0U-B97WB-LUhffGDujDPrC_vb78vGxZ4kg1Q_tm8ABpwyMxo53B6PaMI_FukfxjuPSWvWBlX9C–vCOUTxH_;
rememberme=true; AF_C=4_http%3A//news.google.com/%3Far%3D1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http header: “Cache-Control:
max-age=0”
2010/11/18 14:42:23 [debug] 24622#0: *206 http header done
2010/11/18 14:42:23 [debug] 24622#0: *206 event timer del: 14:
1290120203647
2010/11/18 14:42:23 [debug] 24622#0: *206 rewrite phase: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http script complex value
2010/11/18 14:42:23 [debug] 24622#0: *206 http script copy: “http://”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“news.google.com”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script set $af_proxy_addr
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“http://news.google.com/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script regex:
“facebook.com/extern/login_status.php”
2010/11/18 14:42:23 [notice] 24622#0: *206
“facebook.com/extern/login_status.php” does not match
“http://news.google.com/?ar=1290119308”, client: 10.222.16.2, server:
hss, request: “GET /?ar=1290119308 HTTP/1.1”, host: “news.google.com”,
referrer: “http://news.google.com/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var: “Mozilla/5.0
(X11; U; FreeBSD i386; en-US; rv:1.9.1.14) Gecko/20101022
Firefox/3.5.14”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script regex: “Torrent”
2010/11/18 14:42:23 [notice] 24622#0: *206 “Torrent” does not match
“Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14) Gecko/20101022
Firefox/3.5.14”, client: 10.222.16.2, server: hss, request: “GET
/?ar=1290119308 HTTP/1.1”, host: “news.google.com”, referrer:
“http://news.google.com/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“news.google.com”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script regex:
“northcountrygazette.org”
2010/11/18 14:42:23 [notice] 24622#0: *206 “northcountrygazette.org”
does not match “news.google.com”, client: 10.222.16.2, server: hss,
request: “GET /?ar=1290119308 HTTP/1.1”, host: “news.google.com”,
referrer: “http://news.google.com/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *206 test location: “/”
2010/11/18 14:42:23 [debug] 24622#0: *206 using configuration “/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http cl:-1 max:1048576
2010/11/18 14:42:23 [debug] 24622#0: *206 rewrite phase: 2
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var: “GET”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script value: “HEAD”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script equal
2010/11/18 14:42:23 [debug] 24622#0: *206 http script equal: no
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if
2010/11/18 14:42:23 [debug] 24622#0: *206 http script if: false
2010/11/18 14:42:23 [debug] 24622#0: *206 post rewrite phase: 3
2010/11/18 14:42:23 [debug] 24622#0: *206 generic phase: 4
2010/11/18 14:42:23 [debug] 24622#0: *206 generic phase: 5
2010/11/18 14:42:23 [debug] 24622#0: *206 access phase: 6
2010/11/18 14:42:23 [debug] 24622#0: *206 access: 0210DE0A 000000FF
0000000A
2010/11/18 14:42:23 [debug] 24622#0: *206 access phase: 7
2010/11/18 14:42:23 [debug] 24622#0: *206 post access phase: 8
2010/11/18 14:42:23 [debug] 24622#0: *206 posix_memalign:
000000000555AA60:4096 @16
2010/11/18 14:42:23 [debug] 24622#0: *206 http script copy: “http://”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“news.google.com”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http init upstream, client
timer: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 epoll add event: fd:14 op:3
ev:80000005
2010/11/18 14:42:23 [debug] 24622#0: *206 http script copy: “Host: "
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“news.google.com”
2010/11/18 14:42:23 [debug] 24622#0: *206 http script copy: "
"
2010/11/18 14:42:23 [debug] 24622#0: *206 http script copy: “Connection:
close
"
2010/11/18 14:42:23 [debug] 24622#0: 206 http proxy header:
“User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14)
Gecko/20101022 Firefox/3.5.14”
2010/11/18 14:42:23 [debug] 24622#0: 206 http proxy header: "Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“Accept-Language: en-us,en;q=0.5”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“Accept-Encoding: gzip,deflate”
2010/11/18 14:42:23 [debug] 24622#0: 206 http proxy header:
"Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.7”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header: “Referer:
http://news.google.com/”
2010/11/18 14:42:23 [debug] 24622#0: 206 http proxy header: “Cookie:
PREF=ID=6525926552b9e494:U=93cb6d5927e9b698:TM=1275696172:LM=1276718201:GM=1:S=UgVptM_ctrBVeN_L;
NID=40=OpJOX_yqI5wRZrfKaluyXdnDmAhNyrmCrKVwiAMJjJLG0U-B97WB-LUhffGDujDPrC_vb78vGxZ4kg1Q_tm8ABpwyMxo53B6PaMI_FukfxjuPSWvWBlX9C–vCOUTxH_;
rememberme=true; AF_C=4_http%3A//news.google.com/%3Far%3D1290119308”
2010/11/18 14:42:23 [debug] 24622#0: 206 http proxy header:
“Cache-Control: max-age=0”
2010/11/18 14:42:23 [debug] 24622#0: 206 http proxy header:
"GET /?ar=1290119308 HTTP/1.0
Host: news.google.com
Connection: close
User-Agent: Mozilla/5.0 (X11; U; FreeBSD i386; en-US; rv:1.9.1.14)
Gecko/20101022 Firefox/3.5.14
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,/;q=0.8
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,;q=0.7
Referer: http://news.google.com/
Cookie:
PREF=ID=6525926552b9e494:U=93cb6d5927e9b698:TM=1275696172:LM=1276718201:GM=1:S=UgVptM_ctrBVeN_L;
NID=40=OpJOX_yqI5wRZrfKaluyXdnDmAhNyrmCrKVwiAMJjJLG0U-B97WB-LUhffGDujDPrC_vb78vGxZ4kg1Q_tm8ABpwyMxo53B6PaMI_FukfxjuPSWvWBlX9C–vCOUTxH_;
rememberme=true; AF_C=4_http%3A//news.google.com/%3Far%3D1290119308
Cache-Control: max-age=0

"
2010/11/18 14:42:23 [debug] 24622#0: *206 http script var:
“68.68.108.251”
2010/11/18 14:42:23 [debug] 24622#0: *206 http cleanup add:
000000000555B360
2010/11/18 14:42:23 [debug] 24622#0: *206 name was resolved to
74.125.19.104
2010/11/18 14:42:23 [debug] 24622#0: *206 name was resolved to
74.125.19.147
2010/11/18 14:42:23 [debug] 24622#0: *206 name was resolved to
74.125.19.99
2010/11/18 14:42:23 [debug] 24622#0: *206 name was resolved to
74.125.19.103
2010/11/18 14:42:23 [debug] 24622#0: *206 get rr peer, try: 4
2010/11/18 14:42:23 [debug] 24622#0: *206 get rr peer, current: 3 1
2010/11/18 14:42:23 [debug] 24622#0: *206 socket 16
2010/11/18 14:42:23 [debug] 24622#0: *206 epoll add connection: fd:16
ev:80000005
2010/11/18 14:42:23 [debug] 24622#0: *206 connect to 74.125.19.103:80,
fd:16 #207
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream connect: -2
2010/11/18 14:42:23 [debug] 24622#0: *206 event timer add: 16:
60000:1290120203658
2010/11/18 14:42:23 [debug] 24622#0: *206 http finalize request: -4,
“/?ar=1290119308” a:1, c:2
2010/11/18 14:42:23 [debug] 24622#0: *206 http request count:2 blk:0
2010/11/18 14:42:23 [debug] 24622#0: *206 post event 00000000010EE8C0
2010/11/18 14:42:23 [debug] 24622#0: *190 event timer del: 30:
1290120143659
2010/11/18 14:42:23 [debug] 24622#0: *190 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *190 close http connection: 30
2010/11/18 14:42:23 [debug] 24622#0: *190 free: 00000000011F2180
2010/11/18 14:42:23 [debug] 24622#0: *190 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *190 free: 000000000555C6A0,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *190 free: 000000000555C7B0,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *206 delete posted event
00000000010EE8C0
2010/11/18 14:42:23 [debug] 24622#0: *206 http run request:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream check client,
write event:1, “/”
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream recv(): -1 (11:
Resource temporarily unavailable)
2010/11/18 14:42:23 [debug] 24622#0: *206 post event 00000000010EE650
2010/11/18 14:42:23 [debug] 24622#0: *206 delete posted event
00000000010EE650
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream request:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream send request
handler
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream send request
2010/11/18 14:42:23 [debug] 24622#0: *206 chain writer buf fl:1 s:728
2010/11/18 14:42:23 [debug] 24622#0: *206 chain writer in:
000000000555B5E8
2010/11/18 14:42:23 [debug] 24622#0: *206 writev: 728
2010/11/18 14:42:23 [debug] 24622#0: *206 chain writer out:
0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 event timer del: 16:
1290120203658
2010/11/18 14:42:23 [debug] 24622#0: *206 event timer add: 16:
60000:1290120203662
2010/11/18 14:42:23 [debug] 24622#0: *192 event timer del: 31:
1290120143667
2010/11/18 14:42:23 [debug] 24622#0: *192 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *192 close http connection: 31
2010/11/18 14:42:23 [debug] 24622#0: *192 free: 00000000012121C0
2010/11/18 14:42:23 [debug] 24622#0: *192 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *192 free: 00000000006DB190,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *192 free: 00000000006DB2A0,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *194 event timer del: 34:
1290120143675
2010/11/18 14:42:23 [debug] 24622#0: *194 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *194 close http connection: 34
2010/11/18 14:42:23 [debug] 24622#0: *194 free: 000000000121A1D0
2010/11/18 14:42:23 [debug] 24622#0: *194 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *194 free: 00000000006DB3B0,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *194 free: 000000000555A950,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *196 event timer del: 35:
1290120143685
2010/11/18 14:42:23 [debug] 24622#0: *196 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *196 close http connection: 35
2010/11/18 14:42:23 [debug] 24622#0: *196 free: 00000000012221E0
2010/11/18 14:42:23 [debug] 24622#0: *196 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *196 free: 000000000555BA70,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *196 free: 00000000056BFE40,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *198 event timer del: 37:
1290120143696
2010/11/18 14:42:23 [debug] 24622#0: *198 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *198 close http connection: 37
2010/11/18 14:42:23 [debug] 24622#0: *198 free: 000000000122A1F0
2010/11/18 14:42:23 [debug] 24622#0: *198 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *198 free: 00000000056BFF50,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *198 free: 00000000056C0550,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *200 event timer del: 39:
1290120143708
2010/11/18 14:42:23 [debug] 24622#0: *200 http keepalive handler
2010/11/18 14:42:23 [debug] 24622#0: *200 close http connection: 39
2010/11/18 14:42:23 [debug] 24622#0: *200 free: 0000000001232200
2010/11/18 14:42:23 [debug] 24622#0: *200 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *200 free: 00000000056C0660,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *200 free: 00000000056C0C60,
unused: 128
2010/11/18 14:42:23 [debug] 24622#0: *206 post event 00000000055AE2B0
2010/11/18 14:42:23 [debug] 24622#0: *206 post event 00000000010EE650
2010/11/18 14:42:23 [debug] 24622#0: *206 delete posted event
00000000010EE650
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream request:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream dummy handler
2010/11/18 14:42:23 [debug] 24622#0: *206 delete posted event
00000000055AE2B0
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream request:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream process header
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc: 00000000012021A0:65536
2010/11/18 14:42:23 [debug] 24622#0: *206 recv: fd:16 303 of 65536
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy status 200 “200 OK”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“Content-Type: text/html; charset=UTF-8”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“Content-Encoding: gzip”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header: “Date: Thu,
18 Nov 2010 22:42:29 GMT”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header: “Expires:
Thu, 18 Nov 2010 22:42:29 GMT”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“Cache-Control: private, max-age=0”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“X-Content-Type-Options: nosniff”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“X-Frame-Options: SAMEORIGIN”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header:
“X-XSS-Protection: 1; mode=block”
2010/11/18 14:42:23 [debug] 24622#0: *206 posix_memalign:
0000000005558930:4096 @16
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header: “Server:
GSE”
2010/11/18 14:42:23 [debug] 24622#0: *206 http proxy header done
2010/11/18 14:42:23 [debug] 24622#0: *206 http afheader in
2010/11/18 14:42:23 [debug] 24622#0: *206 http afheader out
2010/11/18 14:42:23 [debug] 24622#0: *206 HTTP/1.1 200 OK
Server: nginx/0.8.53
Date: Thu, 18 Nov 2010 22:42:23 GMT
Content-Type: text/html; charset=UTF-8
Transfer-Encoding: chunked
Connection: keep-alive
Expires: Thu, 18 Nov 2010 22:42:29 GMT
Cache-Control: private, max-age=0
X-Content-Type-Options: nosniff
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
Content-Encoding: gzip

2010/11/18 14:42:23 [debug] 24622#0: *206 write new buf t:1 f:0
0000000005558C28, pos 0000000005558C28, size: 364 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http write filter: l:0 f:0
s:364
2010/11/18 14:42:23 [debug] 24622#0: *206 tcp_nodelay
2010/11/18 14:42:23 [debug] 24622#0: *206 http output filter
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http copy filter:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http gunzip filter
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip alloc: n:1 s:9552
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc: 000000000557C9C0:9552
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in: 000000000555BA40
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in_buf:0000000005558D98
ni:0000000000000000 ai:0
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc: 0000000005559940:4096
2010/11/18 14:42:23 [debug] 24622#0: *206 inflate in:
ni:0000000000000000 no:0000000005559940 ai:0 ao:4096 fl:2 redo:0
2010/11/18 14:42:23 [debug] 24622#0: *206 inflate out:
ni:0000000000000000 no:0000000005559940 ai:0 ao:4096 rc:-5
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in_buf:0000000005558D98
pos:0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody in
2010/11/18 14:42:23 [debug] 24622#0: *206 http chunk size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody out
2010/11/18 14:42:23 [debug] 24622#0: *206 http postpone filter
“/?ar=1290119308” 0000000005558EA0
2010/11/18 14:42:23 [debug] 24622#0: *206 http gzip filter
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc:
0000000001242220:270336
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip alloc: n:1 s:5928 a:8192
p:0000000001242220
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip alloc: n:32768 s:2
a:65536 p:0000000001244220
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip alloc: n:32768 s:2
a:65536 p:0000000001254220
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip alloc: n:32768 s:2
a:65536 p:0000000001264220
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip alloc: n:16384 s:4
a:65536 p:0000000001274220
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip in: 0000000005558F10
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip in_buf:0000000005558EB0
ni:0000000000000000 ai:0
2010/11/18 14:42:23 [debug] 24622#0: *206 malloc: 00000000056BDE20:8192
2010/11/18 14:42:23 [debug] 24622#0: *206 deflate in:
ni:0000000000000000 no:00000000056BDE20 ai:0 ao:8192 fl:2 redo:0
2010/11/18 14:42:23 [debug] 24622#0: *206 deflate out:
ni:0000000000000000 no:00000000056BDE26 ai:0 ao:8186 rc:0
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip in_buf:0000000005558EB0
pos:0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 http chunk: 10
2010/11/18 14:42:23 [debug] 24622#0: *206 http chunk: 6
2010/11/18 14:42:23 [debug] 24622#0: *206 write old buf t:1 f:0
0000000005558C28, pos 0000000005558C28, size: 364 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 write new buf t:1 f:0
0000000000000000, pos 0000000005559060, size: 4 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 write new buf t:0 f:0
0000000000000000, pos 0000000000698D28, size: 10 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 write new buf t:1 f:0
00000000056BDE20, pos 00000000056BDE20, size: 6 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 write new buf t:0 f:0
0000000000000000, pos 000000000047E18D, size: 2 file: 0, size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http write filter: l:0 f:1
s:386
2010/11/18 14:42:23 [debug] 24622#0: *206 http write filter limit 0
2010/11/18 14:42:23 [debug] 24622#0: *206 writev: 386
2010/11/18 14:42:23 [debug] 24622#0: *206 http write filter
0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip in: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip out: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 http copy filter: 0
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http upstream process non
buffered upstream
2010/11/18 14:42:23 [debug] 24622#0: *206 recv: fd:16 10 of 65536
2010/11/18 14:42:23 [debug] 24622#0: *206 http output filter
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http copy filter:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http gunzip filter
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in: 00000000055590E8
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in_buf:0000000005559108
ni:00000000012021A0 ai:10
2010/11/18 14:42:23 [debug] 24622#0: *206 inflate in:
ni:00000000012021A0 no:0000000005559940 ai:10 ao:4096 fl:2 redo:0
2010/11/18 14:42:23 [debug] 24622#0: *206 inflate out:
ni:00000000012021AA no:0000000005559940 ai:0 ao:4096 rc:0
2010/11/18 14:42:23 [debug] 24622#0: *206 gunzip in_buf:0000000005559108
pos:00000000012021A0
2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody in
2010/11/18 14:42:23 [debug] 24622#0: *206 http chunk size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody out
2010/11/18 14:42:23 [debug] 24622#0: *206 http postpone filter
“/?ar=1290119308” 00000000055590D8
2010/11/18 14:42:23 [debug] 24622#0: *206 http gzip filter
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip in: 00000000055590C8
2010/11/18 14:42:23 [debug] 24622#0: *206 gzip in_buf:0000000005559158
ni:0000000000000000 ai:0
2010/11/18 14:42:23 [debug] 24622#0: *206 deflate in:
ni:0000000000000000 no:00000000056BDE20 ai:0 ao:8192 fl:2 redo:0
2010/11/18 14:42:23 [alert] 24622#0: *206 deflate() failed: 2, -5 while
reading upstream, client: 10.222.16.2, server: hss, request: “GET
/?ar=1290119308 HTTP/1.1”, upstream:
“http://74.125.19.103:80/?ar=1290119308”, host: “news.google.com”,
referrer: “http://news.google.com/”
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 0000000001242220
2010/11/18 14:42:23 [debug] 24622#0: *206 http copy filter: -1
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 finalize http upstream
request: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 finalize http proxy request
2010/11/18 14:42:23 [debug] 24622#0: *206 free rr peer 4 0
2010/11/18 14:42:23 [debug] 24622#0: *206 close http upstream
connection: 16
2010/11/18 14:42:23 [debug] 24622#0: *206 event timer del: 16:
1290120203662
2010/11/18 14:42:23 [debug] 24622#0: *206 http output filter
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http copy filter:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody in
2010/11/18 14:42:23 [debug] 24622#0: *206 http chunk size: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http afbody out
2010/11/18 14:42:23 [debug] 24622#0: *206 http postpone filter
“/?ar=1290119308” 00007FFF41986B20
2010/11/18 14:42:23 [debug] 24622#0: *206 http chunk: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 http copy filter: -1
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http finalize request: -1,
“/?ar=1290119308” a:1, c:1
2010/11/18 14:42:23 [debug] 24622#0: *206 http terminate request count:1
2010/11/18 14:42:23 [debug] 24622#0: *206 http terminate cleanup count:1
blk:0
2010/11/18 14:42:23 [debug] 24622#0: *206 http posted request:
“/?ar=1290119308”
2010/11/18 14:42:23 [debug] 24622#0: *206 http terminate handler count:1
2010/11/18 14:42:23 [debug] 24622#0: *206 http request count:1 blk:0
2010/11/18 14:42:23 [debug] 24622#0: *206 http close request
2010/11/18 14:42:23 [debug] 24622#0: *206 http log handler
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 00000000056BDE20
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 0000000000000000
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 0000000005559940
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 000000000557C9C0
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 00000000012021A0
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 00000000006D9740,
unused: 3
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 000000000555AA60,
unused: 0
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 0000000005558930,
unused: 1768
2010/11/18 14:42:23 [debug] 24622#0: *206 close http connection: 14
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 00000000011FA190
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 00000000056C0060
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 0000000005174080,
unused: 8
2010/11/18 14:42:23 [debug] 24622#0: *206 free: 0000000004E88BD0,
unused: 128
2010/11/18 14:42:24 [debug] 24622#0: *202 event timer del: 22:
1290120144005
2010/11/18 14:42:24 [debug] 24622#0: *202 http keepalive handler
2010/11/18 14:42:24 [debug] 24622#0: *202 close http connection: 22
2010/11/18 14:42:24 [debug] 24622#0: *202 free: 000000000123A210
2010/11/18 14:42:24 [debug] 24622#0: *202 free: 0000000000000000
2010/11/18 14:42:24 [debug] 24622#0: *202 free: 000000000555BB80,
unused: 8
2010/11/18 14:42:24 [debug] 24622#0: *202 free: 000000000555BC90,
unused: 128
2010/11/18 14:42:24 [debug] 24622#0: *204 event timer del: 26:
1290120144362
2010/11/18 14:42:24 [debug] 24622#0: *204 http keepalive handler
2010/11/18 14:42:24 [debug] 24622#0: *204 close http connection: 26
2010/11/18 14:42:24 [debug] 24622#0: *204 free: 00000000056B5E10
2010/11/18 14:42:24 [debug] 24622#0: *204 free: 0000000000000000
2010/11/18 14:42:24 [debug] 24622#0: *204 free: 000000000555BDA0,
unused: 8
2010/11/18 14:42:24 [debug] 24622#0: *204 free: 000000000555BEB0,
unused: 128