NGINX says "client sent no required SSL certificate while reading client request headers" how do we troubleshoot?

ssl curl nginx client-certificates mutual-authentication
Daniel Kaplan picture Daniel Kaplan · Dec 20, 2016 · Viewed 8.1k times · Source

We've configured NGINX to use mutual authentication. When a client makes a request to us, we get an info line in the NGINX log saying, "client sent no required SSL certificate while reading client request headers". We believe that the client actually is sending a certificate.

The evidence is that we saw the curl command the client used and it was sending a cert. We correlated their call to this log message. Also, we have an F5 proxy that is configured to use mutual auth and their same curl command is accepted if they change it to hit the F5. This call would be rejected if they were not sending a client cert. In the F5 logs we see that F5 is receiving a client cert. The client is not changing its behavior, we are changing the DNS to point between F5 and NGINX.

When I google for "client sent no required SSL certificate while reading client request headers" I can't find any official NGINX documentation about this message. How can I troubleshoot this better? Right now we're starting nginx with nginx-debug but the debug output doesn't seem to clearly explain why we're seeing this problem. Here are some of these logs:

2016/12/19 23:27:59 [debug] 179#179: epoll: fd:6 ev:0001 d:0000000000C7AEB0
2016/12/19 23:27:59 [debug] 179#179: accept on 0.0.0.0:443, ready: 0
2016/12/19 23:27:59 [debug] 179#179: posix_memalign: 0000000000B8D530:512 @16
2016/12/19 23:27:59 [debug] 179#179: *4539 accept: 172.20.72.125:23211 fd:3
2016/12/19 23:27:59 [debug] 179#179: *4539 event timer add: 3: 60000:1482190139859
2016/12/19 23:27:59 [debug] 179#179: *4539 reusable connection: 1
2016/12/19 23:27:59 [debug] 179#179: *4539 epoll add event: fd:3 op:1 ev:80002001
2016/12/19 23:27:59 [debug] 179#179: timer delta: 873
2016/12/19 23:27:59 [debug] 179#179: worker cycle
2016/12/19 23:27:59 [debug] 179#179: epoll timer: 60000
2016/12/19 23:27:59 [debug] 179#179: epoll: fd:3 ev:0001 d:0000000000C7B360
2016/12/19 23:27:59 [debug] 179#179: *4539 http check ssl handshake
2016/12/19 23:27:59 [debug] 179#179: *4539 http recv(): 1
2016/12/19 23:27:59 [debug] 179#179: *4539 https ssl handshake: 0x16
2016/12/19 23:27:59 [debug] 181#181: accept on 0.0.0.0:443, ready: 0
2016/12/19 23:27:59 [debug] 181#181: accept() not ready (11: Resource temporarily unavailable)
2016/12/19 23:27:59 [debug] 179#179: *4539 ssl get session: DB2C8809:32
2016/12/19 23:27:59 [debug] 179#179: shmtx lock
2016/12/19 23:27:59 [debug] 179#179: shmtx unlock
2016/12/19 23:27:59 [debug] 181#181: timer delta: 873
2016/12/19 23:27:59 [debug] 181#181: worker cycle
2016/12/19 23:27:59 [debug] 181#181: epoll timer: -1
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_do_handshake: -1
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_get_error: 2
2016/12/19 23:27:59 [debug] 179#179: *4539 reusable connection: 0
2016/12/19 23:27:59 [debug] 179#179: timer delta: 0
2016/12/19 23:27:59 [debug] 179#179: worker cycle
2016/12/19 23:27:59 [debug] 179#179: epoll timer: 60000
2016/12/19 23:27:59 [debug] 179#179: epoll: fd:3 ev:0001 d:0000000000C7B360
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL handshake handler: 0
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_do_handshake: -1
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_get_error: 2
2016/12/19 23:27:59 [debug] 179#179: timer delta: 29
2016/12/19 23:27:59 [debug] 179#179: worker cycle
2016/12/19 23:27:59 [debug] 179#179: epoll timer: 59971
2016/12/19 23:27:59 [debug] 179#179: epoll: fd:3 ev:0001 d:0000000000C7B360
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL handshake handler: 0
2016/12/19 23:27:59 [debug] 179#179: shmtx lock
2016/12/19 23:27:59 [debug] 179#179: slab alloc: 136 slot: 5
2016/12/19 23:27:59 [debug] 179#179: slab alloc: 00007FF33D86B000
2016/12/19 23:27:59 [debug] 179#179: slab alloc: 128 slot: 4
2016/12/19 23:27:59 [debug] 179#179: slab alloc: 00007FF33D869080
2016/12/19 23:27:59 [debug] 179#179: *4539 ssl new session: B0945ECD:32:136
2016/12/19 23:27:59 [debug] 179#179: shmtx unlock
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_do_handshake: 1
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL: TLSv1.1, cipher: "ECDHE-RSA-AES256-SHA SSLv3 Kx=ECDH Au=RSA Enc=AES(256) Mac=SHA1"
2016/12/19 23:27:59 [debug] 179#179: *4539 reusable connection: 1
2016/12/19 23:27:59 [debug] 179#179: *4539 http wait request handler
2016/12/19 23:27:59 [debug] 179#179: *4539 malloc: 0000000000B89230:1024
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_read: -1
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_get_error: 2
2016/12/19 23:27:59 [debug] 179#179: *4539 free: 0000000000B89230
2016/12/19 23:27:59 [debug] 179#179: timer delta: 3
2016/12/19 23:27:59 [debug] 179#179: worker cycle
2016/12/19 23:27:59 [debug] 179#179: epoll timer: 59968
2016/12/19 23:27:59 [debug] 179#179: epoll: fd:3 ev:0001 d:0000000000C7B360
2016/12/19 23:27:59 [debug] 179#179: *4539 http wait request handler
2016/12/19 23:27:59 [debug] 179#179: *4539 malloc: 0000000000B89230:1024
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_read: 172
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_read: -1
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_get_error: 2
2016/12/19 23:27:59 [debug] 179#179: *4539 reusable connection: 0
2016/12/19 23:27:59 [debug] 179#179: *4539 posix_memalign: 0000000000C71800:4096 @16
2016/12/19 23:27:59 [debug] 179#179: *4539 http process request line
2016/12/19 23:27:59 [debug] 179#179: *4539 http request line: "GET /myapp-myapi/v2/id12345/endpoint HTTP/1.1"
2016/12/19 23:27:59 [debug] 179#179: *4539 http uri: "/myapp-myapi/v2/id12345/endpoint"
2016/12/19 23:27:59 [debug] 179#179: *4539 http args: ""
2016/12/19 23:27:59 [debug] 179#179: *4539 http exten: ""
2016/12/19 23:27:59 [debug] 179#179: *4539 http process request header line
2016/12/19 23:27:59 [debug] 179#179: *4539 http header: "a-request-header: client-qa"
2016/12/19 23:27:59 [debug] 179#179: *4539 posix_memalign: 0000000000B9C640:4096 @16
2016/12/19 23:27:59 [debug] 179#179: *4539 http header: "User-Agent: Jakarta Commons-HttpClient/3.1"
2016/12/19 23:27:59 [debug] 179#179: *4539 http header: "Host: pre.myapp.com"
2016/12/19 23:27:59 [debug] 179#179: *4539 http header done
2016/12/19 23:27:59 [info] 179#179: *4539 client sent no required SSL certificate while reading client request headers, client: 172.20.72.125, server: pre.myapp.com, request: "GET /myapp-myapi/v2/id12345/endpoint HTTP/1.1", host: "pre.myapp.com"
2016/12/19 23:27:59 [debug] 179#179: ssl remove session: B0945ECD:32
2016/12/19 23:27:59 [debug] 179#179: shmtx lock
2016/12/19 23:27:59 [debug] 179#179: slab free: 00007FF33D86B000
2016/12/19 23:27:59 [debug] 179#179: slab free: 00007FF33D869080
2016/12/19 23:27:59 [debug] 179#179: shmtx unlock
2016/12/19 23:27:59 [debug] 179#179: *4539 http finalize request: 496, "/myapp-myapi/v2/id12345/endpoint?" a:1, c:1
2016/12/19 23:27:59 [debug] 179#179: *4539 event timer del: 3: 1482190139859
2016/12/19 23:27:59 [debug] 179#179: *4539 http special response: 496, "/myapp-myapi/v2/id12345/endpoint?"
2016/12/19 23:27:59 [debug] 179#179: *4539 http set discard body
2016/12/19 23:27:59 [debug] 179#179: *4539 HTTP/1.1 400 Bad Request
Server: nginx/1.11.4
Date: Mon, 19 Dec 2016 23:27:59 GMT
Content-Type: text/html
Content-Length: 253
Connection: close

