Intermittant SSL Problems

Server NGINX
1

Hi folks,

We are using Nginx for SSL termination, and then it proxies to an ATS or
Haproxy server depending on our environment.

We’re running into a problem where every now and then, Nginx closes a
connection due to a timeout. When investigating, it looks like the
connections that are being timed-out are not being forwarded to the
backend
service. The scenario when we were able to best reproduce this is one
where one of our Java client was running about 100 REST requests that
were
fairly similar. I’ve attached files that contain both the tcpdump from
the
client side as well as the debug log on the nginx side.

I tried comparing a successful and unsuccessful request next to each
other. From the client side, it looks like the messages back and forth
look very consistent. On the nginx side, the first difference seems to
happen when reading in the Http Request. The requests that fail, all
seem
to do a partial read:

==SNIPPET FROM FAILING REQUEST==

2013/11/20 01:58:05 [debug] 52611#0: *621 http wait request handler
2013/11/20 01:58:05 [debug] 52611#0: *621 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 335
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: 1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_read: -1
2013/11/20 01:58:05 [debug] 52611#0: *621 SSL_get_error: 2
2013/11/20 01:58:05 [debug] 52611#0: *621 reusable connection: 0
2013/11/20 01:58:05 [debug] 52611#0: *621 posix_memalign:
0000000000EFB600:4096 @16
2013/11/20 01:58:05 [debug] 52611#0: *621 http process request line

==SNIPPET FROM SUCCEEDING REQUEST==
2013/11/20 01:58:04 [debug] 52611#0: *619 http wait request handler
2013/11/20 01:58:04 [debug] 52611#0: *619 malloc: 0000000000F1BE20:1024
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 335
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 167
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: 1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_read: -1
2013/11/20 01:58:04 [debug] 52611#0: *619 SSL_get_error: 2
2013/11/20 01:58:04 [debug] 52611#0: *619 reusable connection: 0
2013/11/20 01:58:04 [debug] 52611#0: *619 posix_memalign:
0000000000EFB600:4096 @16
2013/11/20 01:58:04 [debug] 52611#0: *619 http process request line

This difference seems to be consistent with errors. Later on, the
request
that ends up failing attempts to load the request body, but only gets
about
16 bytes, and looks like it keeps waiting for the rest of the data.
However, looking at a tcpdump from the client, it looks like all the
data
is sent up and ack-ed. Then the client sees nothing for a minute until
the
connection is closed by the server.

==TCP DUMP FROM FAILING REQUEST==
…
17:58:05.259451 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack
2996,
win 8023, options [nop,nop,TS val 145724966 ecr 155421032], length 0
17:58:05.261592 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
221:296, ack 2996, win 8192, options [nop,nop,TS val 145724968 ecr
155421032], length 75
17:58:05.262989 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
296:302, ack 2996, win 8192, options [nop,nop,TS val 145724969 ecr
155421032], length 6
17:58:05.263196 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
302:355, ack 2996, win 8192, options [nop,nop,TS val 145724969 ecr
155421032], length 53
17:58:05.295347 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack
355,
win 122, options [nop,nop,TS val 155421041 ecr 145724968], length 0
17:58:05.295387 IP y.y.y.209.https > x.x.x.145.53167: Flags [P.], seq
2996:3055, ack 355, win 122, options [nop,nop,TS val 155421042 ecr
145724968], length 59
17:58:05.295481 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack
3055,
win 8188, options [nop,nop,TS val 145725000 ecr 155421042], length 0
17:58:05.300058 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
355:728, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 373
17:58:05.300253 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
728:765, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300254 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
765:962, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 197
17:58:05.300282 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
962:999, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300307 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
999:1036, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300342 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
1036:1073, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.300365 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
1073:1110, ack 3055, win 8192, options [nop,nop,TS val 145725004 ecr
155421042], length 37
17:58:05.332040 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack
765,
win 130, options [nop,nop,TS val 155421051 ecr 145725004], length 0
17:58:05.332247 IP y.y.y.209.https > x.x.x.145.53167: Flags [.], ack
1110,
win 139, options [nop,nop,TS val 155421051 ecr 145725004], length 0
17:59:05.338429 IP y.y.y.209.https > x.x.x.145.53167: Flags [F.], seq
3055, ack 1110, win 139, options [nop,nop,TS val 155436119 ecr
145725004],
length 0
17:59:05.338581 IP x.x.x.145.53167 > y.y.y.209.https: Flags [.], ack
3056,
win 8192, options [nop,nop,TS val 145784751 ecr 155436119], length 0
17:59:05.338932 IP x.x.x.145.53167 > y.y.y.209.https: Flags [P.], seq
1110:1147, ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr
155436119], length 37
17:59:05.338933 IP x.x.x.145.53167 > y.y.y.209.https: Flags [F.], seq
1147,
ack 3056, win 8192, options [nop,nop,TS val 145784751 ecr 155436119],
length 0
17:59:05.370400 IP y.y.y.209.https > x.x.x.145.53167: Flags [R], seq
325468762, win 0, length 0

