MEDIUM: log: add the client's SNI to the default HTTPS log format

During a troublehooting it came obvious that the SNI always ought to
be logged on httpslog, as it explains errors caused by selection of
the default certificate (or failure to do so in case of strict-sni).

This expectation was also confirmed on the mailing list.

Since the field may be empty it appeared important not to leave an
empty string in the current format, so it was decided to place the
field before a '/' preceding the SSL version and ciphers, so that
in the worst case a missing field leads to a field looking like
"/TLSv1.2/AES...", though usually a missing element still results
in a "-" in logs.

This will change the log format for users who already deployed the
2.5-dev versions (hence the medium level) but no released version
was using this format yet so there's no harm for stable deployments.
The reg-test was updated to check for "-" there since we don't send
SNI in reg-tests.

Link: https://www.mail-archive.com/haproxy@formilux.org/msg41410.html
Cc: William Lallemand <wlallemand@haproxy.org>

diff --git a/doc/configuration.txt b/doc/configuration.txt
index e858de0..789d932 100644 (file)
--- a/doc/configuration.txt
+++ b/doc/configuration.txt
@@ -21268,7 +21268,7 @@ if required. Refer to section 8.2.5 "Custom log format" to see how to use this:
     log-format "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC \
                %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r \
                %[fc_err]/%[ssl_fc_err,hex]/%[ssl_c_err]/\
-               %[ssl_c_ca_err]/%[ssl_fc_is_resumed] %sslv/%sslc"
+               %[ssl_c_ca_err]/%[ssl_fc_is_resumed] %[ssl_fc_sni]/%sslv/%sslc"
 
 This format is basically the HTTP one (see section 8.2.3) with new fields
 appended to it. The new fields (lines 17 and 18) will be detailed here. For the
@@ -21288,7 +21288,8 @@ HTTP ones, refer to the HTTP section.
     >>> Feb  6 12:14:14 localhost \
           haproxy[14389]: 10.0.1.2:33317 [06/Feb/2009:12:14:14.655] https-in \
           static/srv1 10/0/30/69/109 200 2750 - - ---- 1/1/1/1/0 0/0 {1wt.eu} \
-          {} "GET /index.html HTTP/1.1" 0/0/0/0/0 TLSv1.3/TLS_AES_256_GCM_SHA384
+          {} "GET /index.html HTTP/1.1" 0/0/0/0/0 \
+          1wt.eu/TLSv1.3/TLS_AES_256_GCM_SHA384
 
   Field   Format                                  Extract from the example above
       1   process_name '[' pid ']:'                              haproxy[14389]:
@@ -21309,7 +21310,8 @@ HTTP ones, refer to the HTTP section.
      16   '"' http_request '"'                        "GET /index.html HTTP/1.1"
      17   fc_err '/' ssl_fc_err '/' ssl_c_err
           '/' ssl_c_ca_err '/' ssl_fc_is_resumed                       0/0/0/0/0
-     18   ssl_version '/' ssl_ciphers             TLSv1.3/TLS_AES_256_GCM_SHA384
+     18   ssl_fc_sni '/' ssl_version
+          '/' ssl_ciphers                  1wt.eu/TLSv1.3/TLS_AES_256_GCM_SHA384
 
 Detailed fields description :
   - "fc_err" is the status of the connection on the frontend's side. It
@@ -21336,6 +21338,12 @@ Detailed fields description :
     the stateful cache or a stateless ticket. Don't forgot that a TLS session
     can be shared by multiple requests.
 
+  - "ssl_fc_sni" is the SNI (Server Name Indication) presented by the client
+    to select the certificate to be used. It usually matches the host name for
+    the first request of a connection. An absence of this field may indicate
+    that the SNI was not sent by the client, and will lead haproxy to use the
+    default certificate, or to reject the connection in case of strict-sni.
+
   - "ssl_version" is the SSL version of the frontend.
 
   - "ssl_ciphers" is the SSL cipher used for the connection.

