Patchwork [4/4] os/log: refactor logging

login
register
mail settings
Submitter Daniel Kurtz
Date April 18, 2012, 9:51 a.m.
Message ID <1334742713-26570-5-git-send-email-djkurtz@chromium.org>
Download mbox | patch
Permalink /patch/10001/
State Accepted
Commit c91d00e0f330b9de604068e1bfcb0a307096434f
Headers show

Comments

Daniel Kurtz - April 18, 2012, 9:51 a.m.
It is not safe to ever use an arbitrary (possibly user supplied) string as
part of the format for a *sprintf() call.

For example:
  1. Name a Bluetooth keyboard "%n%n%n%n%n%n%n%n"
  2. Pair it with a computer running X and try to use it
  3. X is not happy when trying to do the following in xf86-input-evdev:
     xf86IDrvMsg(pInfo, X_CONFIG, "Device: \"%s\"\n", device);
     because LogVHdrMessageVerb() has put the %n from the device name
     into a format string.

Instead, build up a log message in place by appending successive formatted
strings by sncprintf'ing to the end of the previous.

Signed-off-by: Daniel Kurtz <djkurtz@chromium.org>
---
 os/log.c |   97 +++++++++++++++++++++++++++++--------------------------------
 1 files changed, 46 insertions(+), 51 deletions(-)
Peter Hutterer - May 3, 2012, 3:38 a.m.
On Wed, Apr 18, 2012 at 05:51:53PM +0800, Daniel Kurtz wrote:
> It is not safe to ever use an arbitrary (possibly user supplied) string as
> part of the format for a *sprintf() call.
> 
> For example:
>   1. Name a Bluetooth keyboard "%n%n%n%n%n%n%n%n"
>   2. Pair it with a computer running X and try to use it
>   3. X is not happy when trying to do the following in xf86-input-evdev:
>      xf86IDrvMsg(pInfo, X_CONFIG, "Device: \"%s\"\n", device);
>      because LogVHdrMessageVerb() has put the %n from the device name
>      into a format string.
> 
> Instead, build up a log message in place by appending successive formatted
> strings by sncprintf'ing to the end of the previous.
> 
> Signed-off-by: Daniel Kurtz <djkurtz@chromium.org>

verified and all 4 merged, thanks. took me a while to find the actual issue
because I was looking in the wrong place. for the archives: The culprit here
was not the user-supplied format string but rather xf86IDrvMsg using the
device's name, assembling a format string in the form of
    <driver>: <name>: message
i.e.
    "evdev: %n%n%n%n: Device \"%s\"\n"
and using that as format string to LogVWrite.

Cheers,
  Peter

