[PATCH 3/4] os/log: only write timestamp if a message is actually written to logfile

[Daniel Kurtz]

The current code will write a timestamps into the logFile whenever
the last message ended with a '\n' - even if the verb for that timestamp
is at too high a level.  This timestamp will sit there with no matching
message until the next call to LogVWrite with a valid verb.

In other words, in some cases, timestamps in the X.org.log are for some
completely unrelated message that was previously ignored due to
insufficient verbosity, and not for the message that appears next to it
in the log file.

We keep the current policy which appears to be to only apply timestamps if
a message is actually written to a log file.  That is, no timestamps on
stderr, or in the mem buffer.  Therefore, the timestamp stringification
is moved to the conditional where it is used.

Since logging uses a fixed length buffer, this patch also forces a '\n'
whenever a buffer is terminated due to a too-long write request.  This
allows the newline detection to work even on overflow, and also cleans up
the log a bit in the overflow case.

Signed-off-by: Daniel Kurtz <djkurtz at chromium.org>
---
 os/log.c |   18 +++++++++---------
 1 files changed, 9 insertions(+), 9 deletions(-)

diff --git a/os/log.c b/os/log.c
index 92cb7aa..36378e4 100644
--- a/os/log.c
+++ b/os/log.c
@@ -276,12 +276,8 @@ LogVWrite(int verb, const char *f, va_list args)
     int len = 0;
     static Bool newline = TRUE;
 
-    if (newline) {
-        sprintf(tmpBuffer, "[%10.3f] ", GetTimeInMillis() / 1000.0);
-        len = strlen(tmpBuffer);
-        if (logFile)
-            fwrite(tmpBuffer, len, 1, logFile);
-    }
+    if (verb > logFileVerbosity && verb > logVerbosity)
+        return;
 
     /*
      * Since a va_list can only be processed once, write the string to a
@@ -289,14 +285,18 @@ LogVWrite(int verb, const char *f, va_list args)
      * stream(s).
      */
     if (verb < 0 || logFileVerbosity >= verb || logVerbosity >= verb) {
-        vsnprintf(tmpBuffer, sizeof(tmpBuffer), f, args);
-        len = strlen(tmpBuffer);
+        len = Xvscnprintf(tmpBuffer, sizeof(tmpBuffer), f, args);
+        /* If message is truncated, terminate with '\n' */
+        if (sizeof(tmpBuffer) - len == 1)
+            tmpBuffer[len - 1] = '\n';
     }
-    newline = (tmpBuffer[len - 1] == '\n');
     if ((verb < 0 || logVerbosity >= verb) && len > 0)
         fwrite(tmpBuffer, len, 1, stderr);
     if ((verb < 0 || logFileVerbosity >= verb) && len > 0) {
         if (logFile) {
+            if (newline)
+                fprintf(logFile, "[%10.3f] ", GetTimeInMillis() / 1000.0);
+            newline = (tmpBuffer[len - 1] == '\n');
             fwrite(tmpBuffer, len, 1, logFile);
             if (logFlush) {
                 fflush(logFile);
-- 
1.7.7.3