# Multiple Entries in Log File

**URL:** <https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627>\
**Category:** NGINX\
**Created:** [November 30, 2009, 8:43pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627 "2009-11-30T20:43:58Z")\
**Posts on this page:** 6\
**Page:** 1

<div class="post-metadata">

**Author:** ![cpriest](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/c/8491ac/32.png) [@cpriest](https://www.ruby-forum.com/u/cpriest)\
**Post date:** [November 30, 2009, 8:43pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627/1 "2009-11-30T20:43:58Z")

</div>

I have nginx setup as a load balancer to three servers. Is there _any_  
reason a request would hit the log file more than once unless there were  
actually more than one incoming (from the internet) requests?

For example, if one of my internal servers is down or slow and a proxy  
timeout setting is reached, would that cause nginx to log twice to the  
access log? Would there be any message about said occurrence in any  
error or other log?

Thanks,

-Clint

Posted at Nginx Forum:

> **[Multiple Entries in Log File](https://forum.nginx.org/read.php?2,26839,26839#msg-26839)**
>
> I have nginx setup as a load balancer to three servers. Is there \*any\* reason a request would hit the log file more than once unless there were actually more than one incoming (from the internet) requests? For example, if one of my internal servers...

---

<div class="post-metadata">

**Author:** ![cpriest](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/c/8491ac/32.png) [@cpriest](https://www.ruby-forum.com/u/cpriest)\
**Post date:** [December 1, 2009, 10:13pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627/2 "2009-12-01T22:13:54Z")

</div>

Why did that solve the problem for this individual? This doesn’t really  
answer my question anyways, I’m trying to determine why it would be  
logging it twice, not how to get around the issue.

The servers behind nginx are showing two connections…

Posted at Nginx Forum:

> **[Re: Multiple Entries in Log File](https://forum.nginx.org/read.php?2,26839,26934#msg-26934)**
>
> I have nginx setup as a load balancer to three servers. Is there \*any\* reason a request would hit the log file more than once unless there were actually more than one incoming (from the internet) requests? For example, if one of my internal servers...

---

<div class="post-metadata">

**Author:** ![cpriest](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/c/8491ac/32.png) [@cpriest](https://www.ruby-forum.com/u/cpriest)\
**Post date:** [December 19, 2009, 3:25pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627/3 "2009-12-19T15:25:26Z")

</div>

On Mon, Nov 30, 2009 at 8:36 PM, cpriest [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) wrote:

> I have nginx setup as a load balancer to three servers. Â Is there _any_ reason a request would hit the log file more than once unless there were actually more than one incoming (from the internet) requests?
> 
> For example, if one of my internal servers is down or slow and a proxy timeout setting is reached, would that cause nginx to log twice to the access log? Â Would there be any message about said occurrence in any error or other log?

uhm? [http://forum.nginx.org/read.php?2,26189,26201#msg-26201](http://forum.nginx.org/read.php?2,26189,26201#msg-26201)

## mk

(let\* ((mk “MichaÅ‚ Kowalski”) (sig `(lambda () ,mk))) ((eval sig)))

---

<div class="post-metadata">

**Author:** ![cpriest](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/c/8491ac/32.png) [@cpriest](https://www.ruby-forum.com/u/cpriest)\
**Post date:** [December 2, 2009, 10:18pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627/4 "2009-12-02T22:18:56Z")

</div>

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](http://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](http://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:

> **[Re: Multiple Entries in Log File](https://forum.nginx.org/read.php?2,26839,27522#msg-27522)**
>
> I have nginx setup as a load balancer to three servers. Is there \*any\* reason a request would hit the log file more than once unless there were actually more than one incoming (from the internet) requests? For example, if one of my internal servers...

---

<div class="post-metadata">

**Author:** ![cpriest](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/c/8491ac/32.png) [@cpriest](https://www.ruby-forum.com/u/cpriest)\
**Post date:** [December 19, 2009, 3:25pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627/5 "2009-12-19T15:25:26Z")

</div>

On Mon, Nov 30, 2009 at 02:36:55PM -0500, cpriest wrote:

> I have nginx setup as a load balancer to three servers. Is there _any_ reason a request would hit the log file more than once unless there were actually more than one incoming (from the internet) requests?
> 
> For example, if one of my internal servers is down or slow and a proxy timeout setting is reached, would that cause nginx to log twice to the access log? Would there be any message about said occurrence in any error or other log?

nginx should log once in access\_log and may log several times in  
error\_log.  
Could you create debug log ?

–  
Igor S.

> **[Igor Sysoev](http://sysoev.ru/en/)**

---

<div class="post-metadata">

**Author:** ![cpriest](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/c/8491ac/32.png) [@cpriest](https://www.ruby-forum.com/u/cpriest)\
**Post date:** [December 19, 2009, 3:25pm UTC](https://www.ruby-forum.com/t/multiple-entries-in-log-file/179627/6 "2009-12-19T15:25:27Z")

</div>

On Wed, Dec 02, 2009 at 04:14:41PM -0500, cpriest wrote:

> 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?

Yes, the client send request twice.

> Also, is 180140 a sequential connection number?

Yes. It’s usually used to search particular connection in huge debug  
logs.

> What’s the 4388#0 designator?

4388 is a proces number, 0 is a thread number (0 means there are no  
threads).

> Lastly which of these lines indicates a “new request” and also which means “new connection”?

The log is not complete, probably, because you have other error\_log  
directives.

> 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

Here is a new request:

> 2009/12/02 08:06:49 4388#0: \*180140 http keepalive handler

But some lines are missed.

> 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

–  
Igor S.

> **[Igor Sysoev](http://sysoev.ru/en/)**