From c30862879d2c766519780bb7f353f35edf0daa9b Mon Sep 17 00:00:00 2001 From: Daniel Kurtz Date: Wed, 18 Apr 2012 17:51:50 +0800 Subject: [PATCH 1/4] os/log: trivial cleanups * space->tab * remove comment that doesn't make any sense Signed-off-by: Daniel Kurtz Reviewed-by: Peter Hutterer Signed-off-by: Peter Hutterer --- os/log.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/os/log.c b/os/log.c index 061b3dd61..92cb7aa24 100644 --- a/os/log.c +++ b/os/log.c @@ -168,7 +168,7 @@ asm(".desc ___crashreporter_info__, 0x10"); #define X_DEBUG_STRING "(DB)" #endif #ifndef X_NONE_STRING -#define X_NONE_STRING "" +#define X_NONE_STRING "" #endif /* @@ -226,7 +226,7 @@ LogInit(const char *fname, const char *backup) * needed. */ if (saveBuffer && bufferSize > 0) { - free(saveBuffer); /* Must be free(), not free() */ + free(saveBuffer); saveBuffer = NULL; bufferSize = 0; } From 5c2e2a164d615ab06be28a663734e782614b5cc7 Mon Sep 17 00:00:00 2001 From: Daniel Kurtz Date: Wed, 18 Apr 2012 09:51:51 +0000 Subject: [PATCH 2/4] os/xprintf: add Xvscnprintf and Xscnprintf Normal snprintf() usually returns the number of bytes that would have been written into a buffer had the buffer been long enough. The scnprintf() variants return the actual number of bytes written, excluding the trailing '\0'. Signed-off-by: Daniel Kurtz Reviewed-by: Peter Hutterer Signed-off-by: Peter Hutterer --- include/Xprintf.h | 12 ++++++++++++ os/xprintf.c | 44 ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 56 insertions(+) diff --git a/include/Xprintf.h b/include/Xprintf.h index 414fd46fb..9e8cdc5dc 100644 --- a/include/Xprintf.h +++ b/include/Xprintf.h @@ -66,4 +66,16 @@ _X_ATTRIBUTE_PRINTF(2, 0); #define vasprintf Xvasprintf #endif +/* + * These functions provide a portable implementation of the linux kernel + * scnprintf & vscnprintf routines that return the number of bytes actually + * copied during a snprintf, (excluding the final '\0'). + */ +extern _X_EXPORT int +Xscnprintf(char *s, int n, const char * _X_RESTRICT_KYWD fmt, ...) +_X_ATTRIBUTE_PRINTF(3,4); +extern _X_EXPORT int +Xvscnprintf(char *s, int n, const char * _X_RESTRICT_KYWD fmt, va_list va) +_X_ATTRIBUTE_PRINTF(3,0); + #endif /* XPRINTF_H */ diff --git a/os/xprintf.c b/os/xprintf.c index 17fea2ec7..80caa5790 100644 --- a/os/xprintf.c +++ b/os/xprintf.c @@ -186,6 +186,50 @@ XNFasprintf(char **ret, const char *_X_RESTRICT_KYWD format, ...) return size; } +/** + * Varargs snprintf that returns the actual number of bytes (excluding final + * '\0') that were copied into the buffer. + * This is opposed to the normal sprintf() usually returns the number of bytes + * that would have been written. + * + * @param s buffer to copy into + * @param n size of buffer s + * @param format printf style format string + * @param va variable argument list + * @return number of bytes actually copied, excluding final '\0' + */ +int +Xvscnprintf(char *s, int n, const char *format, va_list args) +{ + int x; + if (n == 0) + return 0; + x = vsnprintf(s, n , format, args); + return (x >= n) ? (n - 1) : x; +} + +/** + * snprintf that returns the actual number of bytes (excluding final '\0') that + * were copied into the buffer. + * This is opposed to the normal sprintf() usually returns the number of bytes + * that would have been written. + * + * @param s buffer to copy into + * @param n size of buffer s + * @param format printf style format string + * @param ... arguments for specified format + * @return number of bytes actually copied, excluding final '\0' + */ +int Xscnprintf(char *s, int n, const char *format, ...) +{ + int x; + va_list ap; + va_start(ap, format); + x = Xvscnprintf(s, n, format, ap); + va_end(ap); + return x; +} + /* Old api, now deprecated, may be removed in the future */ char * Xvprintf(const char *format, va_list va) From 6ce0eac4f8a05f6d7401445cab95027709d3a479 Mon Sep 17 00:00:00 2001 From: Daniel Kurtz Date: Wed, 18 Apr 2012 17:51:52 +0800 Subject: [PATCH 3/4] 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 Reviewed-by: Peter Hutterer Signed-off-by: Peter Hutterer --- os/log.c | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/os/log.c b/os/log.c index 92cb7aa24..36378e497 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); From c91d00e0f330b9de604068e1bfcb0a307096434f Mon Sep 17 00:00:00 2001 From: Daniel Kurtz Date: Wed, 18 Apr 2012 17:51:53 +0800 Subject: [PATCH 4/4] os/log: refactor logging 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 of the form: "evdev: %n%n%n%n%n%n%n%n: Device: \"%s\"\n" 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 Reviewed-by: Peter Hutterer Signed-off-by: Peter Hutterer --- os/log.c | 97 +++++++++++++++++++++++++++----------------------------- 1 file changed, 46 insertions(+), 51 deletions(-) diff --git a/os/log.c b/os/log.c index 36378e497..2c13c1a7d 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,12 +298,18 @@ 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, ...) { @@ -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); - LogVWrite(verb, new_format, args); + 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'; + + 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); - /* 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 (hdr_format && size - len > 1) + len += Xvscnprintf(&buf[len], size - len, hdr_format, hdr_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); + if (msg_format && size - len > 1) + len += Xvscnprintf(&buf[len], size - len, msg_format, msg_args); - LogVWrite(verb, tmpFormat, msg_args); + /* Force '\n' at end of truncated line */ + if (size - len == 1) + buf[len - 1] = '\n'; + + newline = (buf[len - 1] == '\n'); + LogSWrite(verb, buf, len, newline); } void