diff --git a/reg-tests/ssl/ssl_errors.vtc b/reg-tests/ssl/ssl_errors.vtc
index 5dd3491..ad3b82d 100644 (file)
--- a/reg-tests/ssl/ssl_errors.vtc
+++ b/reg-tests/ssl/ssl_errors.vtc
@@ -63,24 +63,24 @@ syslog Slg_cust_fmt -level info {
 
 syslog Slg_https_fmt -level info {
     recv
-    expect ~ ".*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/s1.*0/0000000000000000/0/0/.? TLSv1.2/AES256-GCM-SHA384"
+    expect ~ ".*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/s1.*0/0000000000000000/0/0/.? -/TLSv1.2/AES256-GCM-SHA384"
 
     barrier b1 sync
 } -start
 
 syslog Slg_https_fmt_err -level info {
     recv
-    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*30/0000000000000086/0/2/.? TLSv1.2/\\(NONE\\)"
+    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*30/0000000000000086/0/2/.? -/TLSv1.2/\\(NONE\\)"
 
     barrier b1 sync
 
     recv
-    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*31/0000000000000086/20/0/.? TLSv1.2/\\(NONE\\)"
+    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*31/0000000000000086/20/0/.? -/TLSv1.2/\\(NONE\\)"
 
     barrier b1 sync
 
     recv
-    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*34/00000000000000C1/0/0/.? TLSv1.2/\\(NONE\\)"
+    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*34/00000000000000C1/0/0/.? -/TLSv1.2/\\(NONE\\)"
 } -start
 
 syslog Slg_logconnerror -level info {
@@ -214,7 +214,7 @@ haproxy h1 -conf {
         option log-separate-errors
         mode http
         option httpslog
-        error-log-format "ERROR %ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r %[fc_err]/%[ssl_fc_err,and(proc.ssl_error_mask),hex]/%[ssl_c_err]/%[ssl_c_ca_err]/%[ssl_fc_is_resumed] %sslv/%sslc"
+        error-log-format "ERROR %ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r %[fc_err]/%[ssl_fc_err,and(proc.ssl_error_mask),hex]/%[ssl_c_err]/%[ssl_c_ca_err]/%[ssl_fc_is_resumed] %[ssl_fc_sni]/%sslv/%sslc"
         bind "${tmpdir}/https_logfmt_ssl.sock" ssl crt ${testdir}/set_cafile_server.pem ca-verify-file ${testdir}/set_cafile_rootCA.crt ca-file ${testdir}/set_cafile_interCA1.crt verify required ciphers "kRSA"
         server s1 ${s1_addr}:${s1_port}
 

diff --git a/src/log.c b/src/log.c
index 51ad75a..81bf97b 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -195,7 +195,7 @@ static const struct logformat_type logformat_keywords[] = {
 };
 
 char default_http_log_format[] = "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r"; // default format
-char default_https_log_format[] = "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r %[fc_err]/%[ssl_fc_err,hex]/%[ssl_c_err]/%[ssl_c_ca_err]/%[ssl_fc_is_resumed] %sslv/%sslc";
+char default_https_log_format[] = "%ci:%cp [%tr] %ft %b/%s %TR/%Tw/%Tc/%Tr/%Ta %ST %B %CC %CS %tsc %ac/%fc/%bc/%sc/%rc %sq/%bq %hr %hs %{+Q}r %[fc_err]/%[ssl_fc_err,hex]/%[ssl_c_err]/%[ssl_c_ca_err]/%[ssl_fc_is_resumed] %[ssl_fc_sni]/%sslv/%sslc";
 char clf_http_log_format[] = "%{+Q}o %{-Q}ci - - [%trg] %r %ST %B \"\" \"\" %cp %ms %ft %b %s %TR %Tw %Tc %Tr %Ta %tsc %ac %fc %bc %sc %rc %sq %bq %CC %CS %hrl %hsl";
 char default_tcp_log_format[] = "%ci:%cp [%t] %ft %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq";
 char *log_format = NULL;