nginx stream_ssl_preread module unable to read ssl_preread_server_name

Question

I am trying to set up nginx to map TLS connections to different backends based on the SNI server name. From what I can tell, my client is sending the server name, but the preread module is only reading a hyphen.

Here is my nginx congif:

stream  {
    map_hash_bucket_size 64;

    ############################################################
    ### logging
    log_format log_stream '$remote_addr [$time_local] $protocol [$ssl_preread_server_name] [$ssl_preread_alpn_protocols] [$instanceport] '
        '$status $bytes_sent $bytes_received $session_time';

    error_log   /usr/home/glance/Logs/pservernginx.error.log info;
    access_log  /usr/home/glance/Logs/pservernginx.access.log log_stream;

    ############################################################
    ### ssl configuration

    ssl_certificate      /usr/home/glance/GlanceReleases/star.myglance.org.pem;
    ssl_certificate_key  /usr/home/glance/GlanceReleases/star.myglance.org.pem;

    ssl_protocols       TLSv1.1 TLSv1.2;
    ssl_ciphers         HIGH:!aNULL:!MD5:!RC4;

    limit_conn_zone $binary_remote_addr zone=ip_addr:10m;

    ########################################################################
    ### Raw TLS PServer Connections
    ### Listen for TLS on 5501 and forward to TCP sock 6500 (socket port)

    ### https://nginx.org/en/docs/stream/ngx_stream_ssl_preread_module.html
    map $ssl_preread_server_name $instanceport {
        presence.myglance.org      6500;
        presence-1.myglance.org    6501;
        presence-2.myglance.org    6502;
        default                    glance-no-upstream-instance-configured;
    }

    server {

        listen                  5501 ssl;
        ssl_preread             on;
        proxy_connect_timeout   20s;  # max time to connect to pserver
        proxy_timeout           30s;  # max time between successive reads or writes
        proxy_pass              127.0.0.1:$instanceport;
    }
}

wireshark shows the Server Name header:

The nginx access log shows only hyphens for the preread variables:

108.49.96.66 [12/Apr/2019:11:50:58 +0000] TCP [-] [-] [glance-no-upstream-instance-configured] 500 0 0 0.066

I'm running nginx 1.14.2 on FreeBSD. How can I debug what is happening in the preread module?

================ UPDATE =============== Turned on debug logging. Maybe "ssl preread: not a handshake" is a clue.

2019/04/12 14:49:50 [info] 61420#0: *9 client 108.49.96.66:54740 connected to 0.0.0.0:5501
2019/04/12 14:49:50 [debug] 61420#0: *9 posix_memalign: 0000000801C35000:256 @16
2019/04/12 14:49:50 [debug] 61419#0: accept on 0.0.0.0:5501, ready: 1
2019/04/12 14:49:50 [debug] 61419#0: accept() not ready (35: Resource temporarily unavailable)
2019/04/12 14:49:50 [debug] 61420#0: *9 posix_memalign: 0000000801C35600:256 @16
2019/04/12 14:49:50 [debug] 61420#0: *9 generic phase: 0
2019/04/12 14:49:50 [debug] 61420#0: *9 generic phase: 1
2019/04/12 14:49:50 [debug] 61420#0: *9 generic phase: 2
2019/04/12 14:49:50 [debug] 61420#0: *9 tcp_nodelay
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_do_handshake: -1
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_get_error: 2
2019/04/12 14:49:50 [debug] 61420#0: *9 kevent set event: 5: ft:-1 fl:0025
2019/04/12 14:49:50 [debug] 61420#0: *9 event timer add: 5: 60000:29203481224
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL handshake handler: 0
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_do_handshake: 1
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(256) Mac=AEAD"
2019/04/12 14:49:50 [debug] 61420#0: *9 event timer del: 5: 29203481224
2019/04/12 14:49:50 [debug] 61420#0: *9 generic phase: 2
2019/04/12 14:49:50 [debug] 61420#0: *9 ssl preread handler
2019/04/12 14:49:50 [debug] 61420#0: *9 malloc: 0000000801CFF000:16384
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_read: -1
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_get_error: 2
2019/04/12 14:49:50 [debug] 61420#0: *9 ssl preread handler
2019/04/12 14:49:50 [debug] 61420#0: *9 posix_memalign: 0000000801C35900:256 @16
2019/04/12 14:49:50 [debug] 61420#0: *9 event timer add: 5: 30000:29203451252
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_read: 81
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_read: -1
2019/04/12 14:49:50 [debug] 61420#0: *9 SSL_get_error: 2
2019/04/12 14:49:50 [debug] 61420#0: *9 ssl preread handler
2019/04/12 14:49:50 [debug] 61420#0: *9 ssl preread: not a handshake
2019/04/12 14:49:50 [debug] 61420#0: *9 event timer del: 5: 29203451252
2019/04/12 14:49:50 [debug] 61420#0: *9 proxy connection handler
2019/04/12 14:49:50 [debug] 61420#0: *9 malloc: 0000000801DF7000:400
2019/04/12 14:49:50 [debug] 61420#0: *9 malloc: 0000000801CD9000:16384
2019/04/12 14:49:50 [debug] 61420#0: *9 stream map started
2019/04/12 14:49:50 [debug] 61420#0: *9 stream map: "" "glance-no-upstream-instance-configured"

