Multiple Entries in Log File

cpriest nginx-forum at nginx.us
Thu Dec 3 00:14:41 MSK 2009 

Okay, I've got some more details on this event.  I've changed the query params to zzzz=1 to secure my customers data but otherwise these are unmodified.

So based on this I *think* they are sending a second request through right?

Also, is 180140 a sequential connection number?  What's the 4388#0 designator?  Lastly which of these lines indicates a "new request" and also which means "new connection"?

Thanks!


2009/12/02 08:06:46  4388#0: *180140 http cl:-1 max:536870912
2009/12/02 08:06:46  4388#0: *180140 generic phase: 3
2009/12/02 08:06:46  4388#0: *180140 post rewrite phase: 4
2009/12/02 08:06:46  4388#0: *180140 generic phase: 5
2009/12/02 08:06:46  4388#0: *180140 generic phase: 6
2009/12/02 08:06:46  4388#0: *180140 generic phase: 7
2009/12/02 08:06:46  4388#0: *180140 access phase: 8
2009/12/02 08:06:46  4388#0: *180140 access phase: 9
2009/12/02 08:06:46  4388#0: *180140 post access phase: 10
2009/12/02 08:06:46  4388#0: *180140 http init upstream, client timer: 0
2009/12/02 08:06:46  4388#0: *180140 http script copy: "X-Forwarded-For: "
2009/12/02 08:06:46  4388#0: *180140 http script var: "216.52.252.82"
2009/12/02 08:06:46  4388#0: *180140 http script copy: "
2009/12/02 08:06:46  4388#0: *180140 http script copy: "Host: "
2009/12/02 08:06:46  4388#0: *180140 http script var: "levelyourdebt.com"
2009/12/02 08:06:46  4388#0: *180140 http script copy: "
2009/12/02 08:06:46  4388#0: *180140 http script copy: "Connection: close
2009/12/02 08:06:46  4388#0: *180140 http proxy header: "User-Agent: httpunit/1.5"
2009/12/02 08:06:46  4388#0: *180140 http proxy header: "Accept-Encoding: gzip"
2009/12/02 08:06:46  4388#0: *180140 http proxy header: "Cache-Control: no-cache"
2009/12/02 08:06:46  4388#0: *180140 http proxy header: "Pragma: no-cache"
2009/12/02 08:06:46  4388#0: *180140 http proxy header: "Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"
2009/12/02 08:06:46  4388#0: *180140 http proxy header:
2009/12/02 08:06:46  4388#0: *180140 http cleanup add: 080FD740
2009/12/02 08:06:46  4388#0: *180140 get rr peer, try: 2
2009/12/02 08:06:46  4388#0: *180140 get rr peer, current: 1 1
2009/12/02 08:06:46  4388#0: *180140 http upstream connect: -2
2009/12/02 08:06:46  4388#0: *180140 http run request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:46  4388#0: *180140 http upstream check client, write event:1, "/Post"
2009/12/02 08:06:46  4388#0: *180140 http upstream recv(): -1 (11: Resource temporarily unavailable)
2009/12/02 08:06:46  4388#0: *180140 http upstream request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:46  4388#0: *180140 http upstream send request handler
2009/12/02 08:06:46  4388#0: *180140 http upstream send request
2009/12/02 08:06:49  4388#0: *180140 http upstream request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 http upstream dummy handler
2009/12/02 08:06:49  4388#0: *180140 http upstream request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 http upstream process header
2009/12/02 08:06:49  4388#0: *180140 http proxy status 200 "200 OK"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Date: Wed, 02 Dec 2009 14:06:46 GMT"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Server: Apache"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Set-Cookie: PHPSESSID=038olqru8b0ivahda8uch58c93; path=/"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Expires: Thu, 19 Nov 1981 08:52:00 GMT"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Pragma: no-cache"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Content-Length: 25"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Connection: close"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Content-Type: text/plain; charset=UTF-8"
2009/12/02 08:06:49  4388#0: *180140 http proxy header done
2009/12/02 08:06:49  4388#0: *180140 HTTP/1.1 200 OK
2009/12/02 08:06:49  4388#0: *180140 http write filter: l:0 f:0 s:413
2009/12/02 08:06:49  4388#0: *180140 tcp_nodelay
2009/12/02 08:06:49  4388#0: *180140 http upstream process non buffered downstream
2009/12/02 08:06:49  4388#0: *180140 http output filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 copy filter: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 http postpone filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1" 080FDB6C
2009/12/02 08:06:49  4388#0: *180140 http gzip filter
2009/12/02 08:06:49  4388#0: *180140 gzip alloc: n:1 s:5824 a:8192 p:080E8DE8
2009/12/02 08:06:49  4388#0: *180140 gzip alloc: n:512 s:2 a:1024 p:080EADE8
2009/12/02 08:06:49  4388#0: *180140 gzip alloc: n:512 s:2 a:1024 p:080EB1E8
2009/12/02 08:06:49  4388#0: *180140 gzip alloc: n:512 s:2 a:1024 p:080EB5E8
2009/12/02 08:06:49  4388#0: *180140 gzip alloc: n:256 s:4 a:1024 p:080EB9E8
2009/12/02 08:06:49  4388#0: *180140 gzip in: 080FDBE0
2009/12/02 08:06:49  4388#0: *180140 gzip in_buf:080FDB74 ni:08128123 ai:25
2009/12/02 08:06:49  4388#0: *180140 deflate in: ni:08128123 no:081074C0 ai:25 ao:8192 fl:2 redo:0
2009/12/02 08:06:49  4388#0: *180140 deflate out: ni:0812813C no:081074DF ai:0 ao:8161 rc:0
2009/12/02 08:06:49  4388#0: *180140 gzip in_buf:080FDB74 pos:08128123
2009/12/02 08:06:49  4388#0: *180140 http chunk: 10
2009/12/02 08:06:49  4388#0: *180140 http chunk: 31
2009/12/02 08:06:49  4388#0: *180140 http write filter: l:0 f:1 s:460
2009/12/02 08:06:49  4388#0: *180140 http write filter limit 0
2009/12/02 08:06:49  4388#0: *180140 http write filter 00000000
2009/12/02 08:06:49  4388#0: *180140 gzip in: 00000000
2009/12/02 08:06:49  4388#0: *180140 copy filter: 0 "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 finalize http upstream request: 0
2009/12/02 08:06:49  4388#0: *180140 finalize http proxy request
2009/12/02 08:06:49  4388#0: *180140 free rr peer 2 0
2009/12/02 08:06:49  4388#0: *180140 close http upstream connection: 32
2009/12/02 08:06:49  4388#0: *180140 http output filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 copy filter: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 http postpone filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1" BFCE8E38
2009/12/02 08:06:49  4388#0: *180140 http gzip filter
2009/12/02 08:06:49  4388#0: *180140 gzip in: 0811EFD8
2009/12/02 08:06:49  4388#0: *180140 gzip in_buf:0811EFE0 ni:00000000 ai:0
2009/12/02 08:06:49  4388#0: *180140 deflate in: ni:00000000 no:081074C0 ai:0 ao:8192 fl:4 redo:0
2009/12/02 08:06:49  4388#0: *180140 deflate out: ni:00000000 no:081074C2 ai:0 ao:8190 rc:1
2009/12/02 08:06:49  4388#0: *180140 gzip in_buf:0811EFE0 pos:00000000
2009/12/02 08:06:49  4388#0: *180140 http chunk: 10
2009/12/02 08:06:49  4388#0: *180140 http write filter: l:1 f:1 s:20
2009/12/02 08:06:49  4388#0: *180140 http write filter limit 0
2009/12/02 08:06:49  4388#0: *180140 http write filter 00000000
2009/12/02 08:06:49  4388#0: *180140 copy filter: 0 "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 http finalize request: 0, "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1" 1
2009/12/02 08:06:49  4388#0: *180140 set http keepalive handler
2009/12/02 08:06:49  4388#0: *180140 http close request
2009/12/02 08:06:49  4388#0: *180140 http log handler
2009/12/02 08:06:49  4388#0: *180140 hc free: 00000000 0
2009/12/02 08:06:49  4388#0: *180140 hc busy: 00000000 0
2009/12/02 08:06:49  4388#0: *180140 http keepalive handler
2009/12/02 08:06:49  4388#0: *180140 http empty handler
2009/12/02 08:06:49  4388#0: *180140 http keepalive handler
2009/12/02 08:06:49  4388#0: *180140 http cl:-1 max:536870912
2009/12/02 08:06:49  4388#0: *180140 generic phase: 3
2009/12/02 08:06:49  4388#0: *180140 post rewrite phase: 4
2009/12/02 08:06:49  4388#0: *180140 generic phase: 5
2009/12/02 08:06:49  4388#0: *180140 generic phase: 6
2009/12/02 08:06:49  4388#0: *180140 generic phase: 7
2009/12/02 08:06:49  4388#0: *180140 access phase: 8
2009/12/02 08:06:49  4388#0: *180140 access phase: 9
2009/12/02 08:06:49  4388#0: *180140 post access phase: 10
2009/12/02 08:06:49  4388#0: *180140 http init upstream, client timer: 0
2009/12/02 08:06:49  4388#0: *180140 http script copy: "X-Forwarded-For: "
2009/12/02 08:06:49  4388#0: *180140 http script var: "216.52.252.82"
2009/12/02 08:06:49  4388#0: *180140 http script copy: "
2009/12/02 08:06:49  4388#0: *180140 http script copy: "Host: "
2009/12/02 08:06:49  4388#0: *180140 http script var: "levelyourdebt.com"
2009/12/02 08:06:49  4388#0: *180140 http script copy: "
2009/12/02 08:06:49  4388#0: *180140 http script copy: "Connection: close
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "User-Agent: httpunit/1.5"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Cookie: PHPSESSID=038olqru8b0ivahda8uch58c93"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Accept-Encoding: gzip"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Cache-Control: no-cache"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Pragma: no-cache"
2009/12/02 08:06:49  4388#0: *180140 http proxy header: "Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2"
2009/12/02 08:06:49  4388#0: *180140 http proxy header:
2009/12/02 08:06:49  4388#0: *180140 http cleanup add: 0811F88C
2009/12/02 08:06:49  4388#0: *180140 get rr peer, try: 2
2009/12/02 08:06:49  4388#0: *180140 get rr peer, current: 0 1
2009/12/02 08:06:49  4388#0: *180140 http upstream connect: -2
2009/12/02 08:06:49  4388#0: *180140 http upstream request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:49  4388#0: *180140 http upstream send request handler
2009/12/02 08:06:49  4388#0: *180140 http upstream send request
2009/12/02 08:06:50  4388#0: *180140 http upstream request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 http upstream dummy handler
2009/12/02 08:06:50  4388#0: *180140 http upstream request: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 http upstream process header
2009/12/02 08:06:50  4388#0: *180140 http proxy status 200 "200 OK"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Date: Wed, 02 Dec 2009 14:06:49 GMT"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Server: Apache"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Expires: Thu, 19 Nov 1981 08:52:00 GMT"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Pragma: no-cache"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Content-Length: 25"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Connection: close"
2009/12/02 08:06:50  4388#0: *180140 http proxy header: "Content-Type: text/plain; charset=UTF-8"
2009/12/02 08:06:50  4388#0: *180140 http proxy header done
2009/12/02 08:06:50  4388#0: *180140 HTTP/1.1 200 OK
2009/12/02 08:06:50  4388#0: *180140 http write filter: l:0 f:0 s:355
2009/12/02 08:06:50  4388#0: *180140 http upstream process non buffered downstream
2009/12/02 08:06:50  4388#0: *180140 http output filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 copy filter: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 http postpone filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1" 0811FD08
2009/12/02 08:06:50  4388#0: *180140 http gzip filter
2009/12/02 08:06:50  4388#0: *180140 gzip alloc: n:1 s:5824 a:8192 p:080E8DE8
2009/12/02 08:06:50  4388#0: *180140 gzip alloc: n:512 s:2 a:1024 p:080EADE8
2009/12/02 08:06:50  4388#0: *180140 gzip alloc: n:512 s:2 a:1024 p:080EB1E8
2009/12/02 08:06:50  4388#0: *180140 gzip alloc: n:512 s:2 a:1024 p:080EB5E8
2009/12/02 08:06:50  4388#0: *180140 gzip alloc: n:256 s:4 a:1024 p:080EB9E8
2009/12/02 08:06:50  4388#0: *180140 gzip in: 0811FD7C
2009/12/02 08:06:50  4388#0: *180140 gzip in_buf:0811FD10 ni:081280E9 ai:25
2009/12/02 08:06:50  4388#0: *180140 deflate in: ni:081280E9 no:081074C0 ai:25 ao:8192 fl:2 redo:0
2009/12/02 08:06:50  4388#0: *180140 deflate out: ni:08128102 no:081074DF ai:0 ao:8161 rc:0
2009/12/02 08:06:50  4388#0: *180140 gzip in_buf:0811FD10 pos:081280E9
2009/12/02 08:06:50  4388#0: *180140 http chunk: 10
2009/12/02 08:06:50  4388#0: *180140 http chunk: 31
2009/12/02 08:06:50  4388#0: *180140 http write filter: l:0 f:1 s:402
2009/12/02 08:06:50  4388#0: *180140 http write filter limit 0
2009/12/02 08:06:50  4388#0: *180140 http write filter 00000000
2009/12/02 08:06:50  4388#0: *180140 gzip in: 00000000
2009/12/02 08:06:50  4388#0: *180140 copy filter: 0 "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 finalize http upstream request: 0
2009/12/02 08:06:50  4388#0: *180140 finalize http proxy request
2009/12/02 08:06:50  4388#0: *180140 free rr peer 2 0
2009/12/02 08:06:50  4388#0: *180140 close http upstream connection: 22
2009/12/02 08:06:50  4388#0: *180140 http output filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 copy filter: "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 http postpone filter "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1" BFCE8E38
2009/12/02 08:06:50  4388#0: *180140 http gzip filter
2009/12/02 08:06:50  4388#0: *180140 gzip in: 0811FFCC
2009/12/02 08:06:50  4388#0: *180140 gzip in_buf:0811FFD4 ni:00000000 ai:0
2009/12/02 08:06:50  4388#0: *180140 deflate in: ni:00000000 no:081074C0 ai:0 ao:8192 fl:4 redo:0
2009/12/02 08:06:50  4388#0: *180140 deflate out: ni:00000000 no:081074C2 ai:0 ao:8190 rc:1
2009/12/02 08:06:50  4388#0: *180140 gzip in_buf:0811FFD4 pos:00000000
2009/12/02 08:06:50  4388#0: *180140 http chunk: 10
2009/12/02 08:06:50  4388#0: *180140 http write filter: l:1 f:1 s:20
2009/12/02 08:06:50  4388#0: *180140 http write filter limit 0
2009/12/02 08:06:50  4388#0: *180140 http write filter 00000000
2009/12/02 08:06:50  4388#0: *180140 copy filter: 0 "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1"
2009/12/02 08:06:50  4388#0: *180140 http finalize request: 0, "/Post?zzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzzz=1" 1
2009/12/02 08:06:50  4388#0: *180140 set http keepalive handler
2009/12/02 08:06:50  4388#0: *180140 http close request
2009/12/02 08:06:50  4388#0: *180140 http log handler
2009/12/02 08:06:50  4388#0: *180140 hc free: 00000000 0
2009/12/02 08:06:50  4388#0: *180140 hc busy: 00000000 0
2009/12/02 08:06:50  4388#0: *180140 http keepalive handler
2009/12/02 08:06:59  4388#0: *180140 http empty handler
2009/12/02 08:06:59  4388#0: *180140 http keepalive handler
2009/12/02 08:06:59  4388#0: *180140 client 216.52.252.82 closed keepalive connection
2009/12/02 08:06:59  4388#0: *180140 close http connection: 25


Posted at Nginx Forum: http://forum.nginx.org/read.php?2,26839,27522#msg-27522

More information about the nginx mailing list