Dropped https client connection doesn't drop backend proxy_pass connection

Fri Mar 15 04:22:31 UTC 2013

Hi

I'm trying to setup nginx to proxy a server sent events connection
(http://dev.w3.org/html5/eventsource/) to a backend server.

The approach is the browser connects to a particular path, which then
checks the cookies to see the connection is authorised, and then returns
an X-Accel-Redirect header to connect up to a separate internal path to
do the proxying. That separate internal path is configured like this:

    location ^~ /pushevents/ {
      internal;

      # Immediately send backend responses back to client
      proxy_buffering off;
      # Disable keepalive to browser
      keepalive_timeout 0;
      # It's a long lived backend connection with potentially a long
      time between
      #  push events, make sure proxy doesn't timeout
      proxy_read_timeout 7200;

      proxy_pass http://pushbackend;
    }

The backend service listening on pushbackend then holds the connection
open, and returns data down the connection whenever a push event occurs,
which nginx proxies straight back to the browser because buffering is
turned off.

One important thing here is that if the client drops the connection to
nginx, nginx should also drop the connection to the backend server. This
is done by making sure we do not change proxy_ignore_client_abort, which
defaults to off.

Testing this out, it all works fine for http browser connections, but
appears to be broken for https browser connections.

When using http with my test client, I see this in the nginx log when
the client disconnects:

2013/03/14 23:27:27 [info] 27717#0: *1 client prematurely closed
connection, so upstream connection is closed too while reading upstream,
client: 10.50.1.14, server: www.*, request: "GET /events/ HTTP/1.0",
upstream: "http://127.0.0.4:80/.../", host: "..."

And when I check netstat, I see that the connection from nginx ->
pushbackend has been dropped as well.

However for https connections, this is not what happens. Instead, it
appears nginx fails to detect that the client has closed the connection,
and leaves the nginx -> pushbackend connection open (confirmed with
netstat). And because we set proxy_read_timeout to 2 hours, it takes 2
hours for that connection to be closed! That's bad.

This is nginx 1.2.7 compiled with openssl 1.0.1e.

With an http connection with debugging enabled, when I close the client
connection I see this in the log:

2013/03/15 00:11:33 [debug] 28285#0: epoll: fd:3 ev:0005
d:00007F6B414AA150
2013/03/15 00:11:33 [debug] 28285#0: *1 http run request: "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 http upstream check client,
write event:0, "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 http upstream recv(): 0 (11:
Resource temporarily unavailable)
2013/03/15 00:11:33 [info] 28285#0: *1 client prematurely closed
connection, so upstream connection is closed too while reading upstream,
client: 10.50.1.14, server: insecure.*, request: "GET /events/
HTTP/1.0", upstream: "http://127.0.0.4/.../", host: "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 finalize http upstream request:
499
2013/03/15 00:11:33 [debug] 28285#0: *1 finalize http proxy request
2013/03/15 00:11:33 [debug] 28285#0: *1 free rr peer 1 0
2013/03/15 00:11:33 [debug] 28285#0: *1 close http upstream connection:
32
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001847BC0, unused:
48
2013/03/15 00:11:33 [debug] 28285#0: *1 event timer del: 32:
1363327885296
2013/03/15 00:11:33 [debug] 28285#0: *1 reusable connection: 0
2013/03/15 00:11:33 [debug] 28285#0: *1 http output filter "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 http copy filter: "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 http postpone filter "..."
00007FFF614BAFE0
2013/03/15 00:11:33 [debug] 28285#0: *1 http copy filter: -1 "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 http finalize request: -1, "..."
a:1, c:1
2013/03/15 00:11:33 [debug] 28285#0: *1 http terminate request count:1
2013/03/15 00:11:33 [debug] 28285#0: *1 http terminate cleanup count:1
blk:0
2013/03/15 00:11:33 [debug] 28285#0: *1 http posted request: "..."
2013/03/15 00:11:33 [debug] 28285#0: *1 http terminate handler count:1
2013/03/15 00:11:33 [debug] 28285#0: *1 http request count:1 blk:0
2013/03/15 00:11:33 [debug] 28285#0: *1 http close request
2013/03/15 00:11:33 [debug] 28285#0: *1 http log handler
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001952800
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001895EA0
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001846BB0, unused:
0
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001894E90, unused:
3
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001896EB0, unused:
1771
2013/03/15 00:11:33 [debug] 28285#0: *1 close http connection: 3
2013/03/15 00:11:33 [debug] 28285#0: *1 reusable connection: 0
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 00000000018467A0
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 00000000018461A0
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 000000000183B210, unused:
8
2013/03/15 00:11:33 [debug] 28285#0: *1 free: 0000000001846690, unused:
128
2013/03/15 00:11:33 [debug] 28285#0: timer delta: 3247
2013/03/15 00:11:33 [debug] 28285#0: posted events 0000000000000000
2013/03/15 00:11:33 [debug] 28285#0: worker cycle
2013/03/15 00:11:33 [debug] 28285#0: epoll timer: -1

When doing the same thing with an https connection (openssl s_client)
and closing the connection I see this in the log:

2013/03/15 00:10:23 [debug] 28237#0: epoll: fd:3 ev:0005
d:00007F6ECDCAE150
2013/03/15 00:10:23 [debug] 28237#0: *1 http run request: "..."
2013/03/15 00:10:23 [debug] 28237#0: *1 http upstream check client,
write event:0, "..."
2013/03/15 00:10:23 [debug] 28237#0: *1 http upstream recv(): 1 (11:
Resource temporarily unavailable)
2013/03/15 00:10:23 [debug] 28237#0: *1 http run request: "..."
2013/03/15 00:10:23 [debug] 28237#0: *1 http upstream process non
buffered downstream
2013/03/15 00:10:23 [debug] 28237#0: *1 event timer del: 32:
1363327814331
2013/03/15 00:10:23 [debug] 28237#0: *1 event timer add: 32:
7200000:1363327823956
2013/03/15 00:10:23 [debug] 28237#0: timer delta: 4626
2013/03/15 00:10:23 [debug] 28237#0: posted events 0000000000000000
2013/03/15 00:10:23 [debug] 28237#0: worker cycle
2013/03/15 00:10:23 [debug] 28237#0: epoll timer: 7200000

Is this an nginx bug?

-- 
Rob Mueller
robm at fastmail.fm