MEDIUM: logs: add a new RFC5424 log-format for the structured-data

This patch adds a new RFC5424-specific log-format for the structured-data
that is automatically send by __send_log() when the sender is in RFC5424
mode.

A new statement "log-format-sd" should be used in order to set log-format
for the structured-data part in RFC5424 formatted syslog messages.
Example:

    log-format-sd [exampleSDID@1234\ bytes=\"%B\"\ status=\"%ST\"]

include/proto/log.h

@@ -43,9 +43,12 @@ extern char clf_http_log_format[];
 extern char default_host_tag_pid_log_format[];
 extern char rfc5424_host_tag_pid_log_format[];
 
+extern char default_rfc5424_sd_log_format[];
+
 extern char *logheader;
 extern char *logheader_rfc5424;
 extern char *logline;
+extern char *logline_rfc5424;
 
 
 int build_logline(struct stream *s, char *dst, size_t maxsize, struct list *list_format);
@@ -111,7 +114,7 @@ void send_log(struct proxy *p, int level, const char *format, ...)
  * It doesn't care about errors nor does it report them.
  */
 
-void __send_log(struct proxy *p, int level, char *message, size_t size);
+void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd, size_t sd_size);
 
 /*
  * returns log format for <fmt> or -1 if not found.

include/types/arg.h

@@ -69,6 +69,7 @@ enum {
 	ARGC_STK,      /* sticking rule */
 	ARGC_TRK,      /* tracking rule */
 	ARGC_LOG,      /* log-format */
+	ARGC_LOGSD,    /* log-format-sd */
 	ARGC_HRQ,      /* http-request */
 	ARGC_HRS,      /* http-response */
 	ARGC_UIF,      /* unique-id-format */

include/types/log.h

@@ -30,7 +30,7 @@
 
 #define NB_LOG_FACILITIES       24
 #define NB_LOG_LEVELS           8
-#define NB_MSG_IOVEC_ELEMENTS   3
+#define NB_MSG_IOVEC_ELEMENTS   4
 #define SYSLOG_PORT             514
 #define UNIQUEID_LEN            128
 

include/types/proxy.h

@@ -345,6 +345,7 @@ struct proxy {
 	unsigned int log_count;			/* number of logs produced by the frontend */
 	struct list logsrvs;
 	struct list logformat; 			/* log_format linked list */
+	struct list logformat_sd;		/* log_format linked list for the RFC5424 structured-data part */
 	char *log_tag;                          /* override default syslog tag */
 	struct chunk log_htp;			/* a syslog header part that contains hostname, log_tag and pid (RFC3164 format) */
 	struct chunk log_htp_rfc5424;		/* a syslog header part that contains hostname, log_tag and pid (RFC5424 format) */
@@ -404,6 +405,9 @@ struct proxy {
 		int   uif_line;                 /* file name where the unique-id-format string appears */
 		char *uif_file;                 /* file name where the unique-id-format string appears (strdup) */
 		char *uniqueid_format_string;	/* unique-id format string */
+		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 */
 	} conf;					/* config information */
 	void *parent;				/* parent of the proxy when applicable */
 	struct comp *comp;			/* http compression */

src/cfgparse.c

@@ -1574,6 +1574,7 @@ int cfg_parse_global(const char *file, int linenum, char **args, int kwm)
 			logheader = realloc(logheader, global.max_syslog_len + 1);
 			logheader_rfc5424 = realloc(logheader_rfc5424, global.max_syslog_len + 1);
 			logline = realloc(logline, global.max_syslog_len + 1);
+			logline_rfc5424 = realloc(logline_rfc5424, global.max_syslog_len + 1);
 		}
 
 		/* after the length, a format may be specified */
@@ -2722,6 +2723,17 @@ int cfg_parse_listen(const char *file, int linenum, char **args, int kwm)
 				curproxy->conf.lfs_file = strdup(defproxy.conf.lfs_file);
 				curproxy->conf.lfs_line = defproxy.conf.lfs_line;
 			}
