# Intermittant SSL Problems **URL:** \ **Category:** NGINX\ **Created:** [November 21, 2013, 3:03am UTC](https://www.ruby-forum.com/t/intermittant-ssl-problems/237611 "2013-11-21T03:03:48Z")\ **Posts on this page:** 3\ **Page:** 1
**Author:** ![Detlef\_R](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/d/58f4c7/32.png) [@Detlef\_R](https://www.ruby-forum.com/u/Detlef_R)\ **Post date:** [November 21, 2013, 3:03am UTC](https://www.ruby-forum.com/t/intermittant-ssl-problems/237611/1 "2013-11-21T03:03:48Z")
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 ``` ---
**Author:** ![Will\_Pugh](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/e99b99/32.png) [@Will\_Pugh](https://www.ruby-forum.com/u/Will_Pugh)\ **Post date:** [November 21, 2013, 12:35pm UTC](https://www.ruby-forum.com/t/intermittant-ssl-problems/237611/2 "2013-11-21T12:35:47Z")
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](http://nginx.org/en/donation.html) ---
**Author:** ![Will\_Pugh](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/w/e99b99/32.png) [@Will\_Pugh](https://www.ruby-forum.com/u/Will_Pugh)\ **Post date:** [November 22, 2013, 12:50am UTC](https://www.ruby-forum.com/t/intermittant-ssl-problems/237611/3 "2013-11-22T00:50:47Z")
Cool. Thanks! Initial testing looks like this fixed it. –Will