From 4ace7edbd9e849d5a7a5d8b20e08c0c3e2098a02 Mon Sep 17 00:00:00 2001 From: David Steele Date: Tue, 9 Apr 2019 10:54:36 -0400 Subject: [PATCH] Allow process id in C logging The default process id in C logging has always been zero. This should have been updated when multi-processing was introduced in C, but it was missed. --- doc/xml/release.xml | 2 +- src/common/exit.c | 4 +-- src/common/log.c | 6 ++--- src/common/log.h | 42 ++++++++++++++++++++++++++------ test/src/module/common/logTest.c | 37 +++++++++++++++------------- 5 files changed, 61 insertions(+), 30 deletions(-) diff --git a/doc/xml/release.xml b/doc/xml/release.xml index bdb1daf5b..73df3e1b8 100644 --- a/doc/xml/release.xml +++ b/doc/xml/release.xml @@ -98,7 +98,7 @@ -

Allow three-digits process IDs in logging.

+

Logging improvements. Allow three-digits process IDs in logging. Allow process id in C logging.

 diff --git a/src/common/exit.c b/src/common/exit.c index 30b1f7c8e..394cc6db6 100644 --- a/src/common/exit.c +++ b/src/common/exit.c @@ -117,13 +117,13 @@ exitSafe(int result, bool error, SignalType signalType) else { // Log just the error to non-debug levels - LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, logLevelDetail, errorCode(), errorMessage()); + LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, logLevelDetail, 0, errorCode(), errorMessage()); // Log the stack trace debug levels if (logWill(logLevelDebug)) { LOG_INTERNAL( - logLevel, logLevelDebug, LOG_LEVEL_MAX, errorCode(), "%s\nSTACK TRACE:\n%s", errorMessage(), + logLevel, logLevelDebug, LOG_LEVEL_MAX, 0, errorCode(), "%s\nSTACK TRACE:\n%s", errorMessage(), errorStackTrace()); } } diff --git a/src/common/log.c b/src/common/log.c index 760c9fb87..fecf0d3ee 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -347,8 +347,8 @@ General log function ***********************************************************************************************************************************/ void logInternal( - LogLevel logLevel, LogLevel logRangeMin, LogLevel logRangeMax, const char *fileName, const char *functionName, int code, - const char *format, ...) + LogLevel logLevel, LogLevel logRangeMin, LogLevel logRangeMax, unsigned int processId, const char *fileName, + const char *functionName, int code, const char *format, ...) { FUNCTION_TEST_BEGIN(); FUNCTION_TEST_PARAM(ENUM, logLevel); @@ -386,7 +386,7 @@ logInternal( // Add process and aligned log level bufferPos += (size_t)snprintf( - logBuffer + bufferPos, sizeof(logBuffer) - bufferPos, "P%0*d %*s: ", logProcessSize, 0, 6, logLevelStr(logLevel)); + logBuffer + bufferPos, sizeof(logBuffer) - bufferPos, "P%0*u %*s: ", logProcessSize, processId, 6, logLevelStr(logLevel)); // When writing to stderr the timestamp, process, and log level alignment will be skipped char *logBufferStdErr = logBuffer + bufferPos - strlen(logLevelStr(logLevel)) - 2; diff --git a/src/common/log.h b/src/common/log.h index 8169c1328..e6f9a8893 100644 --- a/src/common/log.h +++ b/src/common/log.h @@ -32,13 +32,19 @@ const char *logLevelStr(LogLevel logLevel); /*********************************************************************************************************************************** Macros -Only call logInternal() if the message will be logged to one of the available outputs. -***********************************************************************************************************************************/ -#define LOG_INTERNAL(logLevel, logRangeMin, logRangeMax, code, ...) \ - logInternal(logLevel, logRangeMin, logRangeMax, __FILE__, __func__, code, __VA_ARGS__) +Only call logInternal() if the message will be logged to one of the available outputs. Also simplify each call site by supplying +commonly-used values. +Note that it's possible that that not all the macros below will appear in the code. They are included for completeness and future +usage. +***********************************************************************************************************************************/ +#define LOG_INTERNAL(logLevel, logRangeMin, logRangeMax, processId, code, ...) \ + logInternal(logLevel, logRangeMin, logRangeMax, processId, __FILE__, __func__, code, __VA_ARGS__) + +#define LOG_PID(logLevel, processId, code, ...) \ + LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, LOG_LEVEL_MAX, processId, code, __VA_ARGS__) #define LOG(logLevel, code, ...) \ - LOG_INTERNAL(logLevel, LOG_LEVEL_MIN, LOG_LEVEL_MAX, code, __VA_ARGS__) + LOG_PID(logLevel, 0, code, __VA_ARGS__) #define LOG_WILL(logLevel, code, ...) \ do \ @@ -47,6 +53,13 @@ do LOG(logLevel, code, __VA_ARGS__); \ } while(0) +#define LOG_WILL_PID(logLevel, processId, code, ...) \ +do \ +{ \ + if (logWill(logLevel)) \ + LOG_PID(logLevel, processId, code, __VA_ARGS__); \ +} while(0) + #define LOG_ASSERT(...) \ LOG_WILL(logLevelAssert, errorTypeCode(&AssertError), __VA_ARGS__) #define LOG_ERROR(code, ...) \ @@ -62,11 +75,26 @@ do #define LOG_TRACE(...) \ LOG_WILL(logLevelTrace, 0, __VA_ARGS__) +#define LOG_ASSERT_PID(processId, ...) \ + LOG_WILL_PID(logLevelAssert, processId, errorTypeCode(&AssertError), __VA_ARGS__) +#define LOG_ERROR_PID(processId, code, ...) \ + LOG_WILL_PID(logLevelError, processId, code, __VA_ARGS__) +#define LOG_WARN_PID(processId, ...) \ + LOG_WILL_PID(logLevelWarn, processId, 0, __VA_ARGS__) +#define LOG_INFO_PID(processId, ...) \ + LOG_WILL_PID(logLevelInfo, processId, 0, __VA_ARGS__) +#define LOG_DETAIL_PID(processId, ...) \ + LOG_WILL_PID(logLevelDetail, processId, 0, __VA_ARGS__) +#define LOG_DEBUG_PID(processId, ...) \ + LOG_WILL_PID(logLevelDebug, processId, 0, __VA_ARGS__) +#define LOG_TRACE_PID(processId, ...) \ + LOG_WILL_PID(logLevelTrace, processId, 0, __VA_ARGS__) + /*********************************************************************************************************************************** Internal Functions ***********************************************************************************************************************************/ void logInternal( - LogLevel logLevel, LogLevel logRangeMin, LogLevel logRangeMax, const char *fileName, const char *functionName, - int code, const char *format, ...); + LogLevel logLevel, LogLevel logRangeMin, LogLevel logRangeMax, unsigned int processId, const char *fileName, + const char *functionName, int code, const char *format, ...); #endif diff --git a/test/src/module/common/logTest.c b/test/src/module/common/logTest.c index b98f259e4..24e9ce38e 100644 --- a/test/src/module/common/logTest.c +++ b/test/src/module/common/logTest.c @@ -179,12 +179,13 @@ testRun(void) { TEST_RESULT_VOID(logInit(logLevelOff, logLevelOff, logLevelOff, false, 1), "init logging to off"); TEST_RESULT_VOID( - logInternal(logLevelWarn, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "file", "function", 0, "format"), + logInternal(logLevelWarn, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 0, "file", "function", 0, "format"), "message not logged anywhere"); TEST_RESULT_VOID(logInit(logLevelWarn, logLevelOff, logLevelOff, true, 1), "init logging to warn (timestamp on)"); TEST_RESULT_VOID(logFileSet(BOGUS_STR), "ignore bogus filename because file logging is off"); - TEST_RESULT_VOID(logInternal(logLevelWarn, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "file", "function", 0, "TEST"), "log timestamp"); + TEST_RESULT_VOID( + logInternal(logLevelWarn, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 0, "file", "function", 0, "TEST"), "log timestamp"); String *logTime = strNewN(logBuffer, 23); TEST_RESULT_BOOL( @@ -205,20 +206,21 @@ testRun(void) logBuffer[0] = 0; TEST_RESULT_VOID( - logInternal(logLevelWarn, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "file", "function", 0, "format %d", 99), "log warn"); + logInternal(logLevelWarn, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 0, "file", "function", 0, "format %d", 99), "log warn"); TEST_RESULT_STR(logBuffer, "P00 WARN: format 99\n", " check log"); // This won't be logged due to the range TEST_RESULT_VOID( - logInternal(logLevelWarn, logLevelError, logLevelError, "file", "function", 0, "NOT OUTPUT"), "out of range"); + logInternal(logLevelWarn, logLevelError, logLevelError, 0, "file", "function", 0, "NOT OUTPUT"), "out of range"); logBuffer[0] = 0; - TEST_RESULT_VOID(logInternal(logLevelError, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "file", "function", 26, "message"), "log error"); + TEST_RESULT_VOID( + logInternal(logLevelError, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 0, "file", "function", 26, "message"), "log error"); TEST_RESULT_STR(logBuffer, "P00 ERROR: [026]: message\n", " check log"); logBuffer[0] = 0; TEST_RESULT_VOID( - logInternal(logLevelError, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "file", "function", 26, "message1\nmessage2"), + logInternal(logLevelError, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 0, "file", "function", 26, "message1\nmessage2"), "log error with multiple lines"); TEST_RESULT_STR(logBuffer, "P00 ERROR: [026]: message1\nmessage2\n", " check log"); @@ -231,16 +233,17 @@ testRun(void) logBuffer[0] = 0; TEST_RESULT_VOID( - logInternal(logLevelDebug, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "test.c", "test_func", 0, "message\nmessage2"), "log debug"); - TEST_RESULT_STR(logBuffer, "P000 DEBUG: test::test_func: message\nmessage2\n", " check log"); + logInternal( + logLevelDebug, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 999, "test.c", "test_func", 0, "message\nmessage2"), "log debug"); + TEST_RESULT_STR(logBuffer, "P999 DEBUG: test::test_func: message\nmessage2\n", " check log"); // This won't be logged due to the range TEST_RESULT_VOID( - logInternal(logLevelDebug, logLevelTrace, logLevelTrace, "test.c", "test_func", 0, "NOT OUTPUT"), "out of range"); + logInternal(logLevelDebug, logLevelTrace, logLevelTrace, 0, "test.c", "test_func", 0, "NOT OUTPUT"), "out of range"); logBuffer[0] = 0; TEST_RESULT_VOID( - logInternal(logLevelTrace, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "test.c", "test_func", 0, "message"), "log debug"); + logInternal(logLevelTrace, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 0, "test.c", "test_func", 0, "message"), "log debug"); TEST_RESULT_STR(logBuffer, "P000 TRACE: test::test_func: message\n", " check log"); // Reopen the log file @@ -249,11 +252,11 @@ testRun(void) logBuffer[0] = 0; TEST_RESULT_VOID( - logInternal(logLevelInfo, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "test.c", "test_func", 0, "info message"), "log info"); - TEST_RESULT_STR(logBuffer, "P00 INFO: info message\n", " check log"); + logInternal(logLevelInfo, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 1, "test.c", "test_func", 0, "info message"), "log info"); + TEST_RESULT_STR(logBuffer, "P01 INFO: info message\n", " check log"); TEST_RESULT_VOID( - logInternal(logLevelInfo, LOG_LEVEL_MIN, LOG_LEVEL_MAX, "test.c", "test_func", 0, "info message 2"), "log info"); - TEST_RESULT_STR(logBuffer, "P00 INFO: info message 2\n", " check log"); + logInternal(logLevelInfo, LOG_LEVEL_MIN, LOG_LEVEL_MAX, 99, "test.c", "test_func", 0, "info message 2"), "log info"); + TEST_RESULT_STR(logBuffer, "P99 INFO: info message 2\n", " check log"); // Reopen invalid log file TEST_RESULT_BOOL(logFileSet("/" BOGUS_STR), false, "attempt to open bogus file"); @@ -292,12 +295,12 @@ testRun(void) testLogResult( fileFile, "-------------------PROCESS START-------------------\n" - "P000 DEBUG: test::test_func: message\n" + "P999 DEBUG: test::test_func: message\n" " message2\n" "\n" "-------------------PROCESS START-------------------\n" - "P00 INFO: info message\n" - "P00 INFO: info message 2"); + "P01 INFO: info message\n" + "P99 INFO: info message 2"); } FUNCTION_HARNESS_RESULT_VOID();