Getting SSL_do_handshake error (version too low) despite all the effort

akalantari · March 29, 2018, 9:22am

Yesterday we installed a letsencrypt SSL certificate on our server which hosts a very busy website.

After a few hours we noticed that some of our users are getting errors from nginx:

2018/03/28 13:06:03 [crit] 9937#9937: *604177779 SSL_do_handshake() failed (SSL: error:1417D18C:SSL routines:tls_process_client_hello:version too low) while SSL handshaking, client: ******, server: 0.0.0.0:443
2018/03/28 13:06:46 [crit] 9949#9949: *604179134 SSL_do_handshake() failed (SSL: error:1417D18C:SSL routines:tls_process_client_hello:version too low) while SSL handshaking, client: *******, server: 0.0.0.0:443
2018/03/28 13:10:33 [crit] 9942#9942: *604185439 SSL_do_handshake() failed (SSL: error:1417D18C:SSL routines:tls_process_client_hello:version too low) while SSL handshaking, client: *******, server: 0.0.0.0:443

Judging from the IP addresses, they are probably using their mobile phone for browsing but I have no idea about their browsers. I’ve changed the nginx error logging to debug mode and here is some parts of the output:

Date: Wed, 28 Mar 2018 13:37:19 GMT^M
Content-Type: text/html; charset=UTF-8^M
Transfer-Encoding: chunked^M
Connection: keep-alive^M
Set-Cookie: PHPSESSID=**; path=/^M
Expires: Thu, 19 Nov 1981 08:52:00 GMT^M
Cache-Control: no-store, no-cache, must-revalidate^M
Pragma: no-cache^M
Location: *******************************
X-Cache: MISS^M

