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.
I don't see a configuration there that requires ssl client auth. Try adding
(from http://nginx.org/en/docs/http/ngx_http_ssl_module.html#ssl_verify_client)