CPU 100% Upstream SSL handshake

[Maxim Dounin]

Hello!

On Wed, Jan 30, 2013 at 03:50:39AM +0000, 彭谦(研六 福州) wrote:

> Hello all!
>    Recently I came across a problem that CPU 100% when nginx upstream were trying to SSL handshake to the web sever.
>    the pass_proxy url is https://www.salesforce.com/export/login-messages/common/css/images/login/bk_promo_overlay3.png;
>    maybe the slow https web site has the same problem.
> 
> The debug log:
> 2013/01/30 11:06:23 [debug] 19604#0: posted event 100232FC
> 2013/01/30 11:06:23 [debug] 19604#0: *1 delete posted event 100232FC
> 2013/01/30 11:06:23 [debug] 19604#0: *1 SSL handshake handler: 1
> 2013/01/30 11:06:23 [debug] 19604#0: *1 SSL_do_handshake: -1
> 2013/01/30 11:06:23 [debug] 19604#0: *1 SSL_get_error: 2
> 2013/01/30 11:06:23 [debug] 19604#0: posted event 00000000
> 2013/01/30 11:06:23 [debug] 19604#0: worker cycle
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:6 wr:0
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:3 wr:0
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:7 wr:0
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:7 wr:1
> 2013/01/30 11:06:23 [debug] 19604#0: max_fd: 7
> 2013/01/30 11:06:23 [debug] 19604#0: select timer: 46801
> 2013/01/30 11:06:23 [debug] 19604#0: select ready 1
> 2013/01/30 11:06:23 [debug] 19604#0: select write 7
> 2013/01/30 11:06:23 [debug] 19604#0: *1 post event 100232FC
> 2013/01/30 11:06:23 [debug] 19604#0: timer delta: 0
> 2013/01/30 11:06:23 [debug] 19604#0: posted events 100232FC
> 2013/01/30 11:06:23 [debug] 19604#0: posted event 100232FC
> 2013/01/30 11:06:23 [debug] 19604#0: *1 delete posted event 100232FC
> 2013/01/30 11:06:23 [debug] 19604#0: *1 SSL handshake handler: 1
> 2013/01/30 11:06:23 [debug] 19604#0: *1 SSL_do_handshake: -1
> 2013/01/30 11:06:23 [debug] 19604#0: *1 SSL_get_error: 2
> 2013/01/30 11:06:23 [debug] 19604#0: posted event 00000000
> 2013/01/30 11:06:23 [debug] 19604#0: worker cycle
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:6 wr:0
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:3 wr:0
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:7 wr:0
> 2013/01/30 11:06:23 [debug] 19604#0: select event: fd:7 wr:1
> 2013/01/30 11:06:23 [debug] 19604#0: max_fd: 7
> 
> we can see the write handler will repeat again and again until the SSL_do_handshake return 1.
> i just repear the problem in select I/O multiplexing.
> Can you help me to fix this bug?

Thank you for your report, it looks like generic problem in ssl handshake
handling with level-triggered event methods.

The following patch should fix the problem:

diff --git a/src/event/ngx_event_openssl.c b/src/event/ngx_event_openssl.c
--- a/src/event/ngx_event_openssl.c
+++ b/src/event/ngx_event_openssl.c
@@ -808,6 +808,10 @@ ngx_ssl_handshake(ngx_connection_t *c)
             return NGX_ERROR;
         }
 
+        if (ngx_handle_write_event(c->write, 0) != NGX_OK) {
+            return NGX_ERROR;
+        }
+
         return NGX_AGAIN;
     }
 
@@ -816,6 +820,10 @@ ngx_ssl_handshake(ngx_connection_t *c)
         c->read->handler = ngx_ssl_handshake_handler;
         c->write->handler = ngx_ssl_handshake_handler;
 
+        if (ngx_handle_read_event(c->read, 0) != NGX_OK) {
+            return NGX_ERROR;
+        }
+
         if (ngx_handle_write_event(c->write, 0) != NGX_OK) {
             return NGX_ERROR;
         }



-- 
Maxim Dounin
http://nginx.com/support.html