MINOR: log: Add new "error-log-format" option

This option can be used to define a specific log format that will be
used in case of error, timeout, connection failure on a frontend... It
will be used for any log line concerned by the log-separate-errors
option. It will also replace the format of specific error messages
decribed in section 8.2.6.
If no "error-log-format" is defined, the legacy error messages are still
emitted and the other error logs keep using the regular log-format.

doc/configuration.txt

@@ -3561,6 +3561,7 @@ errorloc                                  X          X         X         X
 errorloc302                               X          X         X         X
 -- keyword -------------------------- defaults - frontend - listen -- backend -
 errorloc303                               X          X         X         X
+error-log-format                          X          X         X         -
 force-persist                             -          -         X         X
 filter                                    -          X         X         X
 fullconn                                  X          -         X         X
@@ -4943,6 +4944,24 @@ email-alert to <emailaddr>
              "email-alert myhostname", section 3.6 about mailers.
 
 
+error-log-format <string>
+  Specifies the log format string to use in case of connection error on the frontend side.
+  May be used in sections:    defaults | frontend | listen | backend
+                                 yes   |    yes   |   yes  |    no
+
+  This directive specifies the log format string that will be used for logs
+  containing information related to errors, timeouts, retries redispatches or
+  HTTP status code 5xx. This format will in short be used for every log line
+  that would be concerned by the "log-separate-errors" option, including
+  connection errors described in section 8.2.6..
+  If the directive is used in a defaults section, all subsequent frontends will
+  use the same log format. Please see section 8.2.4 which covers the log format
+  string in depth.
+
+  "error-log-format" directive overrides previous "error-log-format"
+  directives.
+
+
 force-persist { if | unless } <condition>
   Declare a condition to force persistence on down servers
   May be used in sections:    defaults | frontend | listen | backend
@@ -7823,6 +7842,8 @@ log-format <string>
   directive is used in a defaults section, all subsequent frontends will use
   the same log format. Please see section 8.2.4 which covers the log format
   string in depth.
+  A specific log-format used only in case of connection error can also be
+  defined, see the "error-log-format" option.
 
   "log-format" directive overrides previous "option tcplog", "log-format",
   "option httplog" and "option httpslog" directives.
@@ -21107,13 +21128,14 @@ Please refer to the table below for currently defined variables :
 -----------------------
 
 When an incoming connection fails due to an SSL handshake or an invalid PROXY
-protocol header, HAProxy will log the event using a shorter, fixed line format.
+protocol header, HAProxy will log the event using a shorter, fixed line format,
+unless a dedicated error log format is defined through an "error-log-format"
+line. In the latter case, the legacy log format described below will not be
+used anymore, and all error log lines will follow the defined format.
 By default, logs are emitted at the LOG_INFO level, unless the option
 "log-separate-errors" is set in the backend, in which case the LOG_ERR level
 will be used. Connections on which no data are exchanged (e.g. probes) are not
-logged if the "dontlognull" option is set. If the "log-error-via-logformat" option
+logged if the "dontlognull" option is set.
-is set, those messages are not emitted and a line following the configured
-log-format is emitted instead.
 
 The format looks like this :
 

include/haproxy/proxy-t.h

