From 43885c728e7f90f6295a195076833b64ff9bb3fb Mon Sep 17 00:00:00 2001 From: Dragan Dosen Date: Thu, 1 Oct 2015 13:18:13 +0200 Subject: [PATCH] BUG/MEDIUM: logs: segfault writing to log from Lua Michael Ezzell reported a bug causing haproxy to segfault during startup when trying to send syslog message from Lua. The function __send_log() can be called with *p that is NULL and/or when the configuration is not fully parsed, as is the case with Lua. This patch fixes this problem by using individual vectors instead of the pre-generated strings log_htp and log_htp_rfc5424. Also, this patch fixes a problem causing haproxy to write the wrong pid in the logs -- the log_htp(_rfc5424) strings were generated at the haproxy start, but "pid" value would be changed after haproxy is started in daemon/systemd mode. --- include/proto/log.h | 5 -- include/types/global.h | 2 +- include/types/log.h | 2 +- include/types/proxy.h | 4 +- src/cfgparse.c | 62 +++------------ src/haproxy.c | 6 +- src/log.c | 169 +++++++++++++++++++++++++++-------------- 7 files changed, 127 insertions(+), 123 deletions(-) diff --git a/include/proto/log.h b/include/proto/log.h index dcc5ae4b9..02e01f7e5 100644 --- a/include/proto/log.h +++ b/include/proto/log.h @@ -148,11 +148,6 @@ char *lf_ip(char *dst, struct sockaddr *sockaddr, size_t size, struct logformat_ */ char *lf_port(char *dst, struct sockaddr *sockaddr, size_t size, struct logformat_node *node); -/* - * Write hostname, log_tag and pid to the log string - */ -char *lf_host_tag_pid(char *dst, int format, const char *hostname, const char *log_tag, int pid, size_t size); - #endif /* _PROTO_LOG_H */ diff --git a/include/types/global.h b/include/types/global.h index ea5c387d6..ca96193df 100644 --- a/include/types/global.h +++ b/include/types/global.h @@ -126,7 +126,7 @@ struct global { char *chroot; char *pidfile; char *node, *desc; /* node name & description */ - char *log_tag; /* name for syslog */ + struct chunk log_tag; /* name for syslog */ struct list logsrvs; char *log_send_hostname; /* set hostname in syslog header */ char *server_state_base; /* path to a directory where server state files can be found */ diff --git a/include/types/log.h b/include/types/log.h index 411ba8ffa..35c1228aa 100644 --- a/include/types/log.h +++ b/include/types/log.h @@ -30,7 +30,7 @@ #define NB_LOG_FACILITIES 24 #define NB_LOG_LEVELS 8 -#define NB_MSG_IOVEC_ELEMENTS 5 +#define NB_MSG_IOVEC_ELEMENTS 8 #define SYSLOG_PORT 514 #define UNIQUEID_LEN 128 diff --git a/include/types/proxy.h b/include/types/proxy.h index 49debc628..e18ae72ee 100644 --- a/include/types/proxy.h +++ b/include/types/proxy.h @@ -346,9 +346,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 */ - 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) */ + struct chunk log_tag; /* override default syslog tag */ char *header_unique_id; /* unique-id header */ struct list format_unique_id; /* unique-id format */ int to_log; /* things to be logged (LW_*) */ diff --git a/src/cfgparse.c b/src/cfgparse.c index 6958a1d24..bc7cd9468 100644 --- a/src/cfgparse.c +++ b/src/cfgparse.c @@ -1659,7 +1659,6 @@ int cfg_parse_global(const char *file, int linenum, char **args, int kwm) else name = hostname; - /* We'll add a space after the name to respect the log format */ free(global.log_send_hostname); global.log_send_hostname = strdup(name); } @@ -1701,8 +1700,8 @@ int cfg_parse_global(const char *file, int linenum, char **args, int kwm) err_code |= ERR_ALERT | ERR_FATAL; goto out; } - free(global.log_tag); - global.log_tag = strdup(args[1]); + chunk_destroy(&global.log_tag); + chunk_initstr(&global.log_tag, strdup(args[1])); } else if (!strcmp(args[0], "spread-checks")) { /* random time between checks (0-50) */ if (alertif_too_many_args(1, file, linenum, args, &err_code)) @@ -2760,8 +2759,7 @@ int cfg_parse_listen(const char *file, int linenum, char **args, int kwm) if (curproxy->conf.uniqueid_format_string) curproxy->conf.uniqueid_format_string = strdup(curproxy->conf.uniqueid_format_string); - if (defproxy.log_tag) - curproxy->log_tag = strdup(defproxy.log_tag); + chunk_dup(&curproxy->log_tag, &defproxy.log_tag); if (defproxy.conf.uif_file) { curproxy->conf.uif_file = strdup(defproxy.conf.uif_file); @@ -2843,7 +2841,7 @@ int cfg_parse_listen(const char *file, int linenum, char **args, int kwm) free(defproxy.conf.uniqueid_format_string); free(defproxy.conf.lfs_file); free(defproxy.conf.uif_file); - free(defproxy.log_tag); + chunk_destroy(&defproxy.log_tag); free_email_alert(&defproxy); if (defproxy.conf.logformat_sd_string != default_rfc5424_sd_log_format) @@ -5852,8 +5850,8 @@ stats_error_parsing: err_code |= ERR_ALERT | ERR_FATAL; goto out; } - free(curproxy->log_tag); - curproxy->log_tag = strdup(args[1]); + chunk_destroy(&curproxy->log_tag); + chunk_initstr(&curproxy->log_tag, strdup(args[1])); } else if (!strcmp(args[0], "log") && kwm == KWM_NO) { /* delete previous herited or defined syslog servers */ @@ -7889,52 +7887,16 @@ int check_config_validity() } out_uri_auth_compat: - /* write a syslog header string that contains hostname, log_tag and pid */ + /* check whether we have a log server that uses RFC5424 log format */ list_for_each_entry(tmplogsrv, &curproxy->logsrvs, list) { - char *hdr; - struct chunk *htp; - char *host = global.log_send_hostname; - - switch (tmplogsrv->format) { - case LOG_FORMAT_RFC3164: - hdr = logheader; - htp = &curproxy->log_htp; - host = host ? host : ""; + if (tmplogsrv->format == LOG_FORMAT_RFC5424) { + if (!curproxy->conf.logformat_sd_string) { + /* set the default logformat_sd_string */ + curproxy->conf.logformat_sd_string = default_rfc5424_sd_log_format; + } break; - - case LOG_FORMAT_RFC5424: - hdr = logheader_rfc5424; - htp = &curproxy->log_htp_rfc5424; - host = host ? host : hostname; - break; - - default: - continue; /* must never happen */ } - - if (htp->str) - continue; - - htp->str = lf_host_tag_pid(hdr, tmplogsrv->format, host, - curproxy->log_tag ? curproxy->log_tag : global.log_tag, - pid, global.max_syslog_len); - - if ((htp->str == NULL) || - ((htp->len = htp->str - hdr) >= global.max_syslog_len)) { - Alert("Proxy '%s': cannot write a syslog header string that contains " - "hostname, log_tag and pid.\n", - curproxy->id); - cfgerr++; - goto out_host_tag_pid; - } - - htp->str = (char *)malloc(htp->len); - memcpy(htp->str, hdr, htp->len); - htp->size = 0; - - hdr[0] = 0; } -out_host_tag_pid: /* compile the log format */ if (!(curproxy->cap & PR_CAP_FE)) { diff --git a/src/haproxy.c b/src/haproxy.c index ebc717714..c2768fc7f 100644 --- a/src/haproxy.c +++ b/src/haproxy.c @@ -626,7 +626,7 @@ void init(int argc, char **argv) progname = tmp + 1; /* the process name is used for the logs only */ - global.log_tag = strdup(progname); + chunk_initstr(&global.log_tag, strdup(progname)); argc--; argv++; while (argc > 0) { @@ -1335,8 +1335,6 @@ void deinit(void) LIST_DEL(&log->list); free(log); } - chunk_destroy(&p->log_htp); - chunk_destroy(&p->log_htp_rfc5424); list_for_each_entry_safe(lf, lfb, &p->logformat, list) { LIST_DEL(&lf->list); @@ -1478,7 +1476,7 @@ void deinit(void) #endif free(global.log_send_hostname); global.log_send_hostname = NULL; - free(global.log_tag); global.log_tag = NULL; + chunk_destroy(&global.log_tag); free(global.chroot); global.chroot = NULL; free(global.pidfile); global.pidfile = NULL; free(global.node); global.node = NULL; diff --git a/src/log.c b/src/log.c index 19aac114b..6556ab6fb 100644 --- a/src/log.c +++ b/src/log.c @@ -41,9 +41,29 @@ #include #endif -const char *log_formats[LOG_FORMATS] = { - [LOG_FORMAT_RFC3164] = "rfc3164", - [LOG_FORMAT_RFC5424] = "rfc5424" +struct log_fmt { + char *name; + struct { + struct chunk sep1; /* first pid separator */ + struct chunk sep2; /* second pid separator */ + } pid; +}; + +static const struct log_fmt log_formats[LOG_FORMATS] = { + [LOG_FORMAT_RFC3164] = { + .name = "rfc3164", + .pid = { + .sep1 = { .str = "[", .len = 1 }, + .sep2 = { .str = "]: ", .len = 3 } + } + }, + [LOG_FORMAT_RFC5424] = { + .name = "rfc5424", + .pid = { + .sep1 = { .str = " ", .len = 1 }, + .sep2 = { .str = " - ", .len = 3 } + } + } }; const char *log_facilities[NB_LOG_FACILITIES] = { @@ -155,12 +175,6 @@ 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. - */ -static char default_host_tag_pid_log_format[] = "%s%s%s[%d]: "; -static char rfc5424_host_tag_pid_log_format[] = "%s%s%s %d - "; - /* Default string used for structured-data part in RFC5424 formatted * syslog messages. */ @@ -653,7 +667,7 @@ int get_log_format(const char *fmt) int format; format = LOG_FORMATS - 1; - while (format >= 0 && strcmp(log_formats[format], fmt)) + while (format >= 0 && strcmp(log_formats[format].name, fmt)) format--; return format; @@ -780,33 +794,6 @@ char *lf_port(char *dst, struct sockaddr *sockaddr, size_t size, struct logforma return ret; } -char *lf_host_tag_pid(char *dst, int format, const char *hostname, const char *log_tag, int pid, size_t size) -{ - char *ret = dst; - char *fmt; - int iret; - - switch (format) { - case LOG_FORMAT_RFC3164: - fmt = default_host_tag_pid_log_format; - break; - - case LOG_FORMAT_RFC5424: - fmt = rfc5424_host_tag_pid_log_format; - break; - - default: - return NULL; - } - - iret = snprintf(dst, size, fmt, hostname, strlen(hostname) ? " " : "", log_tag, pid); - if (iret < 0 || iret > size) - return NULL; - ret += iret; - - return ret; -} - /* Re-generate time-based part of the syslog header in RFC3164 format at * the beginning of logheader once a second and return the pointer to the * first character after it. @@ -815,6 +802,8 @@ 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 */ + static struct chunk host = { NULL, 0, 0 }; + static int sep = 0; if (unlikely(time != tvsec || dataptr == NULL)) { /* this string is rebuild only once a second */ @@ -824,10 +813,17 @@ static char *update_log_hdr(const time_t time) tvsec = time; get_localtime(tvsec, &tm); + if (unlikely(global.log_send_hostname != host.str)) { + host.str = global.log_send_hostname; + host.len = host.str ? strlen(host.str) : 0; + sep = host.len ? 1 : 0; + } + hdr_len = snprintf(logheader, global.max_syslog_len, - "<<<<>%s %2d %02d:%02d:%02d ", + "<<<<>%s %2d %02d:%02d:%02d %.*s%*s", monthname[tm.tm_mon], - tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec); + tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, + host.len, host.str, sep, ""); /* WARNING: depending upon implementations, snprintf may return * either -1 or the number of bytes that would be needed to store * the total message. In both cases, we must adjust it. @@ -861,10 +857,10 @@ static char *update_log_hdr_rfc5424(const time_t time) get_localtime(tvsec, &tm); hdr_len = snprintf(logheader_rfc5424, global.max_syslog_len, - "<<<<>1 %4d-%02d-%02dT%02d:%02d:%02d%s ", + "<<<<>1 %4d-%02d-%02dT%02d:%02d:%02d%s %s ", tm.tm_year+1900, tm.tm_mon+1, tm.tm_mday, - tm.tm_hour, tm.tm_min, tm.tm_sec, - localtimezone); + tm.tm_hour, tm.tm_min, tm.tm_sec, localtimezone, + global.log_send_hostname ? global.log_send_hostname : hostname); /* WARNING: depending upon implementations, snprintf may return * either -1 or the number of bytes that would be needed to store * the total message. In both cases, we must adjust it. @@ -924,8 +920,11 @@ void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd int nblogger; char *hdr, *hdr_ptr; size_t hdr_size; - struct chunk *htp; time_t time = date.tv_sec; + struct chunk *tag = &global.log_tag; + static int curr_pid; + static char pidstr[100]; + static struct chunk pid; dataptr = message; @@ -937,21 +936,34 @@ void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd if (!LIST_ISEMPTY(&p->logsrvs)) { logsrvs = &p->logsrvs; } + if (p->log_tag.str) { + tag = &p->log_tag; + } } if (!logsrvs) return; + if (unlikely(curr_pid != getpid())) { + curr_pid = getpid(); + ltoa_o(curr_pid, pidstr, sizeof(pidstr)); + chunk_initstr(&pid, pidstr); + } + /* Send log messages to syslog server. */ nblogger = 0; list_for_each_entry(tmp, logsrvs, list) { const struct logsrv *logsrv = tmp; int *plogfd = logsrv->addr.ss_family == AF_UNIX ? &logfdunix : &logfdinet; + char *pid_sep1 = NULL, *pid_sep2 = NULL; int sent; int maxlen; int hdr_max = 0; - int htp_max = 0; + int tag_max = 0; + int pid_sep1_max = 0; + int pid_max = 0; + int pid_sep2_max = 0; int sd_max = 0; int max = 0; @@ -980,13 +992,11 @@ void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd case LOG_FORMAT_RFC3164: hdr = logheader; hdr_ptr = update_log_hdr(time); - htp = &p->log_htp; break; case LOG_FORMAT_RFC5424: hdr = logheader_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; @@ -1014,6 +1024,7 @@ void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd hdr_max = hdr_size - (hdr_ptr - hdr); + /* time-based header */ if (unlikely(hdr_size >= logsrv->maxlen)) { hdr_max = MIN(hdr_max, logsrv->maxlen) - 1; sd_max = 0; @@ -1022,15 +1033,49 @@ void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd maxlen = logsrv->maxlen - hdr_max; - if (unlikely(htp->len >= maxlen)) { - htp_max = maxlen - 1; + /* tag */ + tag_max = tag->len; + if (unlikely(tag_max >= maxlen)) { + tag_max = maxlen - 1; sd_max = 0; goto send; } - htp_max = htp->len; - maxlen -= htp_max; + maxlen -= tag_max; + /* first pid separator */ + pid_sep1_max = log_formats[logsrv->format].pid.sep1.len; + if (unlikely(pid_sep1_max >= maxlen)) { + pid_sep1_max = maxlen - 1; + sd_max = 0; + goto send; + } + + pid_sep1 = log_formats[logsrv->format].pid.sep1.str; + maxlen -= pid_sep1_max; + + /* pid */ + pid_max = pid.len; + if (unlikely(pid_max >= maxlen)) { + pid_max = maxlen - 1; + sd_max = 0; + goto send; + } + + maxlen -= pid_max; + + /* second pid separator */ + pid_sep2_max = log_formats[logsrv->format].pid.sep2.len; + if (unlikely(pid_sep2_max >= maxlen)) { + pid_sep2_max = maxlen - 1; + sd_max = 0; + goto send; + } + + pid_sep2 = log_formats[logsrv->format].pid.sep2.str; + maxlen -= pid_sep2_max; + + /* structured-data */ if (sd_max >= maxlen) { sd_max = maxlen - 1; goto send; @@ -1039,15 +1084,21 @@ void __send_log(struct proxy *p, int level, char *message, size_t size, char *sd max = MIN(size, maxlen - sd_max) - 1; send: iovec[0].iov_base = hdr_ptr; - iovec[0].iov_len = hdr_max; - iovec[1].iov_base = htp->str; - iovec[1].iov_len = htp_max; - iovec[2].iov_base = sd; - iovec[2].iov_len = sd_max; - iovec[3].iov_base = dataptr; - iovec[3].iov_len = max; - iovec[4].iov_base = "\n"; /* insert a \n at the end of the message */ - iovec[4].iov_len = 1; + iovec[0].iov_len = hdr_max; + iovec[1].iov_base = tag->str; + iovec[1].iov_len = tag_max; + iovec[2].iov_base = pid_sep1; + iovec[2].iov_len = pid_sep1_max; + iovec[3].iov_base = pid.str; + iovec[3].iov_len = pid_max; + iovec[4].iov_base = pid_sep2; + iovec[4].iov_len = pid_sep2_max; + iovec[5].iov_base = sd; + iovec[5].iov_len = sd_max; + iovec[6].iov_base = dataptr; + iovec[6].iov_len = max; + iovec[7].iov_base = "\n"; /* insert a \n at the end of the message */ + iovec[7].iov_len = 1; msghdr.msg_name = (struct sockaddr *)&logsrv->addr; msghdr.msg_namelen = get_addr_len(&logsrv->addr);