Hi Max, thanks for the explanation, I agree that from the traces, it really looks like there were no data available in the socket from the upstream, thus a different situation than I posted the first time. I will try to reproduce the problem with both, debug log and wireshark traces that will match and will get back to you.
Jirka H. On 10/17/2014 06:58 AM, Maxim Dounin wrote: > Hello! > > On Fri, Oct 17, 2014 at 12:48:43AM +0200, Jiri Horky wrote: > > [...] > >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 connect to 1.1.1.1:8888, >> fd:184 #12552 > Here connection is stablished to an upstream server. > >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream connect: -2 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 posix_memalign: >> 0000000000FD3720:128 @16 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 184: >> 90000:1413499405670 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http finalize request: -4, >> "/en-us/?" a:1, c:2 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http request count:2 blk:0 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event >> 0000000000D36008 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http run request: "/en-us/?" >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream check client, >> write event:1, "/en-us/" >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream recv(): -1 >> (11: Resource temporarily unavailable) >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D39818 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event >> 0000000000D39818 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream request: >> "/en-us/?" >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request >> handler >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream send request >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer buf fl:1 s:1618 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer in: >> 0000000001041398 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 writev: 1618 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 chain writer out: >> 0000000000000000 > Request is written into the socket. > >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer del: 184: >> 1413499405670 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 event timer add: 184: >> 90000:1413499405670 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D33008 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 post event 0000000000D39818 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 delete posted event >> 0000000000D33008 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream request: >> "/en-us/?" >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 http upstream process header >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 malloc: 0000000000FAB620:8192 >> 2014/10/17 00:41:55 [debug] 27396#0: *12485 recv: fd:184 0 of 8192 >> 2014/10/17 00:41:55 [error] 27396#0: *12485 upstream prematurely closed >> connection while reading response header from upstream, client: >> 68.39.176.125, server: my.upstream.com, request: "GET /en-us/ HTTP/1.1", >> upstream: "http://1.1.1.1:8888/en-us/";, host: "my.upstream.com", >> referrer: "https://id.upstream.com/en-us/confirm/registration?token=TOKEN"; > And reading from the socket indicate that it's closed. > > Packet traces you previously posted look unrelated to this debug > log. In this case, there is either no response from the upstream > at all, or the response contents are lost due to RST from the > upstream. > > If, as you wrote, your backend "forcibly closes the connection", > the reason may be that it does so by using close() with SO_LINGER, > and this in turn results in RST being send to nginx in some cases. > > In either case debug log suggests there is nothing wrong on nginx > side, you should focus on your backend instead. > _______________________________________________ nginx mailing list [email protected] http://mailman.nginx.org/mailman/listinfo/nginx