+
+			/* get either a pointer to the logformat string for RFC5424 structured-data or a copy of it */
+			curproxy->conf.logformat_sd_string = defproxy.conf.logformat_sd_string;
+			if (curproxy->conf.logformat_sd_string &&
+			    curproxy->conf.logformat_sd_string != default_rfc5424_sd_log_format)
+				curproxy->conf.logformat_sd_string = strdup(curproxy->conf.logformat_sd_string);
+
+			if (defproxy.conf.lfsd_file) {
+				curproxy->conf.lfsd_file = strdup(defproxy.conf.lfsd_file);
+				curproxy->conf.lfsd_line = defproxy.conf.lfsd_line;
+			}
 		}
 
 		if (curproxy->cap & PR_CAP_BE) {
@@ -2838,6 +2850,10 @@ int cfg_parse_listen(const char *file, int linenum, char **args, int kwm)
 		free(defproxy.log_tag);
 		free_email_alert(&defproxy);
 
+		if (defproxy.conf.logformat_sd_string != default_rfc5424_sd_log_format)
+			free(defproxy.conf.logformat_sd_string);
+		free(defproxy.conf.lfsd_file);
+
 		for (rc = 0; rc < HTTP_ERR_SIZE; rc++)
 			chunk_destroy(&defproxy.errmsg[rc]);
 
@@ -5805,6 +5821,35 @@ stats_error_parsing:
 			err_code |= ERR_WARN;
 		}
 	}
+	else if (!strcmp(args[0], "log-format-sd")) {
+		if (!*(args[1])) {
+			Alert("parsing [%s:%d] : %s expects an argument.\n", file, linenum, args[0]);
+			err_code |= ERR_ALERT | ERR_FATAL;
+			goto out;
+		}
+		if (*(args[2])) {
+			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.logformat_sd_string != default_rfc5424_sd_log_format)
+			free(curproxy->conf.logformat_sd_string);
+		curproxy->conf.logformat_sd_string = strdup(args[1]);
+
+		free(curproxy->conf.lfsd_file);
+		curproxy->conf.lfsd_file = strdup(curproxy->conf.args.file);
+		curproxy->conf.lfsd_line = curproxy->conf.args.line;
+
+		/* get a chance to improve log-format-sd error reporting by
+		 * reporting the correct line-number when possible.
+		 */
+		if (curproxy != &defproxy && !(curproxy->cap & PR_CAP_FE)) {
+			Warning("parsing [%s:%d] : backend '%s' : 'log-format-sd' directive is ignored in backends.\n",
+				file, linenum, curproxy->id);
+			err_code |= ERR_WARN;
+		}
+	}
 	else if (!strcmp(args[0], "log-tag")) {  /* tag to report to syslog */
 		if (*(args[1]) == 0) {
 			Alert("parsing [%s:%d] : '%s' expects a tag for use in syslog.\n", file, linenum, args[0]);
@@ -5871,6 +5916,7 @@ stats_error_parsing:
 				logheader = realloc(logheader, global.max_syslog_len + 1);
 				logheader_rfc5424 = realloc(logheader_rfc5424, global.max_syslog_len + 1);
 				logline = realloc(logline, global.max_syslog_len + 1);
+				logline_rfc5424 = realloc(logline_rfc5424, global.max_syslog_len + 1);
 			}
 
 			/* after the length, a format may be specified */
@@ -7866,6 +7912,8 @@ out_uri_auth_compat:
 				hdr = logheader_rfc5424;
 				htp = &curproxy->log_htp_rfc5424;
 				htp_fmt = rfc5424_host_tag_pid_log_format;
+				if (!curproxy->conf.logformat_sd_string)
+					curproxy->conf.logformat_sd_string = default_rfc5424_sd_log_format;
 				break;
 
 			default:
@@ -7915,6 +7963,13 @@ out_host_tag_pid:
 			free(curproxy->conf.lfs_file);
 			curproxy->conf.lfs_file = NULL;
 			curproxy->conf.lfs_line = 0;
+
+			if (curproxy->conf.logformat_sd_string != default_rfc5424_sd_log_format)
+				free(curproxy->conf.logformat_sd_string);
+			curproxy->conf.logformat_sd_string = NULL;
+			free(curproxy->conf.lfsd_file);
+			curproxy->conf.lfsd_file = NULL;
+			curproxy->conf.lfsd_line = 0;
 		}
 
 		if (curproxy->conf.logformat_string) {
@@ -7927,6 +7982,17 @@ out_host_tag_pid:
 			curproxy->conf.args.line = 0;
 		}
 