> ---
>  os/log.c |   97 +++++++++++++++++++++++++++++--------------------------------
>  1 files changed, 46 insertions(+), 51 deletions(-)
> 
> diff --git a/os/log.c b/os/log.c
> index 36378e4..2c13c1a 100644
> --- a/os/log.c
> +++ b/os/log.c
> @@ -268,36 +268,19 @@ LogSetParameter(LogParameter param, int value)
>  }
>  
>  /* This function does the actual log message writes. */
> -
> -void
> -LogVWrite(int verb, const char *f, va_list args)
> +static void
> +LogSWrite(int verb, const char *buf, size_t len, Bool end_line)
>  {
> -    static char tmpBuffer[1024];
> -    int len = 0;
>      static Bool newline = TRUE;
>  
> -    if (verb > logFileVerbosity && verb > logVerbosity)
> -        return;
> -
> -    /*
> -     * Since a va_list can only be processed once, write the string to a
> -     * buffer, and then write the buffer out to the appropriate output
> -     * stream(s).
> -     */
> -    if (verb < 0 || logFileVerbosity >= verb || logVerbosity >= verb) {
> -        len = Xvscnprintf(tmpBuffer, sizeof(tmpBuffer), f, args);
> -        /* If message is truncated, terminate with '\n' */
> -        if (sizeof(tmpBuffer) - len == 1)
> -            tmpBuffer[len - 1] = '\n';
> -    }
> -    if ((verb < 0 || logVerbosity >= verb) && len > 0)
> -        fwrite(tmpBuffer, len, 1, stderr);
> -    if ((verb < 0 || logFileVerbosity >= verb) && len > 0) {
> +    if (verb < 0 || logVerbosity >= verb)
> +        fwrite(buf, len, 1, stderr);
> +    if (verb < 0 || logFileVerbosity >= verb) {
>          if (logFile) {
>              if (newline)
>                  fprintf(logFile, "[%10.3f] ", GetTimeInMillis() / 1000.0);
> -            newline = (tmpBuffer[len - 1] == '\n');
> -            fwrite(tmpBuffer, len, 1, logFile);
> +            newline = end_line;
> +            fwrite(buf, len, 1, logFile);
>              if (logFlush) {
>                  fflush(logFile);
>  #ifndef WIN32
> @@ -315,13 +298,19 @@ LogVWrite(int verb, const char *f, va_list args)
>                      FatalError("realloc() failed while saving log messages\n");
>              }
>              bufferUnused -= len;
> -            memcpy(saveBuffer + bufferPos, tmpBuffer, len);
> +            memcpy(saveBuffer + bufferPos, buf, len);
>              bufferPos += len;
>          }
>      }
>  }
>  
>  void
> +LogVWrite(int verb, const char *f, va_list args)
> +{
> +    return LogVMessageVerb(X_NONE, verb, f, args);
> +}
> +
> +void
>  LogWrite(int verb, const char *f, ...)
>  {
>      va_list args;
> @@ -376,22 +365,28 @@ void
>  LogVMessageVerb(MessageType type, int verb, const char *format, va_list args)
>  {
>      const char *type_str;
> -    char tmpFormat[1024];
> -    const char *new_format;
> +    char buf[1024];
> +    const size_t size = sizeof(buf);
> +    Bool newline;
> +    size_t len = 0;
>  
>      type_str = LogMessageTypeVerbString(type, verb);
>      if (!type_str)
>          return;
>  
> -    /* if type_str is not "", prepend it and ' ', to format */
> -    if (type_str[0] == '\0')
> -        new_format = format;
> -    else {
> -        new_format = tmpFormat;
> -        snprintf(tmpFormat, sizeof(tmpFormat), "%s %s", type_str, format);
> -    }
> +    /* if type_str is not "", prepend it and ' ', to message */
> +    if (type_str[0] != '\0')
> +        len += Xscnprintf(&buf[len], size - len, "%s ", type_str);
> +
> +    if (size - len > 1)
> +        len += Xvscnprintf(&buf[len], size - len, format, args);
> +
> +    /* Force '\n' at end of truncated line */
> +    if (size - len == 1)
> +        buf[len - 1] = '\n';
>  
> -    LogVWrite(verb, new_format, args);
> +    newline = (buf[len - 1] == '\n');
> +    LogSWrite(verb, buf, len, newline);
>  }
>  
>  /* Log message with verbosity level specified. */
> @@ -421,31 +416,31 @@ LogVHdrMessageVerb(MessageType type, int verb, const char *msg_format,
>                     va_list msg_args, const char *hdr_format, va_list hdr_args)
>  {
>      const char *type_str;
> -    char tmpFormat[1024];
> -    char *tmpFormat_end = &tmpFormat[sizeof(tmpFormat)];
> -    char *p;
> -    int left;
> +    char buf[1024];
> +    const size_t size = sizeof(buf);
> +    Bool newline;
> +    size_t len = 0;
>  
>      type_str = LogMessageTypeVerbString(type, verb);
>      if (!type_str)
>          return;
>  
> -    /* if type_str != "", copy it and ' ' to tmpFormat; set p after ' ' */
> -    p = tmpFormat;
> +    /* if type_str is not "", prepend it and ' ', to message */
>      if (type_str[0] != '\0')
> -        p += snprintf(tmpFormat, sizeof(tmpFormat), "%s ", type_str);
> +        len += Xscnprintf(&buf[len], size - len, "%s ", type_str);
> +
> +    if (hdr_format && size - len > 1)
> +        len += Xvscnprintf(&buf[len], size - len, hdr_format, hdr_args);
>  
> -    /* append as much of hdr as fits after type_str (if there was one) */
> -    left = tmpFormat_end - p;
> -    if (left > 1)
> -        p += vsnprintf(p, left, hdr_format, hdr_args);
> +    if (msg_format && size - len > 1)
> +        len += Xvscnprintf(&buf[len], size - len, msg_format, msg_args);
>  
> -    /* append as much of msg_format as will fit after hdr */
> -    left = tmpFormat_end - p;
> -    if (left > 1)
> -        snprintf(p, left, "%s", msg_format);
> +    /* Force '\n' at end of truncated line */
> +    if (size - len == 1)
> +        buf[len - 1] = '\n';
>  
> -    LogVWrite(verb, tmpFormat, msg_args);
> +    newline = (buf[len - 1] == '\n');
> +    LogSWrite(verb, buf, len, newline);
>  }
>  
>  void
> -- 
> 1.7.7.3
>

Patch

diff --git a/os/log.c b/os/log.c
index 36378e4..2c13c1a 100644
--- a/os/log.c
+++ b/os/log.c
@@ -268,36 +268,19 @@  LogSetParameter(LogParameter param, int value)
 }
 
 /* This function does the actual log message writes. */
-
-void
-LogVWrite(int verb, const char *f, va_list args)
+static void
+LogSWrite(int verb, const char *buf, size_t len, Bool end_line)
 {
-    static char tmpBuffer[1024];
-    int len = 0;
     static Bool newline = TRUE;
 
-    if (verb > logFileVerbosity && verb > logVerbosity)
-        return;
-
-    /*
-     * Since a va_list can only be processed once, write the string to a
-     * buffer, and then write the buffer out to the appropriate output
-     * stream(s).
-     */
-    if (verb < 0 || logFileVerbosity >= verb || logVerbosity >= verb) {
-        len = Xvscnprintf(tmpBuffer, sizeof(tmpBuffer), f, args);
-        /* If message is truncated, terminate with '\n' */
-        if (sizeof(tmpBuffer) - len == 1)
-            tmpBuffer[len - 1] = '\n';
-    }
-    if ((verb < 0 || logVerbosity >= verb) && len > 0)
-        fwrite(tmpBuffer, len, 1, stderr);
-    if ((verb < 0 || logFileVerbosity >= verb) && len > 0) {
+    if (verb < 0 || logVerbosity >= verb)
+        fwrite(buf, len, 1, stderr);
+    if (verb < 0 || logFileVerbosity >= verb) {
         if (logFile) {
             if (newline)
                 fprintf(logFile, "[%10.3f] ", GetTimeInMillis() / 1000.0);
-            newline = (tmpBuffer[len - 1] == '\n');
-            fwrite(tmpBuffer, len, 1, logFile);
+            newline = end_line;
+            fwrite(buf, len, 1, logFile);
             if (logFlush) {
                 fflush(logFile);
 #ifndef WIN32
@@ -315,13 +298,19 @@  LogVWrite(int verb, const char *f, va_list args)
                     FatalError("realloc() failed while saving log messages\n");
             }
             bufferUnused -= len;
-            memcpy(saveBuffer + bufferPos, tmpBuffer, len);
+            memcpy(saveBuffer + bufferPos, buf, len);
             bufferPos += len;
         }
     }
 }
 
 void
+LogVWrite(int verb, const char *f, va_list args)
+{
+    return LogVMessageVerb(X_NONE, verb, f, args);
+}
+
+void
 LogWrite(int verb, const char *f, ...)
 {
     va_list args;
@@ -376,22 +365,28 @@  void
 LogVMessageVerb(MessageType type, int verb, const char *format, va_list args)
 {
     const char *type_str;
-    char tmpFormat[1024];
-    const char *new_format;
+    char buf[1024];
+    const size_t size = sizeof(buf);
+    Bool newline;
+    size_t len = 0;
 
     type_str = LogMessageTypeVerbString(type, verb);
     if (!type_str)
         return;
 
-    /* if type_str is not "", prepend it and ' ', to format */
-    if (type_str[0] == '\0')
-        new_format = format;
-    else {
-        new_format = tmpFormat;
-        snprintf(tmpFormat, sizeof(tmpFormat), "%s %s", type_str, format);
-    }
+    /* if type_str is not "", prepend it and ' ', to message */
+    if (type_str[0] != '\0')
+        len += Xscnprintf(&buf[len], size - len, "%s ", type_str);
+
+    if (size - len > 1)
+        len += Xvscnprintf(&buf[len], size - len, format, args);
+
+    /* Force '\n' at end of truncated line */
+    if (size - len == 1)
+        buf[len - 1] = '\n';
 
-    LogVWrite(verb, new_format, args);
+    newline = (buf[len - 1] == '\n');
+    LogSWrite(verb, buf, len, newline);
 }
 
 /* Log message with verbosity level specified. */
@@ -421,31 +416,31 @@  LogVHdrMessageVerb(MessageType type, int verb, const char *msg_format,
                    va_list msg_args, const char *hdr_format, va_list hdr_args)
 {
     const char *type_str;
-    char tmpFormat[1024];
-    char *tmpFormat_end = &tmpFormat[sizeof(tmpFormat)];
-    char *p;
-    int left;
+    char buf[1024];
+    const size_t size = sizeof(buf);
+    Bool newline;
+    size_t len = 0;
 
     type_str = LogMessageTypeVerbString(type, verb);
     if (!type_str)
         return;
 
-    /* if type_str != "", copy it and ' ' to tmpFormat; set p after ' ' */
-    p = tmpFormat;
+    /* if type_str is not "", prepend it and ' ', to message */
     if (type_str[0] != '\0')
-        p += snprintf(tmpFormat, sizeof(tmpFormat), "%s ", type_str);
+        len += Xscnprintf(&buf[len], size - len, "%s ", type_str);
+
+    if (hdr_format && size - len > 1)
+        len += Xvscnprintf(&buf[len], size - len, hdr_format, hdr_args);
 
-    /* append as much of hdr as fits after type_str (if there was one) */
-    left = tmpFormat_end - p;
-    if (left > 1)
-        p += vsnprintf(p, left, hdr_format, hdr_args);
+    if (msg_format && size - len > 1)
+        len += Xvscnprintf(&buf[len], size - len, msg_format, msg_args);
 
-    /* append as much of msg_format as will fit after hdr */
-    left = tmpFormat_end - p;
-    if (left > 1)
-        snprintf(p, left, "%s", msg_format);
+    /* Force '\n' at end of truncated line */
+    if (size - len == 1)
+        buf[len - 1] = '\n';
 
-    LogVWrite(verb, tmpFormat, msg_args);
+    newline = (buf[len - 1] == '\n');
+    LogSWrite(verb, buf, len, newline);
 }
 
 void