==TCP DUMP FROM SUCCESSFUL REQUEST==
…
17:58:04.481722 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack
2996,
win 8023, options [nop,nop,TS val 145724196 ecr 155420837], length 0
17:58:04.484108 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
221:296, ack 2996, win 8192, options [nop,nop,TS val 145724198 ecr
155420837], length 75
17:58:04.485569 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
296:302, ack 2996, win 8192, options [nop,nop,TS val 145724199 ecr
155420837], length 6
17:58:04.485767 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
302:355, ack 2996, win 8192, options [nop,nop,TS val 145724199 ecr
155420837], length 53
17:58:04.531685 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack
355,
win 122, options [nop,nop,TS val 155420850 ecr 145724198], length 0
17:58:04.531689 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq
2996:3055, ack 355, win 122, options [nop,nop,TS val 155420850 ecr
145724198], length 59
17:58:04.531827 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack
3055,
win 8188, options [nop,nop,TS val 145724244 ecr 155420850], length 0
17:58:04.532709 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
355:728, ack 3055, win 8192, options [nop,nop,TS val 145724244 ecr
155420850], length 373
17:58:04.532906 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
728:765, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.532954 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
765:962, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 197
17:58:04.532983 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
962:999, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.533012 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
999:1036, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.533045 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
1036:1073, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.533143 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
1073:1110, ack 3055, win 8192, options [nop,nop,TS val 145724245 ecr
155420850], length 37
17:58:04.565176 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack
962,
win 139, options [nop,nop,TS val 155420858 ecr 145724244], length 0
17:58:04.565184 IP y.y.y.209.https > x.x.x.145.53166: Flags [.], ack
1110,
win 139, options [nop,nop,TS val 155420858 ecr 145724245], length 0
17:58:05.184331 IP y.y.y.209.https > x.x.x.145.53166: Flags [P.], seq
3055:3540, ack 1110, win 139, options [nop,nop,TS val 155421011 ecr
145724245], length 485
17:58:05.184442 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack
3540,
win 8161, options [nop,nop,TS val 145724894 ecr 155421011], length 0
17:58:05.184592 IP y.y.y.209.https > x.x.x.145.53166: Flags [F.], seq
3540,
ack 1110, win 139, options [nop,nop,TS val 155421011 ecr 145724245],
length
0
17:58:05.184658 IP x.x.x.145.53166 > y.y.y.209.https: Flags [.], ack
3541,
win 8192, options [nop,nop,TS val 145724894 ecr 155421011], length 0
17:58:05.184863 IP x.x.x.145.53166 > y.y.y.209.https: Flags [P.], seq
1110:1147, ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr
155421011], length 37
17:58:05.184863 IP x.x.x.145.53166 > y.y.y.209.https: Flags [F.], seq
1147,
ack 3541, win 8192, options [nop,nop,TS val 145724894 ecr 155421011],
length 0

When I look at the TCP dumps, it looks like the client sends up all the
data, and it looks like the server receives and acks it. At this point,
I’m sorta stuck. Does anyone have any insight here? Is there a know
bug
that has been fixed that we may be missing? I’ve attached files that
have
more complete dumps of the requests.

We are running Ubuntu 12.04.3 LTS, with:
nginx version: nginx/1.4.1
openssl version: OpenSSL 1.0.1 14 Mar 2012

Thanks,
--Will
2

Hello!

On Wed, Nov 20, 2013 at 06:03:11PM -0800, Will Pugh wrote:

fairly similar. I’ve attached files that contain both the tcpdump from the
client side as well as the debug log on the nginx side.

I tried comparing a successful and unsuccessful request next to each
other. From the client side, it looks like the messages back and forth
look very consistent. On the nginx side, the first difference seems to
happen when reading in the Http Request. The requests that fail, all seem
to do a partial read:

[…]

I think I see what happens here:

  • Due to a partial read the c->read->ready flag is reset.

  • While processing request headers rest of the body becomes available in
    a
    socket buffer.

  • The ngx_http_do_read_client_request_body() function calls c->recv(),
    ngx_ssl_recv() in case of SSL, and rest of the data is read from the
    kernel to OpenSSL buffers. The c->recv() is called with a limited
    buffer space though (in the debug log provided, only 16 bytes - as
    this
    happens during reading http chunk header), and only part of the data
    becomes available to nginx.

  • As c->read->ready isn’t set, ngx_http_do_read_client_request_body()
    arms
    a read event and returns to the event loop.

  • The socket buffer is empty, so no further events are reported by
    the kernel till timeout.

Please try the following patch:

— a/src/event/ngx_event_openssl.c
+++ b/src/event/ngx_event_openssl.c
@@ -1025,6 +1025,7 @@ ngx_ssl_recv(ngx_connection_t *c, u_char
size -= n;

         if (size == 0) {

  •            c->read->ready = 1;
           return bytes;
       }

@@ -1034,6 +1035,10 @@ ngx_ssl_recv(ngx_connection_t *c, u_char
}

     if (bytes) {

  •        if (c->ssl->last != NGX_AGAIN) {

  •            c->read->ready = 1;

  •        }

  •        return bytes;
   }

–
Maxim D.
http://nginx.org/en/donation.html

3

Cool. Thanks!

Initial testing looks like this fixed it.

–Will