2018/03/28 18:07:19 [debug] 24356#24356: *604585753 write new buf t:1 f:0 00007F06A5884708, pos 00007F06A5884708, size: 601 file: 0, size: 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http write filter: l:0 f:0 s:601
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http script var: "0"
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http file cache set header
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http cacheable: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http upstream process upstream
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe read upstream: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe preread: 23
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 readv: 1, last:261440
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe recv chain: 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe buf free s:0 t:1 f:0 00007F06A56D0B50, pos 00007F06A56D0DF9, size: 23 file: 0, size: 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe length: -1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 01
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 03
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 00
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 01
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 00
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 08
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 00
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record byte: 00
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi record length: 8
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http fastcgi sent end request
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe write chain
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 add cleanup: 00007F06A5884B20
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 hashed path: /var/lib/nginx/fastcgi/7/54/0423471547
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 temp fd:129
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 write: 129, 00007F06A56D0B50, 681, 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe write downstream: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 pipe write downstream done
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 event timer: 80, old: 1522244549474, new: 1522244549680
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http file cache update
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http file cache rename: "/var/lib/nginx/fastcgi/7/54/0423471547" to "/run/shm/nginx/f/d9/b295394f65a2a43ae0ec0adadd243d9f"
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 malloc: 00007F06A5677B30:64
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 malloc: 00007F06A588F5E0:681
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http upstream exit: 0000000000000000
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 finalize http upstream request: 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 finalize http fastcgi request
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free rr peer 1 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 close http upstream connection: 80
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A55C40A0, unused: 48
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 event timer del: 80: 1522244549474
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 reusable connection: 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http upstream temp fd: 129
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http output filter "/index.php?p=1187697"
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http copy filter: "/index.php?p=1187697"
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 SSL_do_handshake: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http postpone filter "/index.php?p=1187697" 00007FFD85DA3BF0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http chunk: 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 SSL: TLSv1.1, cipher: "ECDHE-RSA-AES128-SHA TLSv1 Kx=ECDH Au=RSA Enc=AES(128) Mac=SHA1"
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 write old buf t:1 f:0 00007F06A5884708, pos 00007F06A5884708, size: 601 file: 0, size: 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 reusable connection: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 write new buf t:0 f:0 0000000000000000, pos 00007F06A3953C9B, size: 5 file: 0, size: 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 http wait request handler
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http write filter: l:1 f:0 s:606
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 malloc: 00007F06A5668370:1024
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http write filter limit 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 SSL_read: -1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 malloc: 00007F06A5722010:16384
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 SSL_get_error: 2
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 SSL buf copy: 601
2018/03/28 18:07:19 [debug] 24364#24364: *604587625 free: 00007F06A5668370
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 SSL buf copy: 5
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 SSL handshake handler: 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 SSL to write: 606
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 SSL_write: 606
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http write filter 0000000000000000
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http copy filter: 0 "/index.php?p=1187697"
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http finalize request: 0, "/index.php?p=1187697" a:1, c:1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 set http keepalive handler
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http close request
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 http log handler
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 posix_memalign: 00007F06A56C79D0:4096 @16
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 run cleanup: 00007F06A5884B20
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 file cleanup: fd:129
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 run cleanup: 00007F06A579A998
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 run cleanup: 00007F06A579A098
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 close cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 expire cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 expire cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 run cleanup: 00007F06A5799E90
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 close cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 expire cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 expire cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 close cached open file: *******************************
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A56D0B50
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A5846DC0, unused: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A57999C0, unused: 2
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A5883DB0, unused: 61
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A56C79D0, unused: 3689
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A571F240
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 hc free: 0000000000000000 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 hc busy: 0000000000000000 0
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 free: 00007F06A5722010
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 reusable connection: 1
2018/03/28 18:07:19 [debug] 24356#24356: *604585753 event timer add: 36: 310000:1522244549680
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 SSL_do_handshake: 1
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 SSL: TLSv1.1, cipher: "ECDHE-RSA-AES128-SHA TLSv1 Kx=ECDH Au=RSA Enc=AES(128) Mac=SHA1"
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 reusable connection: 1
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 http wait request handler
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 malloc: 00007F06A5668480:1024
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 SSL_read: -1
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 SSL_get_error: 2
2018/03/28 18:07:19 [debug] 24364#24364: *604587624 free: 00007F06A5668480
2018/03/28 18:07:19 [debug] 24360#24360: post event 00007F069F820070
2018/03/28 18:07:19 [debug] 24360#24360: delete posted event 00007F069F820070
2018/03/28 18:07:19 [debug] 24360#24360: accept on 0.0.0.0:443, ready: 1
2018/03/28 18:07:19 [debug] 24360#24360: posix_memalign: 00007F06A5621B50:512 @16
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 accept: ******:10738 fd:53
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 event timer add: 53: 10000:1522244249682
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 reusable connection: 1
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 epoll add event: fd:53 op:1 ev:80002001
2018/03/28 18:07:19 [debug] 24360#24360: accept() not ready (11: Resource temporarily unavailable)
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 post event 00007F069F820A90
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 delete posted event 00007F069F820A90
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 http check ssl handshake
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 http recv(): 1
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 https ssl handshake: 0x16
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 SSL_do_handshake: -1
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 SSL_get_error: 1
2018/03/28 18:07:19 [crit] 24360#24360: *604587635 SSL_do_handshake() failed (SSL: error:1417D18C:SSL routines:tls_process_client_hello:version too low) while SSL handshaking, client: *****, server: 0.0.0.0:443
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 close http connection: 53
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 event timer del: 53: 1522244249682
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 reusable connection: 0
2018/03/28 18:07:19 [debug] 24360#24360: *604587635 free: 00007F06A5621B50, unused: 152
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 SSL handshake handler: 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 SSL_do_handshake: 1
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 SSL: TLSv1.1, cipher: "ECDHE-RSA-AES128-SHA TLSv1 Kx=ECDH Au=RSA Enc=AES(128) Mac=SHA1"
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 reusable connection: 1
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 http wait request handler
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 malloc: 00007F06A56A0050:1024
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 SSL_read: -1
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 SSL_get_error: 2
2018/03/28 18:07:19 [debug] 24364#24364: *604587627 free: 00007F06A56A0050
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL handshake handler: 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL_do_handshake: 1
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL: TLSv1.1, cipher: "ECDHE-RSA-AES128-SHA TLSv1 Kx=ECDH Au=RSA Enc=AES(128) Mac=SHA1"
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 reusable connection: 1
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 http wait request handler
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 malloc: 00007F06A56A0130:1024
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL_read: -1
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL_get_error: 2
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 free: 00007F06A56A0130
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http wait request handler
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 malloc: 00007F06A56A0130:1024
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL_read: -1
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 SSL_get_error: 2
2018/03/28 18:07:19 [debug] 24364#24364: *604587626 free: 00007F06A56A0130
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http wait request handler
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 malloc: 00007F06A56A0130:1024
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 SSL_read: 823
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 SSL_read: -1
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 SSL_get_error: 2
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 reusable connection: 0
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 posix_memalign: 00007F06A568CAC0:4096 @16
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http process request line
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http request line: "GET /?p=1246163 HTTP/1.1"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http uri: "/"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http args: "p=1246163"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http exten: ""
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 posix_memalign: 00007F06A5677680:4096 @16
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http process request header line
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http header: "Host: *"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http header: "Connection: keep-alive"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http header: "Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http header: "User-Agent: Mozilla/5.0 (Linux; Android 4.2.2; C2305 Build/16.0.B.2.16) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/28.0.1500.94 Mobile Safari/537.36"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http header: "Accept-Encoding: gzip,deflate,sdch"
2018/03/28 18:07:19 [debug] 24364#24364: *604587623 http header: "Accept-Language: fa,en-US;q=0.8,en;q=0.6"

This is an old android mobile browser or a webview of an old android phone.

I wanted to be sure that what the problem is, so I test added support for TLSv1 & SSLv2 & SSLv3 so I added this to my nginx config file:

ssl_protocols SSLv2 SSLv3 TLSv1 TLSv1.1 TLSv1.2;
ssl_prefer_server_ciphers on;

and I also added RSA as ssl_ciphers, but I still got the same amount of errors. So it shouldn’t be about SSL version or ciphers.

So what is the problem?

_az · March 29, 2018, 11:12am

Could the protocols have been disabled at compilation time in the version of OpenSSL on your server? For example, SSLv2 was disabled in Debian’s openssl package a long time ago. If it was, nginx may just silently upgrade you to the available protocols.

ldd $(which nginx)

Can you successfully connect to your own server using SSLv3 (you may need to use an ancient statically compiled version of openssl):

openssl s_client -ssl3 -connect localhost:443

What does SSL Labs report for what protocols are working?

mnordhoff · March 29, 2018, 7:56pm

If you did successfully enable SSL 2, you need to revoke your certificate, disable SSL 2, and issue a new certificate.

https://drownattack.com/

SSL 3 is also insecure, but doesn’t risk compromising the certificate.

system · April 28, 2018, 7:57pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.