================= UPDATE 2 ======================

I tested using

openssl s_client -connect ... -servername ...

instead of my client. Now it appears that the preread module is blocked waiting for data for 30 seconds (error code 2 is WANT_READ):

2019/04/23 13:04:30 [debug] 61419#0: *12844 SSL: TLSv1.2, cipher: "ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(256) Mac=AEAD"
2019/04/23 13:04:30 [debug] 61419#0: *12844 event timer del: 3: 30147561850
2019/04/23 13:04:30 [debug] 61419#0: *12844 generic phase: 2
2019/04/23 13:04:30 [debug] 61419#0: *12844 ssl preread handler
2019/04/23 13:04:30 [debug] 61419#0: *12844 malloc: 0000000801CA6140:16384
2019/04/23 13:04:30 [debug] 61419#0: *12844 SSL_read: -1
2019/04/23 13:04:30 [debug] 61419#0: *12844 SSL_get_error: 2
2019/04/23 13:04:30 [debug] 61419#0: *12844 ssl preread handler
2019/04/23 13:04:30 [debug] 61419#0: *12844 posix_memalign: 0000000801DB3400:256 @16
2019/04/23 13:04:30 [debug] 61419#0: *12844 event timer add: 3: 30000:30147531898
2019/04/23 13:05:00 [debug] 61419#0: *12844 event timer del: 3: 30147531898
2019/04/23 13:05:00 [debug] 61419#0: *12844 finalize stream session: 200
2019/04/23 13:05:00 [debug] 61419#0: *12844 stream log handler
2019/04/23 13:05:00 [debug] 61419#0: *12844 stream map started
2019/04/23 13:05:00 [debug] 61419#0: *12844 stream script var: ""

Answer 1

I found the problem:

listen                  5501 **ssl**;
ssl_preread             on;

ssl in the listen directive caused that nginx server to do the ssl handshake. By the time the preread module was notified, the handshake bytes had already been consumed, which is all consistent with the behavior I was seeing. In my case, I still want nginx to offload the encryption. So I created a set of nginx server directives to terminate the ssl connection before passing to my back end. This is the relevant portion of my nginx config after fixing it. Note that the last server directive (the one that uses ssl_preread) does not terminate the SSL connection.

########################################################################
### TLS Connections
### Listen for TLS on 5501 and forward to TCP sock 6500 (socket port)

### https://nginx.org/en/docs/stream/ngx_stream_ssl_preread_module.html
map $ssl_preread_server_name $instanceport {
    presence.myglance.org      5502;
    presence-1.myglance.org    5503;
    presence-2.myglance.org    5504;
    default                    glance-no-upstream-instance-configured;
}

server {
    listen                 5502 ssl;
    ssl_preread            off;
    proxy_pass             127.0.0.1:6502;
}

server {
    listen                 5503 ssl;
    ssl_preread            off;
    proxy_pass             127.0.0.1:6503;
}

server {
    listen                 5504 ssl;
    ssl_preread            off;
    proxy_pass             127.0.0.1:6504;
}

server {
    listen                  5501;
    ssl_preread             on;
    proxy_connect_timeout   20s;  # max time to connect to pserver
    proxy_timeout           30s;  # max time between successive reads or writes
    proxy_pass              127.0.0.1:$instanceport;
}

Answer 2

In case you need to use ssl in listen directive, you can simply use $ssl_server_name in the map block instead of $ssl_preread_server_name