@@ -371,6 +371,7 @@ struct proxy {
 	struct list logsrvs;
 	struct list logformat; 			/* log_format linked list */
 	struct list logformat_sd;		/* log_format linked list for the RFC5424 structured-data part */
+	struct list logformat_error;		/* log_format linked list used in case of connection error on the frontend */
 	struct buffer log_tag;                   /* override default syslog tag */
 	struct ist header_unique_id; 		/* unique-id header */
 	struct list format_unique_id;		/* unique-id format */
@@ -429,6 +430,9 @@ struct proxy {
 		char *logformat_sd_string;	/* log format string for the RFC5424 structured-data part */
 		char *lfsd_file;		/* file name where the structured-data logformat string for RFC5424 appears (strdup) */
 		int  lfsd_line;			/* file name where the structured-data logformat string for RFC5424 appears */
+		char *error_logformat_string;
+		char *elfs_file;
+		int elfs_line;
 	} conf;					/* config information */
 	struct eb_root used_server_addr;        /* list of server addresses in use */
 	void *parent;				/* parent of the proxy when applicable */

reg-tests/ssl/ssl_errors.vtc

@@ -44,12 +44,12 @@ syslog Slg_cust_fmt -level info {
     barrier b1 sync
 
     recv
-    expect ~ ".*conn_status:\"30:SSL client CA chain cannot be verified\" hsk_err:\"337100934:error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed\" CN=\"/C=FR/O=HAProxy Technologies/CN=Client\",serial=1007,hash=063DCC2E6A9159E66994B325D6D2EF3D17A75B6F"
+    expect ~ "ERROR.*conn_status:\"30:SSL client CA chain cannot be verified\" hsk_err:\"337100934:error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed\" CN=\"/C=FR/O=HAProxy Technologies/CN=Client\",serial=1007,hash=063DCC2E6A9159E66994B325D6D2EF3D17A75B6F"
 
     barrier b1 sync
 
     recv
-    expect ~ ".*conn_status:\"31:SSL client certificate not trusted\" hsk_err:\"337100934:error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed\" CN=\"/C=FR/O=HAProxy Technologies/CN=Client\",serial=1007,hash=063DCC2E6A9159E66994B325D6D2EF3D17A75B6F"
+    expect ~ "ERROR.*conn_status:\"31:SSL client certificate not trusted\" hsk_err:\"337100934:error:1417C086:SSL routines:tls_process_client_certificate:certificate verify failed\" CN=\"/C=FR/O=HAProxy Technologies/CN=Client\",serial=1007,hash=063DCC2E6A9159E66994B325D6D2EF3D17A75B6F"
 
     barrier b1 sync
 
@@ -57,7 +57,7 @@ syslog Slg_cust_fmt -level info {
     # the client certificate chain is never parsed and verified so we can't
     # have information about the client's certificate.
     recv
-    expect ~ ".*conn_status:\"34:SSL handshake failure\" hsk_err:\"337678529:error:142090C1:SSL routines:tls_early_post_process_client_hello:no shared cipher\" CN=\"\",serial=-,hash=-"
+    expect ~ "ERROR.*conn_status:\"34:SSL handshake failure\" hsk_err:\"337678529:error:142090C1:SSL routines:tls_early_post_process_client_hello:no shared cipher\" CN=\"\",serial=-,hash=-"
 } -start
 
 syslog Slg_https_fmt -level info {
@@ -69,17 +69,17 @@ syslog Slg_https_fmt -level info {
 
 syslog Slg_https_fmt_err -level info {
     recv
-    expect ~ ".*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*30/000000001417C086/0/2 TLSv1.3/TLS_AES_256_GCM_SHA384"
+    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*30/000000001417C086/0/2 TLSv1.3/TLS_AES_256_GCM_SHA384"
 
     barrier b1 sync
 
     recv
-    expect ~ ".*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*31/000000001417C086/20/0 TLSv1.3/TLS_AES_256_GCM_SHA384"
+    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*31/000000001417C086/20/0 TLSv1.3/TLS_AES_256_GCM_SHA384"
 
     barrier b1 sync
 
     recv
-    expect ~ ".*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*34/00000000142090C1/0/0 TLSv1.3/\\(NONE\\)"
+    expect ~ "ERROR.*https_logfmt_ssl_lst~ https_logfmt_ssl_lst/<NOSRV>.*34/00000000142090C1/0/0 TLSv1.3/\\(NONE\\)"
 } -start
 
 syslog Slg_logconnerror -level info {
@@ -137,19 +137,19 @@ haproxy h1 -conf {
 
     listen cust_logfmt_ssl_lst
         log ${Slg_cust_fmt_addr}:${Slg_cust_fmt_port} local0
-	option log-error-via-logformat
         mode http
         log-format "conn_status:\"%[fc_conn_err]:%[fc_conn_err_str]\" hsk_err:\"%[ssl_fc_hsk_err]:%[ssl_fc_hsk_err_str]\" CN=%{+Q}[ssl_c_s_dn],serial=%[ssl_c_serial,hex],hash=%[ssl_c_sha1,hex]"
+        error-log-format "ERROR conn_status:\"%[fc_conn_err]:%[fc_conn_err_str]\" hsk_err:\"%[ssl_fc_hsk_err]:%[ssl_fc_hsk_err_str]\" CN=%{+Q}[ssl_c_s_dn],serial=%[ssl_c_serial,hex],hash=%[ssl_c_sha1,hex]"
         bind "${tmpdir}/cust_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 ciphersuites "TLS_AES_256_GCM_SHA384"
         server s1 ${s1_addr}:${s1_port}
 
     listen https_logfmt_ssl_lst
         log ${Slg_https_fmt_addr}:${Slg_https_fmt_port} local0 info
         log ${Slg_https_fmt_err_addr}:${Slg_https_fmt_err_port} local0 err info
-	option log-error-via-logformat
         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_conn_err]/%[ssl_fc_hsk_err,hex]/%[ssl_c_err]/%[ssl_c_ca_err] %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 ciphersuites "TLS_AES_256_GCM_SHA384"
         server s1 ${s1_addr}:${s1_port}
 

src/cfgparse-listen.c

@@ -52,6 +52,7 @@ static const char *common_kw_list[] = {
 	"fullconn", "dispatch", "balance", "hash-type",
 	"hash-balance-factor", "unique-id-format", "unique-id-header",
 	"log-format", "log-format-sd", "log-tag", "log", "source", "usesrc",
+	"error-log-format",
 	NULL /* must be last */
 };
 
@@ -2753,6 +2754,39 @@ stats_error_parsing:
 			err_code |= ERR_WARN;
 		}
 	}
+	else if (strcmp(args[0], "error-log-format") == 0) {
+		if (!*(args[1])) {
+			ha_alert("parsing [%s:%d] : %s expects an argument.\n", file, linenum, args[0]);
+			err_code |= ERR_ALERT | ERR_FATAL;
+			goto out;
+		}
+		if (*(args[2])) {
+			ha_alert("parsing [%s:%d] : %s expects only one argument, don't forget to escape spaces!\n", file, linenum, args[0]);
+			err_code |= ERR_ALERT | ERR_FATAL;
+			goto out;
+		}
+		if (curproxy->conf.error_logformat_string && curproxy->cap & PR_CAP_DEF) {
+			ha_warning("parsing [%s:%d]: 'error-log-format' overrides previous 'error-log-format' in 'defaults' section.\n",
+				   file, linenum);
+		}
+		free(curproxy->conf.error_logformat_string);
+		curproxy->conf.error_logformat_string = strdup(args[1]);
+		if (!curproxy->conf.error_logformat_string)
+			goto alloc_error;
+
+		free(curproxy->conf.elfs_file);
+		curproxy->conf.elfs_file = strdup(curproxy->conf.args.file);
+		curproxy->conf.elfs_line = curproxy->conf.args.line;
+
+		/* get a chance to improve log-format error reporting by
+		 * reporting the correct line-number when possible.
+		 */
+		if (!(curproxy->cap & PR_CAP_DEF) && !(curproxy->cap & PR_CAP_FE)) {
+			ha_warning("parsing [%s:%d] : backend '%s' : 'error-log-format' directive is ignored in backends.\n",
+				   file, linenum, curproxy->id);
+			err_code |= ERR_WARN;
+		}
+	}
 	else if (strcmp(args[0], "log-tag") == 0) {  /* tag to report to syslog */
 		if (*(args[1]) == 0) {
 			ha_alert("parsing [%s:%d] : '%s' expects a tag for use in syslog.\n", file, linenum, args[0]);

src/cfgparse.c

@@ -3115,6 +3115,23 @@ out_uri_auth_compat:
 			curproxy->conf.args.line = 0;
 		}
 
+		if (curproxy->conf.error_logformat_string) {
+			curproxy->conf.args.ctx = ARGC_LOG;
+			curproxy->conf.args.file = curproxy->conf.elfs_file;
+			curproxy->conf.args.line = curproxy->conf.elfs_line;
+			err = NULL;
+			if (!parse_logformat_string(curproxy->conf.error_logformat_string, curproxy, &curproxy->logformat_error,
+			                            LOG_OPT_MANDATORY|LOG_OPT_MERGE_SPACES,
+			                            SMP_VAL_FE_LOG_END, &err)) {
+				ha_alert("Parsing [%s:%d]: failed to parse error-log-format : %s.\n",
+					 curproxy->conf.elfs_file, curproxy->conf.elfs_line, err);
+				free(err);
+				cfgerr++;
+			}
+			curproxy->conf.args.file = NULL;
+			curproxy->conf.args.line = 0;
+		}
+
 		/* only now we can check if some args remain unresolved.
 		 * This must be done after the users and groups resolution.
 		 */

src/log.c

@@ -3126,6 +3126,9 @@ void sess_log(struct session *sess)
 		                             &sess->fe->logformat_sd);
 	}
 
+	if (!LIST_ISEMPTY(&sess->fe->logformat_error))
+		size = sess_build_logline(sess, NULL, logline, global.max_syslog_len, &sess->fe->logformat_error);
+	else
 		size = sess_build_logline(sess, NULL, logline, global.max_syslog_len, &sess->fe->logformat);
 	if (size > 0) {
 		_HA_ATOMIC_INC(&sess->fe->log_count);

src/proxy.c

@@ -178,6 +178,9 @@ void free_proxy(struct proxy *p)
 		free(p->conf.logformat_sd_string);
 	free(p->conf.lfsd_file);
 
+	free(p->conf.error_logformat_string);
+	free(p->conf.elfs_file);
+
 	list_for_each_entry_safe(cond, condb, &p->mon_fail_cond, list) {
 		LIST_DELETE(&cond->list);
 		prune_acl_cond(cond);
@@ -257,6 +260,13 @@ void free_proxy(struct proxy *p)
 		free(lf);
 	}
 
+	list_for_each_entry_safe(lf, lfb, &p->logformat_error, list) {
+		LIST_DELETE(&lf->list);
+		release_sample_expr(lf->expr);
+		free(lf->arg);
+		free(lf);
+	}
+
 	free_act_rules(&p->tcp_req.inspect_rules);
 	free_act_rules(&p->tcp_rep.inspect_rules);
 	free_act_rules(&p->tcp_req.l4_rules);
@@ -1321,6 +1331,7 @@ void init_new_proxy(struct proxy *p)
 	LIST_INIT(&p->logformat);
 	LIST_INIT(&p->logformat_sd);
 	LIST_INIT(&p->format_unique_id);
+	LIST_INIT(&p->logformat_error);
 	LIST_INIT(&p->conf.bind);
 	LIST_INIT(&p->conf.listeners);
 	LIST_INIT(&p->conf.errors);
@@ -1434,9 +1445,11 @@ void proxy_free_defaults(struct proxy *defproxy)
 		ha_free(&defproxy->conf.logformat_sd_string);
 
 	ha_free(&defproxy->conf.uniqueid_format_string);
+	ha_free(&defproxy->conf.error_logformat_string);
 	ha_free(&defproxy->conf.lfs_file);
 	ha_free(&defproxy->conf.lfsd_file);
 	ha_free(&defproxy->conf.uif_file);
+	ha_free(&defproxy->conf.elfs_file);
 	chunk_destroy(&defproxy->log_tag);
 
 	free_email_alert(defproxy);
@@ -1668,6 +1681,15 @@ static int proxy_defproxy_cpy(struct proxy *curproxy, const struct proxy *defpro
 			curproxy->conf.lfsd_file = strdup(defproxy->conf.lfsd_file);
 			curproxy->conf.lfsd_line = defproxy->conf.lfsd_line;
 		}
+
+		curproxy->conf.error_logformat_string = defproxy->conf.error_logformat_string;
+		if (curproxy->conf.error_logformat_string)
+			curproxy->conf.error_logformat_string = strdup(curproxy->conf.error_logformat_string);
+
+		if (defproxy->conf.elfs_file) {
+			curproxy->conf.elfs_file = strdup(defproxy->conf.elfs_file);
+			curproxy->conf.elfs_line = defproxy->conf.elfs_line;
+		}
 	}
 
 	if (curproxy->cap & PR_CAP_BE) {

src/session.c

@@ -357,8 +357,8 @@ static void session_kill_embryonic(struct session *sess, unsigned int state)
 				conn->err_code = CO_ER_SSL_TIMEOUT;
 		}
 
-		if (sess->fe->options & PR_O_ERR_LOGFMT) {
+		if(!LIST_ISEMPTY(&sess->fe->logformat_error)) {
-			/* Display a log line following the configured log-format. */
+			/* Display a log line following the configured error-log-format. */
 			sess_log(sess);
 		}
 		else {