400 Bad Request - No required SSL certificate was sent occurs randomly during a valid SSL session

[Jeffrey]

What is wrong?
Subdomains are protected with a client certificate per subdomain. It is possible to access the subdomain when you choose the right client certificate. Randomly during a session (can be after 5min, or after 2 hours) NGINX will return with a "400 Bad Request - No required SSL certificate was sent". I would expect either NGINX to re-request the client certificate or just continue with the previous session.

Configuration
We have 112 SNI based subdomains protected with client certificates like so:

server {
    listen       443 ssl;
    server_name  sub.domain.com;

    ssl_certificate        /etc/nginx/ssl/certs/site.pem;
    ssl_certificate_key    /etc/nginx/ssl/private/site.key;
    ssl_client_certificate /etc/nginx/ssl/certs/clientCA.crt;
    ssl_verify_client      on;

    include     /etc/nginx/props/ssldefault.conf;

    location / {
        include         /etc/nginx/props/proxyall.conf;
        if ( $ssl_client_serial != 61) {return 403;}
        proxy_pass      http://backend;
    }
}

Because we have 112 subdomains we've set the following:

 server_names_hash_max_size  1600;  

Debugging so far
See attached debug log. Either the browser does not get informed it should send a certificate, or NGINX ignore the sent certificate, might be losing the cache

Reproduce
It's hard to reproduce, but the best way so far:

• Use Internet Explorer 11
• Go to an URL using a client certificate
• Use multiple tabs with URLs using client certificates pointing to the same NGINX instance
• Refresh once in a while
• The issue will occur within 1 hour (sometimes within 5 minutes)
• Other tabs mostly follow shortly after.

This bug does occur in other browsers as well, but might take 2 to 8 hours to reproduce.

[Jeffrey]

debug log

[Maxim Dounin]

