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
--- a/doc/configuration.txt
+++ b/doc/configuration.txt
@@ -21268,7 +21268,7 @@
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 @@
>>> 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 @@
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 @@
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
--- a/reg-tests/ssl/ssl_errors.vtc
+++ b/reg-tests/ssl/ssl_errors.vtc
@@ -63,24 +63,24 @@
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 @@
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
--- a/src/log.c
+++ b/src/log.c
@@ -195,7 +195,7 @@
};
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;