+		if (curproxy->conf.logformat_sd_string) {
+			curproxy->conf.args.ctx = ARGC_LOGSD;
+			curproxy->conf.args.file = curproxy->conf.lfsd_file;
+			curproxy->conf.args.line = curproxy->conf.lfsd_line;
+			parse_logformat_string(curproxy->conf.logformat_sd_string, curproxy, &curproxy->logformat_sd, LOG_OPT_MANDATORY,
+					       SMP_VAL_FE_LOG_END, curproxy->conf.lfsd_file, curproxy->conf.lfsd_line);
+			add_to_logformat_list(NULL, NULL, LF_SEPARATOR, &curproxy->logformat_sd);
+			curproxy->conf.args.file = NULL;
+			curproxy->conf.args.line = 0;
+		}
+
 		if (curproxy->conf.uniqueid_format_string) {
 			curproxy->conf.args.ctx = ARGC_UIF;
 			curproxy->conf.args.file = curproxy->conf.uif_file;
@@ -8287,7 +8353,8 @@ out_host_tag_pid:
 			curproxy->to_log &= ~LW_BYTES;
 
 		if ((curproxy->mode == PR_MODE_TCP || curproxy->mode == PR_MODE_HTTP) &&
-		    (curproxy->cap & PR_CAP_FE) && !LIST_ISEMPTY(&curproxy->logformat) && LIST_ISEMPTY(&curproxy->logsrvs)) {
+		    (curproxy->cap & PR_CAP_FE) && LIST_ISEMPTY(&curproxy->logsrvs) &&
+		    (!LIST_ISEMPTY(&curproxy->logformat) || !LIST_ISEMPTY(&curproxy->logformat_sd))) {
 			Warning("config : log format ignored for %s '%s' since it has no log address.\n",
 				proxy_type_str(curproxy), curproxy->id);
 			err_code |= ERR_WARN;

src/haproxy.c

@@ -1227,6 +1227,10 @@ void deinit(void)
 		free(p->conf.uif_file);
 		free(p->lbprm.map.srv);
 
+		if (p->conf.logformat_sd_string != default_rfc5424_sd_log_format)
+			free(p->conf.logformat_sd_string);
+		free(p->conf.lfsd_file);
+
 		for (i = 0; i < HTTP_ERR_SIZE; i++)
 			chunk_destroy(&p->errmsg[i]);
 
@@ -1336,6 +1340,11 @@ void deinit(void)
 			free(lf);
 		}
 
+		list_for_each_entry_safe(lf, lfb, &p->logformat_sd, list) {
+			LIST_DEL(&lf->list);
+			free(lf);
+		}
+
 		deinit_tcp_rules(&p->tcp_req.inspect_rules);
 		deinit_tcp_rules(&p->tcp_req.l4_rules);
 

src/log.c

@@ -155,8 +155,16 @@ char clf_http_log_format[] = "%{+Q}o %{-Q}ci - - [%T] %r %ST %B \"\" \"\" %cp %m
 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;
 
+/* Common printf format strings for hostname, log_tag and pid used in all
+ * outgoing syslog messages.
+ */
 char default_host_tag_pid_log_format[] = "%s%s[%d]: ";
-char rfc5424_host_tag_pid_log_format[] = "%s%s %d - - ";
+char rfc5424_host_tag_pid_log_format[] = "%s%s %d - ";
+
+/* Default string used for structured-data part in RFC5424 formatted
+ * syslog messages.
+ */
+char default_rfc5424_sd_log_format[] = "- ";
 
 /* This is a global syslog header, common to all outgoing messages in
  * RFC3164 format. It begins with time-based part and is updated by
@@ -174,6 +182,11 @@ char *logheader_rfc5424 = NULL;
  */
 char *logline = NULL;
 
+/* A global syslog message buffer, common to all RFC5424 syslog messages.
+ * Currently, it is used for generating the structured-data part.
+ */
+char *logline_rfc5424 = NULL;
+
 struct logformat_var_args {
 	char *name;
 	int mask;
@@ -201,6 +214,8 @@ static inline const char *fmt_directive(const struct proxy *curproxy)
 		return "track-sc";
 	case ARGC_LOG:
 		return "log-format";
+	case ARGC_LOGSD:
+		return "log-format-sd";
 	case ARGC_HRQ:
 		return "http-request";
 	case ARGC_HRS:
@@ -782,17 +797,17 @@ char *lf_host_tag_pid(char *dst, const char *format, const char *hostname, const
  * the beginning of logheader once a second and return the pointer to the
  * first character after it.
  */
-static char *update_log_hdr()
+static char *update_log_hdr(const time_t time)
 {
 	static long tvsec;
 	static char *dataptr = NULL; /* backup of last end of header, NULL first time */
 
-	if (unlikely(date.tv_sec != tvsec || dataptr == NULL)) {
+	if (unlikely(time != tvsec || dataptr == NULL)) {
 		/* this string is rebuild only once a second */
 		struct tm tm;
 		int hdr_len;
 
-		tvsec = date.tv_sec;
+		tvsec = time;
 		get_localtime(tvsec, &tm);
 
 		hdr_len = snprintf(logheader, global.max_syslog_len,
@@ -818,17 +833,17 @@ static char *update_log_hdr()
  * the beginning of logheader_rfc5424 once a second and return the pointer
  * to the first character after it.
  */
-static char *update_log_hdr_rfc5424()
+static char *update_log_hdr_rfc5424(const time_t time)
 {
 	static long tvsec;
 	static char *dataptr = NULL; /* backup of last end of header, NULL first time */
 
-	if (unlikely(date.tv_sec != tvsec || dataptr == NULL)) {
+	if (unlikely(time != tvsec || dataptr == NULL)) {
 		/* this string is rebuild only once a second */
 		struct tm tm;
 		int hdr_len;
 
-		tvsec = date.tv_sec;
+		tvsec = time;
 		get_localtime(tvsec, &tm);
 
 		hdr_len = snprintf(logheader_rfc5424, global.max_syslog_len,
@@ -869,15 +884,17 @@ void send_log(struct proxy *p, int level, const char *format, ...)
 		data_len = global.max_syslog_len;
 	va_end(argp);
 
-	__send_log(p, level, logline, data_len);
+	__send_log(p, level, logline, data_len, default_rfc5424_sd_log_format, 2);
 }
 
 /*
  * This function sends a syslog message.
  * It doesn't care about errors nor does it report them.
- * It overrides the last byte of the vector with an LF character.
+ * It overrides the last byte of the message vector with an LF character.
+ * The arguments <sd> and <sd_size> are used for the structured-data part
+ * in RFC5424 formatted syslog messages.
  */
-void __send_log(struct proxy *p, int level, char *message, size_t size)
+void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd, size_t sd_size)
 {
 	static struct iovec iovec[NB_MSG_IOVEC_ELEMENTS] = { };
 	static struct msghdr msghdr = {
@@ -895,6 +912,7 @@ void __send_log(struct proxy *p, int level, char *message, size_t size)
 	char *hdr, *hdr_ptr;
 	size_t hdr_size;
 	struct chunk *htp;
+	time_t time = date.tv_sec;
 
 	dataptr = message;
 
@@ -921,6 +939,7 @@ void __send_log(struct proxy *p, int level, char *message, size_t size)
 		int maxlen;
 		int hdr_max = 0;
 		int htp_max = 0;
+		int sd_max = 0;
 		int max = 1;
 		char backup;
 
@@ -948,14 +967,15 @@ void __send_log(struct proxy *p, int level, char *message, size_t size)
 		switch (logsrv->format) {
 		case LOG_FORMAT_RFC3164:
 			hdr = logheader;
-			hdr_ptr = update_log_hdr();
+			hdr_ptr = update_log_hdr(time);
 			htp = &p->log_htp;
 			break;
 
 		case LOG_FORMAT_RFC5424:
 			hdr = logheader_rfc5424;
-			hdr_ptr = update_log_hdr_rfc5424();
+			hdr_ptr = update_log_hdr_rfc5424(time);
 			htp = &p->log_htp_rfc5424;
+			sd_max = sd_size; /* the SD part allowed only in RFC5424 */
 			break;
 
 		default:
@@ -986,21 +1006,28 @@ void __send_log(struct proxy *p, int level, char *message, size_t size)
 
 		if (unlikely(hdr_size >= logsrv->maxlen)) {
 			hdr_max = MIN(hdr_max, logsrv->maxlen) - 1;
+			sd_max = 0;
 			goto send;
 		}
 
 		maxlen = logsrv->maxlen - hdr_max;
-		htp_max = htp->len;
 
-		if (unlikely(htp_max >= maxlen)) {
+		if (unlikely(htp->len >= maxlen)) {
 			htp_max = maxlen - 1;
+			sd_max = 0;
 			goto send;
 		}
 
-		max = MIN(size, maxlen - htp_max);
+		htp_max = htp->len;
+		maxlen -= htp_max;
 
+		if (sd_max >= maxlen) {
+			sd_max = maxlen - 1;
+			goto send;
+		}
+
+		max = MIN(size, maxlen - sd_max);
 		log_ptr += max - 1;
-
 send:
 		/* insert a \n at the end of the message, but save what was
 		 * there first because we could have different max lengths
@@ -1013,8 +1040,10 @@ send:
 		iovec[0].iov_len = hdr_max;
 		iovec[1].iov_base = htp->str;
 		iovec[1].iov_len = htp_max;
-		iovec[2].iov_base = dataptr;
+		iovec[2].iov_base = sd;
-		iovec[2].iov_len = max;
+		iovec[2].iov_len = sd_max;
+		iovec[3].iov_base = dataptr;
+		iovec[3].iov_len = max;
 
 		msghdr.msg_name = (struct sockaddr *)&logsrv->addr;
 		msghdr.msg_namelen = get_addr_len(&logsrv->addr);
@@ -1942,6 +1971,7 @@ void strm_log(struct stream *s)
 {
 	struct session *sess = s->sess;
 	int size, err, level;
+	int sd_size = 0;
 
 	/* if we don't want to log normal traffic, return now */
 	err = (s->flags & SF_REDISP) ||
@@ -1975,10 +2005,15 @@ void strm_log(struct stream *s)
 			build_logline(s, s->unique_id, UNIQUEID_LEN, &sess->fe->format_unique_id);
 	}
 
+	if (!LIST_ISEMPTY(&sess->fe->logformat_sd)) {
+		sd_size = build_logline(s, logline_rfc5424, global.max_syslog_len,
+		                        &sess->fe->logformat_sd);
+	}
+
 	size = build_logline(s, logline, global.max_syslog_len, &sess->fe->logformat);
 	if (size > 0) {
 		sess->fe->log_count++;
-		__send_log(sess->fe, level, logline, size + 1);
+		__send_log(sess->fe, level, logline, size + 1, logline_rfc5424, sd_size);
 		s->logs.logwait = 0;
 	}
 }

src/proxy.c

@@ -741,6 +741,7 @@ void init_new_proxy(struct proxy *p)
 	LIST_INIT(&p->listener_queue);
 	LIST_INIT(&p->logsrvs);
 	LIST_INIT(&p->logformat);
+	LIST_INIT(&p->logformat_sd);
 	LIST_INIT(&p->format_unique_id);
 	LIST_INIT(&p->conf.bind);
 	LIST_INIT(&p->conf.listeners);

src/sample.c

@@ -1103,16 +1103,17 @@ int smp_resolve_args(struct proxy *p)
 		where = "in";
 		ctx = "sample fetch keyword";
 		switch (cur->ctx) {
-		case ARGC_STK: where = "in stick rule in"; break;
+		case ARGC_STK:   where = "in stick rule in"; break;
-		case ARGC_TRK: where = "in tracking rule in"; break;
+		case ARGC_TRK:   where = "in tracking rule in"; break;
-		case ARGC_LOG: where = "in log-format string in"; break;
+		case ARGC_LOG:   where = "in log-format string in"; break;
-		case ARGC_HRQ: where = "in http-request header format string in"; break;
+		case ARGC_LOGSD: where = "in log-format-sd string in"; break;
-		case ARGC_HRS: where = "in http-response header format string in"; break;
+		case ARGC_HRQ:   where = "in http-request header format string in"; break;
-		case ARGC_UIF: where = "in unique-id-format string in"; break;
+		case ARGC_HRS:   where = "in http-response header format string in"; break;
-		case ARGC_RDR: where = "in redirect format string in"; break;
+		case ARGC_UIF:   where = "in unique-id-format string in"; break;
-		case ARGC_CAP: where = "in capture rule in"; break;
+		case ARGC_RDR:   where = "in redirect format string in"; break;
-		case ARGC_ACL: ctx = "ACL keyword"; break;
+		case ARGC_CAP:   where = "in capture rule in"; break;
-		case ARGC_SRV: where = "in server directive in"; break;
+		case ARGC_ACL:   ctx = "ACL keyword"; break;
+		case ARGC_SRV:   where = "in server directive in"; break;
 		}
 
 		/* set a few default settings */