upstream prematurely closed connection while reading response header from upstream

[Maxim Dounin]

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.

-- 
Maxim Dounin
http://nginx.org/