BUG/CRITICAL: log: fix risk of crash in development snapshot

Commit a1cc38 introduced a regression which was easy to trigger till ad4cd58
(snapshots 20120222 to 20120311 included). The bug was still present after
that but harder to trigger.

The bug is caused by the use of two distinct log buffers due to intermediary
changes. The issue happens when an HTTP request is logged just after a TCP
request during the same second and the HTTP request is too large for the buffer.
In this case, it happens that the HTTP request is logged into the TCP buffer
instead and that length controls can't detect anything.

Starting with bddd4f, the issue is still possible when logging too large an
HTTP request just after a send_log() call (typically a server status change).

We owe a big thanks to Sander Klein for testing several snapshots and more
specifically for taking significant risks in production by letting the buggy
version crash several times in order to provide an exploitable core ! The bug
could not have been found without this precious help. Thank you Sander !

This fix does not need to be backported, it did not affect any released version.

diff --git a/include/proto/log.h b/include/proto/log.h
index 43c84becdb16e7d5480741ab9011a220b92e27fa..0ee60a00dd52697b4adeb09875959f125e1a0585 100644 (file)
--- a/include/proto/log.h
+++ b/include/proto/log.h
@@ -88,9 +88,6 @@ void Warning(const char *fmt, ...)
 void qfprintf(FILE *out, const char *fmt, ...)
        __attribute__ ((format(printf, 2, 3)));
 
-/* generate the syslog header one time per second */
-char *hdr_log(char *dst);
-
 /*
  * This function adds a header to the message and sends the syslog message
  * using a printf format string

diff --git a/src/log.c b/src/log.c
index 4ef51e1e9abfa671272d72c59080a788c07237a0..f09529735562962260d05a0f3d0db4616ce8d7e0 100644 (file)
--- a/src/log.c
+++ b/src/log.c
@@ -106,6 +106,11 @@ char clf_http_log_format[] = "%{+Q}o %{-Q}Ci - - [%T] %r %st %B \"\" \"\" %Cp %m
 char default_tcp_log_format[] = "%Ci:%Cp [%t] %f %b/%s %Tw/%Tc/%Tt %B %ts %ac/%fc/%bc/%sc/%rc %sq/%bq";
 char *log_format = NULL;
 
+/* This is a global syslog line, common to all outgoing messages. It begins
+ * with the syslog tag and the date that are updated by update_log_hdr().
+ */
+static char logline[MAX_SYSLOG_LEN];
+
 struct logformat_var_args {
        char *name;
        int mask;
@@ -515,21 +520,23 @@ char *logformat_write_string(char *dst, char *src, size_t size, struct logformat
        return dst;
 }
 
-/* generate the syslog header once a second */
-char *hdr_log(char *dst)
+/* Re-generate the syslog header at the beginning of logline once a second and
+ * return the pointer to the first character after the header.
+ */
+static char *update_log_hdr()
 {
-       int hdr_len = 0;
-       static long tvsec = -1; /* to force the string to be initialized */
-       static char *dataptr = NULL;
+       static long tvsec;
+       static char *dataptr = NULL; /* backup of last end of header, NULL first time */
 
        if (unlikely(date.tv_sec != tvsec || dataptr == NULL)) {
                /* this string is rebuild only once a second */
                struct tm tm;
+               int hdr_len;
 
                tvsec = date.tv_sec;
                get_localtime(tvsec, &tm);
 
-               hdr_len = snprintf(dst, MAX_SYSLOG_LEN,
+               hdr_len = snprintf(logline, MAX_SYSLOG_LEN,
                                   "<<<<>%s %2d %02d:%02d:%02d %s%s[%d]: ",
                                   monthname[tm.tm_mon],
                                   tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
@@ -542,7 +549,7 @@ char *hdr_log(char *dst)
                if (hdr_len < 0 || hdr_len > MAX_SYSLOG_LEN)
                        hdr_len = MAX_SYSLOG_LEN;
 
-               dataptr = dst + hdr_len;
+               dataptr = logline + hdr_len;
        }
 
        return dataptr;
@@ -555,23 +562,22 @@ char *hdr_log(char *dst)
 void send_log(struct proxy *p, int level, const char *format, ...)
 {
        va_list argp;
-       static char logmsg[MAX_SYSLOG_LEN];
-       static char *dataptr = NULL;
-       int  data_len = 0;
+       char *dataptr;
+       int  data_len;
 
        if (level < 0 || format == NULL)
                return;
 
-       dataptr = hdr_log(logmsg); /* create header */
-       data_len = dataptr - logmsg;
+       dataptr = update_log_hdr(); /* update log header and skip it */
+       data_len = dataptr - logline;
 
        va_start(argp, format);
-       data_len += vsnprintf(dataptr, MAX_SYSLOG_LEN, format, argp);
+       data_len += vsnprintf(dataptr, logline + sizeof(logline) - dataptr, format, argp);
        if (data_len < 0 || data_len > MAX_SYSLOG_LEN)
                data_len =  MAX_SYSLOG_LEN;
        va_end(argp);
 
-       __send_log(p, level, logmsg, data_len);
+       __send_log(p, level, logline, data_len);
 }
 
 /*
@@ -713,8 +719,7 @@ void sess_log(struct session *s)
        int t_request;
        int hdr;
        int last_isspace = 1;
-       static char logline[MAX_SYSLOG_LEN] = { 0 };
-       static char *tmplog;
+       char *tmplog;
        struct logformat_node *tmp;
 
        /* if we don't want to log normal traffic, return now */
@@ -763,8 +768,7 @@ void sess_log(struct session *s)
 
        /* fill logbuffer */
 
-       tmplog = logline;
-       tmplog = hdr_log(tmplog);
+       tmplog = update_log_hdr(); /* update log header and skip it */
 
        list_for_each_entry(tmp, &fe->logformat, list) {
                char *src = NULL;