nginx has problem sending request body to upstream

[Roman Arutyunyan]

On Fri, Apr 12, 2019 at 09:21:07PM -0400, allenhe wrote:
> I understand the connection establish timer, write timer and read timer
> should be setup and removed in order, but where is the write timer? 

It's not that simple.  Writing and reading are done in parallel.
In fact if nginx receives the response even before sending out the full request,
it also counts as a successful proxying.

> are
> there lines in the logs saying I'm going to send the bytes, the sending is
> on-going, and the bytes has been sent out?

I'll give a short explanation of what's going on:

> 2019/04/12 14:49:38 [debug] 92#92: *405 epoll add connection: fd:29 ev:80002005
> 2019/04/12 14:49:38 [debug] 92#92: *405 connect to 202.111.0.40:1084, fd:29 #406

Calling connect() on the upstream socket fd=29

> 2019/04/12 14:49:38 [debug] 92#92: *405 http upstream connect: -2

The connect() call returned EINPROGRESS (converted to NGX_AGAIN=-2).
Now wait until the socket is connected, this will be repored on the write event.

> 2019/04/12 14:49:38 [debug] 92#92: *405 posix_memalign: 0000000001CCA480:128 @16
> 2019/04/12 14:49:38 [debug] 92#92: *405 event timer add: 29: 2000:1555051780835

Schedule a timer for proxy_connect_timeout to wait until the upstream socket is
connected.  This is very much like the write timeout, and it is scheduled on the
write event.

> 2019/04/12 14:49:38 [debug] 92#92: *405 http finalize request: -4, "/inetmanager/v1/configinfo?" a:1, c:2
> 2019/04/12 14:49:38 [debug] 92#92: *405 http request count:2 blk:0 2019/04/12 14:49:38 [debug] 92#92: *405 http run request: "/inetmanager/v1/configinfo?"
> 2019/04/12 14:49:38 [debug] 92#92: *405 http upstream check client, write event:1, "/inetmanager/v1/configinfo"

This call is irrelevant to the main topic.

> 2019/04/12 14:49:38 [debug] 92#92: *405 http upstream request: "/inetmanager/v1/configinfo?"

Upstream socket write event.  The socket is now connected.  Code below tries to
send the request.

> 2019/04/12 14:49:38 [debug] 92#92: *405 http upstream send request handler
> 2019/04/12 14:49:38 [debug] 92#92: *405 http upstream send request
> 2019/04/12 14:49:38 [debug] 92#92: *405 http upstream send request body
> 2019/04/12 14:49:38 [debug] 92#92: *405 chain writer buf fl:1 s:323
> 2019/04/12 14:49:38 [debug] 92#92: *405 chain writer in: 0000000001CB5498
> 2019/04/12 14:49:38 [debug] 92#92: *405 writev: 323 of 323
> 2019/04/12 14:49:38 [debug] 92#92: *405 chain writer out: 0000000000000000

All 323 bytes of the request are sent.  No surprise we could send 323 bytes
with a single writev().

> 2019/04/12 14:49:38 [debug] 92#92: *405 event timer del: 29: 1555051780835

Unschedule the write timer, we have nothing to write now.

> 2019/04/12 14:49:38 [debug] 92#92: *405 event timer add: 29: 600000:1555052378841

We still expect to read something from upstream.  Now scheduling
proxy_read_timeout for this on the read event.  Read and write can run in
parallel in nginx, but in this particular case write was fast.

> 2019/04/12 14:50:17 [debug] 92#92: *405 http run request: "/inetmanager/v1/configinfo?"
> 2019/04/12 14:50:17 [debug] 92#92: *405 http upstream check client, write event:0, "/inetmanager/v1/configinfo"
> 2019/04/12 14:50:17 [info] 92#92: *405 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 202.111.0.51, server: , request: "GET /inetmanager/v1/configinfo HTTP/1.1", upstream: "http://202.111.0.40:1084/inetmanager/v1/configinfo", host: "202.111.0.37:1102"
> 2019/04/12 14:50:17 [debug] 92#92: *405 finalize http upstream request: 499

39 seconds later client disconnected.  No events from upstream for this period.

-- 
Roman Arutyunyan