Hi...<div><br></div><div>Just made myself of a dump from the backend perspective and analized with wireshark to see what were on those bytes, I was pretty sure those bytes were some error from the app with the key to fix it.... but no, those 15776 bytes are always 15776 but the first 15776 of every request, so every request is different.</div>
<div><br></div><div>According to tcpdump everything flows OK and after one common ack from upstream while backend sends data, upstream inmediatly sends the FIN flag and inmediatly after that a group of RST arrive.</div>
<div>
<br></div><div>So, clearly there's no backend issue here, whatever happens it's on the upstream, and now it looks more a problem with the OS than nginx fault.</div><div><br></div><div>Anyone have any ideas why the OS may be closing & resetting nginx connections?</div>
<div><br></div><div>OS: Debian Lenny Virtualized inside XenServer (Citrix free version)</div><div>Virtual cores: 2 ( Load: 0.10)</div><div>RAM: 2GB (Currently: 44mb free / 1.3GB os cached, 310MB buffers)</div><div><br></div>
<div>Currently show no load and problem occurrs to 20%-30% of traffic to both backends but only for a specific url. This main nginx it's doing load balancing for more domains, some of them with a lot of traffic, and there's not a single status 200 0 byte request in the logs of others domains.</div>
<div><br></div><div>Some network stats:</div><div><div>netstat -anp|awk '$1~/^tcp/ { print $6 }'|sort -n|uniq -c</div><div> 2 CLOSING</div><div> 164 ESTABLISHED</div><div> 21 FIN_WAIT1</div><div> 150 FIN_WAIT2</div>
<div> 1 LAST_ACK</div><div> 9 LISTEN</div><div> 4 SYN_RECV</div><div> 1 SYN_SENT</div><div> 293 TIME_WAIT</div></div><div><br></div><div>No custom configuration inside /etc/sysctl.conf...</div><div>
<br></div><div>I'll be gladly submit more thata from the faulty nginx server if anyone needs, just ask</div><div><br></div><div>Thanks for any hint, I'm really out of ideas</div><div><br><div class="gmail_quote">
On Fri, Aug 3, 2012 at 2:48 PM, Guzmán Brasó <span dir="ltr"><<a href="mailto:guzman.braso@gmail.com" target="_blank">guzman.braso@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi list!<div><br></div><div>I've a weid issue I've been banging my head without been able to understand what's going on.</div>
<div><br></div><div>Setup is as follow:</div><div>- 1 nginx 0.7.67 doing load balance to two backends.</div>
<div>- backend 1 with Nginx 1.2.2 and php-fpm 5.3</div><div>- backend 2 with Nginx 0.7.67 and php-fpm 5.3</div><div><br></div><div>Some, and only some requests log in the upstream status 200 and 0 byte returned.</div><div>
Same request in the backend log shows a 200 status and ALWAYS the same amount of bytes, which change between backends.</div><div>When this happen on a request that went to backend 1: upstream logs 200 0 byte, backend logs 200 15776 bytes.</div>
<div>When this happen on a request that went to backend 2: upstream logs 200 0 byte, backend logs 200 15670 bytes.</div><div><br></div><div>I've tried without luck to reproduce the problem, so I decided to start debugging all requests to this site to try to understand why nginx is returning empty responses.</div>
<div><br></div><div>This is what I see in upstream when error happens:</div><div>(...)</div><div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http proxy header: "Accept: */*"</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http proxy header: "User-Agent: AdsBot-Google (+<a href="http://www.google.com/adsbot.html" target="_blank">http://www.google.com/adsbot.html</a>)"</div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 http proxy header: "Accept-Encoding: gzip,deflate"</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http proxy header:</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http cleanup add: 0000000001A3DF10</div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 get rr peer, try: 2</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 get rr peer, current: 0 8</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 socket 149</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 epoll add connection: fd:149 ev:80000005 </div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 connect to <a href="http://176.31.64.205:8059" target="_blank">176.31.64.205:8059</a>, fd:149 #824</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http upstream connect: -2</div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 event timer add: 149: 30000:1344011162971</div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 http run request: "/s/miracle+noodle?"</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http upstream check client, write event:1, "/s/miracle+noodle" </div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 http upstream recv(): -1 (11: Resource temporarily unavailable)</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http upstream request: "/s/miracle+noodle?"</div>
<div>
2012/08/03 13:25:32 [debug] 1546#0: *823 http upstream send request handler</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 http upstream send request </div></div><div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 chain writer buf fl:1 s:358</div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 chain writer in: 0000000001A3DF48</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 writev: 358</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 chain writer out: 0000000000000000</div>
<div>2012/08/03 13:25:32 [debug] 1546#0: *823 event timer del: 149: 1344011162971</div><div>2012/08/03 13:25:32 [debug] 1546#0: *823 event timer add: 149: 120000:1344011252972</div><div>2012/08/03 13:25:33 [debug] 1546#0: *823 http run request: "/s/miracle+noodle?"</div>
<div>2012/08/03 13:25:33 [debug] 1546#0: *823 http upstream check client, write event:0, "/s/miracle+noodle"</div><div>2012/08/03 13:25:33 [debug] 1546#0: *823 http upstream recv(): 0 (11: Resource temporarily unavailable)</div>
<div>2012/08/03 13:25:33 [debug] 1546#0: *823 http run request: "/s/miracle+noodle?"</div><div>2012/08/03 13:25:33 [debug] 1546#0: *823 http upstream check client, write event:1, "/s/miracle+noodle"</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 http upstream request: "/s/miracle+noodle?"</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http upstream process header</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 malloc: 0000000001B8DC30:16384</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 recv: fd:149 4344 of 16296</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy status 200 "200 OK"</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy header: "Server: nginx"</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy header: "Date: Fri, 03 Aug 2012 16:24:26 GMT"</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy header: "Content-Type: text/html"</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy header: "Connection: close"</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy header: "X-Powered-By: PHP/5.3.15-1~dotdeb.0"</div><div>
2012/08/03 13:25:45 [debug] 1546#0: *823 http proxy header done</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 HTTP/1.1 200 OKM</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 finalize http upstream request: -1</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 finalize http proxy request</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 free rr peer 2 0</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 close http upstream connection: 149</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 event timer del: 149: 1344011252972</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http upstream cache fd: 0</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http file cache free</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 http finalize request: -1, "/s/miracle+noodle?" 1</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http close request</div></div><div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 http log handler</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 run cleanup: 0000000001A3DC40</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 run cleanup: 0000000001850E58</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 0000000001B8DC30</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 00000000018501C0, unused: 1</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 0000000001A3D890, unused: 757</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 close http connection: 148 </div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 00000000019B7C20</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 0000000001B2BEF0</div><div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 0000000001B3DC00, unused: 8</div>
<div>2012/08/03 13:25:45 [debug] 1546#0: *823 free: 00000000019F55B0, unused: 112</div></div><div><br></div><div>The above debug log on upsteams seems to say that the backend closed the connection after headers, am I right?</div>
<div><br></div><div>However, backend debug of another affected request that always log as returned the same amount of bytes (which is pretty weird), shows a different story..</div><div>After many of...</div><div>(...)</div>
<div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe recv chain: -2</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010A2FD0, size: 49752 file: 0, size: 0</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010AF230, size: 65456 file: 0, size: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf free s:0 t:1 f:0 00000000010BF1F0, pos 00000000010BF1F0, size: 80 file: 0, size: 0</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe length: -1</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe write downstream: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe read upstream: 0</div><div>
2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010A2FD0, size: 49752 file: 0, size: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010AF230, size: 65456 file: 0, size: 0</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf free s:0 t:1 f:0 00000000010BF1F0, pos 00000000010BF1F0, size: 80 file: 0, size: 0 </div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe length: -1</div></div><div>
(...)</div><div><br></div><div>Sudenly this comes:</div><div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe recv chain: -2</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010A2FD0, size: 49752 file: 0, size: 0</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010AF230, size: 65456 file: 0, size: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf free s:0 t:1 f:0 00000000010BF1F0, pos 00000000010BF1F0, size: 49232 file: 0, size: 0</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe length: -1</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe write downstream: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe read upstream: 0</div><div>
2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010A2FD0, size: 49752 file: 0, size: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf busy s:1 t:1 f:0 000000000109F1E0, pos 00000000010AF230, size: 65456 file: 0, size: 0</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe buf free s:0 t:1 f:0 00000000010BF1F0, pos 00000000010BF1F0, size: 49232 file: 0, size: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 pipe length: -1 </div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 event timer: 13, old: 1344013157360, new: 1344013157362</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 event timer: 12, old: 1344013037361, new: 1344013037362</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 post event 000000000106B360</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 delete posted event 000000000106B360</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 http run request: "/s/new+balance+1500?"</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 http upstream check client, write event:0, "/s/new+balance+1500"</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 http upstream recv(): 0 (11: Resource temporarily unavailable)</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 finalize http upstream request: 499</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 finalize http fastcgi request</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 free rr peer 1 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 close http upstream connection: 13</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 free: 0000000000FF7CD0, unused: 48</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 event timer del: 13: 1344013157360</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 reusable connection: 0</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 http upstream temp fd: -1</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 http output filter "/s/new+balance+1500?"</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 http copy filter: "/s/new+balance+1500?"</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 image filter</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 xslt filter body</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 http postpone filter "/s/new+balance+1500?" 0000000000FEDA18</div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 http copy filter: -1 "/s/new+balance+1500?"</div>
<div>2012/08/03 13:56:17 [debug] 1519#0: *221 http finalize request: -1, "/s/new+balance+1500?" a:1, c:1</div></div><div><br></div><div>So this means the backend felt the upstream closed the connection before it was allowed to return all data:</div>
<div><div>2012/08/03 13:56:17 [debug] 1519#0: *221 finalize http upstream request: 499</div></div><div><br></div><div>If that's the case, why it saves this to the logfile:</div><div><div>[03/Aug/2012:13:56:17 -0300] "GET /s/new+balance+1500 HTTP/1.0" 200 15776 "-" "AdsBot-Google (+<a href="http://www.google.com/adsbot.html" target="_blank">http://www.google.com/adsbot.html</a>)" - Cache: - 200 24.535</div>
</div><div><br></div><div>I think the problem may be in the upstream, as this weird beahavior happens with both backends and both use different nginx versions, but I'm really out of answers right now with this issue.</div>
<div><br></div><div>Any idea? Hint? Today of 8K requests, 2779 returned 0 bytes on the upstream and 15776 bytes on the backend.... </div><div><br></div><div>Thank you!!</div><span><font color="#888888"><div>
<br></div><div>Guzmán</div><div><br></div>
<div><br></div><div><br>-- <br>Guzmán Brasó Núñez<br>Senior Perl Developer / Sysadmin<br>Web: <a href="http://guzman.braso.info" target="_blank">http://guzman.braso.info</a><br>Mobile: <a href="tel:%2B598%2098%20674020" value="+59898674020" target="_blank">+598 98 674020</a><br>
</div>
</font></span></blockquote></div><br><br clear="all"><div><br></div>-- <br>Guzmán Brasó Núñez<br>Senior Perl Developer / Sysadmin<br>Web: <a href="http://guzman.braso.info" target="_blank">http://guzman.braso.info</a><br>
Mobile: <a href="tel:%2B598%2098%20674020" value="+59898674020" target="_blank">+598 98 674020</a><br>
</div>