2016/12/19 23:27:59 [debug] 179#179: *4539 write new buf t:1 f:0 0000000000B9C6C0, pos 0000000000B9C6C0, size: 152 file: 0, size: 0
2016/12/19 23:27:59 [debug] 179#179: *4539 http write filter: l:0 f:0 s:152
2016/12/19 23:27:59 [debug] 179#179: *4539 http output filter "/myapp-myapi/v2/id12345/endpoint?"
2016/12/19 23:27:59 [debug] 179#179: *4539 http copy filter: "/myapp-myapi/v2/id12345/endpoint?"
2016/12/19 23:27:59 [debug] 179#179: *4539 http postpone filter "/myapp-myapi/v2/id12345/endpoint?" 0000000000B9C8A0
2016/12/19 23:27:59 [debug] 179#179: *4539 write old buf t:1 f:0 0000000000B9C6C0, pos 0000000000B9C6C0, size: 152 file: 0, size: 0
2016/12/19 23:27:59 [debug] 179#179: *4539 write new buf t:0 f:0 0000000000000000, pos 0000000000711B80, size: 200 file: 0, size: 0
2016/12/19 23:27:59 [debug] 179#179: *4539 write new buf t:0 f:0 0000000000000000, pos 0000000000712DE0, size: 53 file: 0, size: 0
2016/12/19 23:27:59 [debug] 179#179: *4539 http write filter: l:1 f:0 s:405
2016/12/19 23:27:59 [debug] 179#179: *4539 http write filter limit 0
2016/12/19 23:27:59 [debug] 179#179: *4539 posix_memalign: 0000000000BF6100:512 @16
2016/12/19 23:27:59 [debug] 179#179: *4539 malloc: 0000000000C01FE0:16384
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL buf copy: 152
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL buf copy: 200
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL buf copy: 53
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL to write: 405
2016/12/19 23:27:59 [debug] 179#179: *4539 SSL_write: 405
2016/12/19 23:27:59 [debug] 179#179: *4539 http write filter 0000000000000000
2016/12/19 23:27:59 [debug] 179#179: *4539 http copy filter: 0 "/myapp-myapi/v2/id12345/endpoint?"
2016/12/19 23:27:59 [debug] 179#179: *4539 http finalize request: 0, "/myapp-myapi/v2/id12345/endpoint?" a:1, c:1
2016/12/19 23:27:59 [debug] 179#179: *4539 http request count:1 blk:0
2016/12/19 23:27:59 [debug] 179#179: *4539 http close request
2016/12/19 23:27:59 [debug] 179#179: *4539 http log handler
172.20.72.125 - - [19/Dec/2016:23:27:59 +0000] https "GET /myapp-myapi/v2/id12345/endpoint HTTP/1.1" 400 253 "-" "Jakarta Commons-HttpClient/3.1" "-" "-" "NONE" "" "client-qa"

