os/log: only write timestamp if a message is actually written to logfile

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@chromium.org>
Reviewed-by: Peter Hutterer <peter.hutterer@who-t.net>
Signed-off-by: Peter Hutterer <peter.hutterer@who-t.net>
(cherry picked from commit 6ce0eac4f8a05f6d7401445cab95027709d3a479)

1 files changed, 9 insertions, 9 deletions

diff --git a/os/log.c b/os/log.c
index 297b46a44..b79030604 100644
--- a/os/log.c
+++ b/os/log.c
@@ -273,12 +273,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
@@ -286,14 +282,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);