Note that OpenSSL used (1.0.1e) is rather old and has lots of known bugs, including very obscure ones (see #215 for an example). Please try to reproduce the problem with a recent OpenSSL version (and without any 3rd party modules to make sure they don't interfere). If you'll be able to reproduce the problem, providing the following will be helpful:

• full configuration used to reproduce the problem;
• full debug log of the connection in question without any modifications;
• full dump of the connection obtained with tcpdump/wireshark.

[Jeffrey]

Thanks, I've recompile with OpenSSL 1.0.2d, unfortunately that did not solve the problem. Below you'll find some more info. Im still working on the wireshark and debug logs.

nginx -V

nginx version: nginx/1.9.6
built by gcc 4.8.3 20140911 (Red Hat 4.8.3-9) (GCC)
built with OpenSSL 1.0.2d 9 Jul 2015
TLS SNI support enabled
configure arguments: --prefix=/etc/nginx/ --sbin-path=/usr/sbin/nginx --conf-path=/etc/nginx/nginx.conf --error-log-path=/var/log/nginx/error.log --http-log-path=/var/log/nginx/access.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp 
--user=nobody --group=nobody 
--with-http_ssl_module 
--with-http_gzip_static_module 
--with-http_gunzip_module 
--with-cc-opt='-O2 -g' 
--with-openssl=/usr/src/openssl-1.0.2d/ 
--with-debug

Full config to reproduce (nginx.conf)

worker_processes  4;

events {
    worker_connections  2048;
}

http {
    include                     mime.types;
    default_type                application/octet-stream;

    log_format  main  '$remote_addr for $http_x_real_ip - $remote_user [$time_local] "$request" $scheme:$server_port '
                      '$status $body_bytes_sent "$http_referer" '
                      'Upstream ["$upstream_addr" ($upstream_response_time) $upstream_status : $upstream_cache_status] '
                      '"$http_user_agent" "$http_x_forwarded_for" - $http_http_x_forwarded_for';
    log_format clientcert '$time_local $status | $ssl_server_name | $ssl_client_serial $ssl_client_s_dn $ssl_client_verify $ssl_protocol $ssl_session_reused | $ssl_server_name | $http_user_agent | $request';

    sendfile                    on;
    server_tokens               off;

    server {
        listen       443 ssl;
        server_name  debug.test.com;

        ssl_certificate        /etc/nginx/ssl/certs/wildcard.crt;
        ssl_certificate_key    /etc/nginx/ssl/private/wildcard.key;
        ssl_client_certificate /etc/nginx/ssl/certs/CA.crt;
        ssl_verify_client      on;

        ssl_session_timeout           10m;
        ssl_prefer_server_ciphers     On;
        ssl_protocols                 TLSv1 TLSv1.1 TLSv1.2;
        ssl_ciphers                   "EECDH+AESGCM:EDH+AESGCM:AES256+EECDH:AES256+EDH";
        ssl_session_cache             off;
        ssl_session_tickets           off;

        access_log  /var/log/nginx/debug-access.log main;
        access_log  /var/log/nginx/debug-client.log clientcert;
        error_log   /var/log/nginx/debug-debug.log  debug;

        location / {
                proxy_set_header        Host            $host;
                proxy_pass      http://10.111.130.8:8001;
        }
    }
}

[Jeffrey]

debug log (see 2015/11/11 20:54:32)

[Jeffrey]

dump for client and server

[Maxim Dounin]

Unfortunately, there are no interceptions between "client sent no required SSL certificate" errors in the debug log provided where full connection log is available (and source port is known, so we can identify a connection at network level), and the packet dump provided:

$ egrep 'no required' disk87-2.log | awk '{print $5}' | xargs -I% /bin/sh -c 'grep accept: disk87-2.log | fgrep %'
2015/11/11 20:54:36 [debug] 18821#0: *23460 accept: 62.194.255.216:40983 fd:29
2015/11/11 20:54:36 [debug] 18821#0: *23461 accept: 62.194.255.216:40984 fd:30
2015/11/11 20:54:36 [debug] 18821#0: *23464 accept: 62.194.255.216:40986 fd:31
2015/11/11 20:54:36 [debug] 18821#0: *23465 accept: 62.194.255.216:40987 fd:33
2015/11/11 20:54:37 [debug] 18823#0: *23509 accept: 62.194.255.216:40985 fd:27

$ tshark -r debug-server-205432.pcap  | grep 'Client Hello'
  1   0.000000 62.194.255.216 40867 10.111.130.46 https SSL 276 Client Hello
 32   0.352429 62.194.255.216 40870 10.111.130.46 https SSL 271 Client Hello
 46   0.469971 62.194.255.216 40871 10.111.130.46 https SSL 271 Client Hello
 65   1.151049 62.194.255.216 40872 10.111.130.46 https SSL 271 Client Hello
 90   1.858669 62.194.255.216 40873 10.111.130.46 https SSL 276 Client Hello
 93   1.858703 62.194.255.216 40874 10.111.130.46 https SSL 276 Client Hello
 97   1.863168 62.194.255.216 40875 10.111.130.46 https SSL 276 Client Hello
138   2.108980 62.194.255.216 40876 10.111.130.46 https SSL 276 Client Hello
141   2.110706 62.194.255.216 40877 10.111.130.46 https SSL 276 Client Hello
147   2.113271 62.194.255.216 40878 10.111.130.46 https SSL 276 Client Hello
193   2.422185 62.194.255.216 40880 10.111.130.46 https SSL 279 Client Hello
196   2.422218 62.194.255.216 40879 10.111.130.46 https SSL 279 Client Hello
214   2.460777 62.194.255.216 40881 10.111.130.46 https SSL 271 Client Hello
236   2.563335 62.194.255.216 40882 10.111.130.46 https SSL 271 Client Hello
255   2.662765 62.194.255.216 40885 10.111.130.46 https SSL 276 Client Hello
258   2.662801 62.194.255.216 40884 10.111.130.46 https SSL 276 Client Hello
262   2.666005 62.194.255.216 40883 10.111.130.46 https SSL 276 Client Hello
315   2.943747 62.194.255.216 40886 10.111.130.46 https SSL 279 Client Hello
325   2.953698 62.194.255.216 40887 10.111.130.46 https SSL 276 Client Hello
327   2.953763 62.194.255.216 40889 10.111.130.46 https SSL 276 Client Hello
329   2.953776 62.194.255.216 40888 10.111.130.46 https SSL 276 Client Hello
372   3.254690 62.194.255.216 40890 10.111.130.46 https SSL 271 Client Hello
406   3.910247 62.194.255.216 40906 10.111.130.46 https SSL 244 Client Hello
423   3.965119 62.194.255.216 40907 10.111.130.46 https SSL 276 Client Hello
425   3.965154 62.194.255.216 40909 10.111.130.46 https SSL 276 Client Hello
427   3.965200 62.194.255.216 40908 10.111.130.46 https SSL 276 Client Hello
448   3.999603 62.194.255.216 40910 10.111.130.46 https SSL 244 Client Hello
454   4.001332 62.194.255.216 40911 10.111.130.46 https SSL 244 Client Hello
522   4.256701 62.194.255.216 40912 10.111.130.46 https SSL 276 Client Hello
529   4.266137 62.194.255.216 40914 10.111.130.46 https SSL 276 Client Hello
531   4.266172 62.194.255.216 40913 10.111.130.46 https SSL 276 Client Hello
557   4.563941 62.194.255.216 40916 10.111.130.46 https SSL 271 Client Hello
571   4.685222 62.194.255.216 40917 10.111.130.46 https SSL 271 Client Hello

Note well that dumps from a client aren't really needed. It should be enough to see dumps on the server side.

[Jeffrey]

Maxim, I'm not sure what you mean. I can create a new debug log with a new server side tcpdump. But what did I do wrong and/or what should I do to avoid making that mistake again?

[Maxim Dounin]

The problem is that tcpdump file doesn't contain dumps of any connections with "no required SSL certificate" errors (at least ones we know about from the debug log). To check what goes on here, we need to obtain a dump of a connection with an error. In nginx debug log there should be an error and needed information to identify the connection, and tcpdump should contain connection data. Obtaining debug log and tcpdump at the same time for a reasonably long period of time to see several errors should be enough.

[Maxim Dounin]

Feedback timeout. No information provided to conclude the problem is on nginx (or even OpenSSL) side. From the logs it looks like the browser in fact didn't sent a certificate for some unknown reason.

[radko.dinev@…]

We have got exactly the same problem in our company which made us disable client certificate verification due to random 400 responses.

[Maxim Dounin]

See above, to further debug this we need nginx debug log with an error and tcpdump of the corresponding connection. This should make it clear if the problem is on nginx side or on browser side.

[Maxim Dounin]

See also #1019.