title: NGINX says "client sent no required SSL certificate while reading client request headers" how do we troubleshoot?
body: <p>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.  </p>
  
  <p>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 <a href="https://f5.com/" rel="noreferrer">F5</a> 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.</p>
  
  <p>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.  <strong>How can I troubleshoot this better?</strong>  Right now we're starting nginx with <code>nginx-debug</code> but the debug output doesn't seem to clearly explain why we're seeing this problem.  Here are some of these logs:</p>
  
  <pre><code>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"
  </code></pre>
  
  <p>This is our <code>nginx.conf</code> file:</p>
  
  <pre><code>#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;
  }
  </code></pre>
  
  <p>We are using nginx/1.11.4.</p>