This is our nginx.conf file:

#daemon off;
user  nginx;
worker_processes  4;

error_log  /var/log/nginx/error.log debug;
pid        /var/run/nginx.pid;

events {
    worker_connections  1024;
    use epoll;
}

http {
    index  index.php index.htm index.html;
    include  /etc/nginx/mime.types;

    upstream backend-myapi {
      server myapp-myapi:8087 max_fails=0 fail_timeout=0s;
      server myapp-myapi:8087 max_fails=0 fail_timeout=0s;
    }

    map $a_request_header|$ssl_client_verify $ssl_common_name {
      default     $ssl_client_s_dn;
      40011|NONE  CN=mycn;
    }

    ssl_protocols             TLSv1 TLSv1.1;
    ssl_prefer_server_ciphers on;
    ssl_session_cache         shared:SSL:10m;
    ssl_session_timeout       10m;
    ssl_certificate           /etc/secrets/servercert-legacy;
    ssl_certificate_key       /etc/secrets/serverkey-legacy;
    ssl_client_certificate    /etc/nginx/ca.crt;

    proxy_set_header   Host                  $host;
    proxy_set_header   SSL-COMMON-NAME       $ssl_common_name; # TODO change this header to just DN
    proxy_set_header   VERIFIED              $ssl_client_verify;
    proxy_set_header   X-Real-IP             $remote_addr;
    proxy_set_header   X-Forwarded-For       $proxy_add_x_forwarded_for;
    proxy_set_header   X-Forwarded-Proto     $scheme;

    proxy_max_temp_file_size   0;
    proxy_connect_timeout      30;
    proxy_send_timeout         30;
    proxy_read_timeout         300;
    proxy_buffer_size          4k;
    proxy_buffers              4 32k;
    proxy_busy_buffers_size    64k;
    proxy_next_upstream        error http_502;
    proxy_temp_file_write_size 64k;

    default_type  application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] $scheme "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for" '
                      '"$ssl_client_s_dn" "$ssl_client_verify" '
                      '"$ssl_common_name" "$a_request_header"';

    access_log  /var/log/nginx/access.log  main;

    sendfile        on;
    #tcp_nopush     on;

    client_max_body_size 10m;
    client_body_buffer_size 128k;
    large_client_header_buffers 4 16k;

    # gzip on;
    # gzip_buffers 16 8k;
    # gzip_comp_level 3;
    # gzip_disable "msie6";
    # gzip_http_version 1.0;
    # gzip_min_length 1024;
    # gzip_proxied any;
    # gzip_types text/plain text/css text/xml text/javascript application/xml application/xml+rss application/javascript application/json;
    # gzip_vary on;

    include /etc/nginx/conf.d/*.conf;
}

We are using nginx/1.11.4.

Answer

Jason Martin picture Jason Martin · Dec 20, 2016

I don't see a configuration there that requires ssl client auth. Try adding 

ssl_verify_client on 
ssl_verify_depth 3;
ssl_client_certificate /path/to/accepted/CAs.pem;

(from http://nginx.org/en/docs/http/ngx_http_ssl_module.html#ssl_verify_client)

Related questions

cURL not respecting ciphers

I'd like to test the usage of certain ciphers with cURL, but it doesn't seem to respect the --ciphers option: curl -vvv --tlsv1.0 --ciphers 'RC4-SHA' https://my.url.com/alive * Hostname was NOT found in DNS cache * Trying ip... * …

Read More
curl with `-k` and without `-k`

When I am opening a url using curl without -k, my request is passing and I am able to see the expected result. $ curl -vvv https://MYHOSTNAME/wex/archive.info -A SUKU$RANDOM * Trying 10.38.202.192... * Connected to MYHOSTNAME (10.38.202.192) port 443 (#0) * TLS 1.2 connection …

Read More
https connection using CURL from command line

I am new to Curl and Cacerts world and facing a problem while connecting to a server. Basically, I need to test connectivity over https from one machine to another machine. I have a URL to which I need to …

Read More