diff --git a/communication/tests/catch/hal_stubs.cpp b/communication/tests/catch/hal_stubs.cpp index 81723d4778..517fccc011 100644 --- a/communication/tests/catch/hal_stubs.cpp +++ b/communication/tests/catch/hal_stubs.cpp @@ -7,6 +7,7 @@ #include #include +#include "logging.h" extern "C" uint32_t HAL_RNG_GetRandomNumber() { @@ -31,7 +32,7 @@ extern "C" uint32_t HAL_Core_Compute_CRC32(const uint8_t* buf, size_t length) return 0; } -extern "C" void log_message(int level, const char *category, const char *file, int line, const char *func, void *reserved, const char *fmt, ...) +extern "C" void log_message(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, ...) { } diff --git a/docs/reference/firmware.md b/docs/reference/firmware.md index c3d9ea17c7..6fcf949665 100644 --- a/docs/reference/firmware.md +++ b/docs/reference/firmware.md @@ -8469,7 +8469,7 @@ At higher level, the logging framework consists of two parts represented by thei The library provides default logger instance named `Log`, which can be used for all typical logging operations. Note that applications still need to instantiate at least one log handler in order to enable logging, otherwise most of the logging operations will have no effect. In the provided example, the application uses `SerialLogHandler` which sends the logging output to the primary serial over USB interface. -Consider the following output generated by the example application: +Consider the following logging output as generated by the example application: `0000000047 [app] INFO: This is info message` `0000000050 [app] WARN: This is warning message` @@ -8525,7 +8525,7 @@ void loop() { } ``` -Below is the logging output generated by the example application, where the trace and info messages have been filtered out according to the log handler settings: +In the provided example, the trace and info messages will be filtered out according to the log handler settings, which prevent log messages below the `LOG_LEVEL_WARN` level from being logged: `0000000050 [app] WARN: This is warning message` `0000000100 [app] ERROR: This is error message` @@ -8554,7 +8554,7 @@ void connect() { log.trace("Connecting to server"); // Using local logger } -Serial1LogHandler logHandler(LOG_LEVEL_WARN, { // Logging level for non-application messages +SerialLogHandler logHandler(LOG_LEVEL_WARN, { // Logging level for non-application messages { "app", LOG_LEVEL_INFO }, // Default logging level for all application messages { "app.network", LOG_LEVEL_TRACE } // Logging level for networking messages }); @@ -8571,20 +8571,56 @@ void loop() { Category names are written in all lower case and may contain arbitrary number of _subcategories_ separated by period character. In order to not interfere with the system logging, it is recommended to always add `app` prefix to all application-specific category names. -Below is the logging output generated by the example application: +The example application generates the following logging output: `0000000044 [app] INFO: System started` `0000000044 [app.network] TRACE: Connecting to server` -Note that the trace message containing device ID has been filtered out due to the log handler settings, which instruct the handler to log a message with the `app` category only if its logging level is at or above the `LOG_LEVEL_INFO` level. +Note that the trace message containing device ID has been filtered out according to the log handler settings, which prevent log messages with the `app` category from being logged if their logging level is below the `LOG_LEVEL_INFO` level. Category filters are specified using _initializer list_ syntax with each element of the list containing a filter string and a minimum logging level required for messages with matching category to be logged. Note that filter string matches not only exact category name but any of its subcategory names as well, for example: -* `a` – matches `a`, `a.b`, `a.b.c` but not `aaa` or `aaa.b` -* `b.c` – matches `b.c`, `b.c.d` but not `a.b.c` or `b.ccc` + * `a` – matches `a`, `a.b`, `a.b.c` but not `aaa` or `aaa.b` + * `b.c` – matches `b.c`, `b.c.d` but not `a.b.c` or `b.ccc` If more than one filter matches a given category name, the most specific filter is used. +### Additional Attributes + +As described in previous sections, certain log message attributes, such as a timestamp, are automatically added to all generated messages. The library also defines some attributes that can be used for application-specific needs: + + * `code` : arbitrary integer value (e.g. error code) + * `details` : description string (e.g. error message) + +```cpp +// EXAMPLE - specifying additional attributes + +SerialLogHandler logHandler; + +int connect() { + return ECONNREFUSED; // Return an error +} + +void setup() { + Log.info("Connecting to server"); + int error = connect(); + if (error) { + // Get error message string + const char *message = strerror(error); + // Log message with additional attributes + Log.code(error).details(message).error("Connection error"); + } +} + +void loop() { +} +``` + +The example application specifies `code` and `details` attributes for the error message, generating the following logging output: + +`0000000084 [app] INFO: Connecting to server` +`0000000087 [app] ERROR: Connection error [code = 111, details = Connection refused]` + ### Log Handlers In order to enable logging, application needs to instantiate at least one log handler. If necessary, several different log handlers can be instantiated at the same time. @@ -8631,7 +8667,7 @@ Parameters: ### Logger Class -This class is used to generate log messages. The library also provides default instance of this class named `Log`, which can be used for most of the logging operations. +This class is used to generate log messages. The library also provides default instance of this class named `Log`, which can be used for all typical logging operations. `Logger()` `Logger(const char *name)` @@ -8663,10 +8699,13 @@ Returns category name set for this logger. ```cpp // EXAMPLE -Log.trace("This is %s message", "trace"); -Log.info("This is %s message", "info"); -Log.warn("This is %s message", "warning"); -Log.error("This is %s message", "error"); +Log.trace("This is trace message"); +Log.info("This is info message"); +Log.warn("This is warn message"); +Log.error("This is error message"); + +// Format text message +Log.info("The secret of everything is %d", 42); ``` Generate trace, info, warning or error message respectively. @@ -8675,16 +8714,29 @@ Parameters: * format : format string -`void operator()(const char *format, ...)` +`void log(const char *format, ...)` +`void operator()(const char *format, ...)` + +```cpp +// EXAMPLE +Log("The secret of everything is %d", 42); // Generates info message +``` + +Generates log message with the default logging level (`LOG_LEVEL_INFO`). + +Parameters: + + * format : format string + +`void log(LogLevel level, const char *format, ...)` `void operator()(LogLevel level, const char *format, ...)` ```cpp // EXAMPLE -Log("This is %s message", "info"); // Uses default logging level -Log(LOG_LEVEL_INFO, "This is %s message", "info"); +Log(LOG_LEVEL_INFO, "The secret of everything is %d", 42); ``` -Generate log message with the specified logging level. +Generates log message with the specified logging level. Parameters: diff --git a/hal/src/gcc/core_hal.cpp b/hal/src/gcc/core_hal.cpp index a481ea97b7..b1aace3c72 100644 --- a/hal/src/gcc/core_hal.cpp +++ b/hal/src/gcc/core_hal.cpp @@ -52,25 +52,32 @@ void setLoggerLevel(LoggerOutputLevel level) log_level = level; } -void log_message_callback(const char *msg, int level, const char *category, uint32_t time, const char *file, int line, - const char *func, void *reserved) +void log_message_callback(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved) { if (level < log_level) { return; } std::ostringstream strm; // Timestamp - strm << std::setw(10) << std::setfill('0') << time << ' '; - // Category (optional) - if (category && category[0]) { + if (attr->has_time) { + strm << std::setw(10) << std::setfill('0') << attr->time << ' '; + } + // Category + if (category) { strm << '[' << category << "] "; } - // Source info (optional) - if (file && func) { - strm << file << ':' << line << ", "; - // Strip argument and return types for better readability - std::string funcName(func); - const size_t pos = funcName.find(' '); + // Source info + if (attr->has_file && attr->has_line && attr->has_function) { + // Strip directory path + std::string fileName(attr->file); + size_t pos = fileName.rfind('/'); + if (pos != std::string::npos) { + fileName = fileName.substr(pos + 1); + } + strm << fileName << ':' << attr->line << ", "; + // Strip argument and return types + std::string funcName(attr->function); + pos = funcName.find(' '); if (pos != std::string::npos) { funcName = funcName.substr(pos + 1, funcName.find('(') - pos - 1); } @@ -79,7 +86,21 @@ void log_message_callback(const char *msg, int level, const char *category, uint // Level strm << log_level_name(level, nullptr) << ": "; // Message - strm << msg; + if (msg) { + strm << msg; + } + // Additional attributes + if (attr->has_code || attr->has_details) { + strm << " ["; + if (attr->has_code) { + strm << "code = " << attr->code << ", "; + } + if (attr->has_details) { + strm << "details = " << attr->details << ", "; + } + strm.seekp(-2, std::ios_base::end); // Overwrite trailing comma + strm << "] "; + } std::cout << strm.str() << std::endl; } @@ -117,7 +138,7 @@ extern "C" int main(int argc, char* argv[]) if (exists_file(eeprom_bin)) { GCC_EEPROM_Load(eeprom_bin); } - app_setup_and_loop(); + app_setup_and_loop(); } return 0; } diff --git a/services/inc/logging.h b/services/inc/logging.h index 85044f0dbf..f6228dd9f9 100644 --- a/services/inc/logging.h +++ b/services/inc/logging.h @@ -22,12 +22,20 @@ This header defines various macros for logging: LOG(level, format, ...) - generates log message according to printf-alike format string. - This macro adds several attributes to all generated messages: timestamp, source file name, line - number, function name (see also LOG_INCLUDE_SOURCE_INFO). + This macro adds several default attributes to all log messages: timestamp, source file name, + line number, function name (see also LOG_INCLUDE_SOURCE_INFO). const char* user = "John D."; LOG(INFO, "Hello %s!", user); + LOG_ATTR(level, attrs, format, ...) - generates log message with additional attributes. + Supported attributes and their types are described by the LogAttributes structure. + + int error = network_connect(); + if (error) { + LOG_ATTR(ERROR, (code = error, details = "network"), "Connection error"); + } + LOG_WRITE(level, data, size) - primary macro for direct logging. Provided buffer is forwarded to backend logger as is. @@ -80,6 +88,7 @@ Following macros take category name as argument: LOG_C(level, category, format, ...) + LOG_ATTR_C(level, category, attrs, format, ...) LOG_WRITE_C(level, category, data, size) LOG_PRINT_C(level, category, str) LOG_PRINTF_C(level, category, format, ...) @@ -115,6 +124,7 @@ #include #include "panic.h" #include "config.h" +#include "preprocessor.h" // NOTE: This header defines various string constants. Ensure identical strings defined in different // translation units get merged during linking (may require enabled optimizations) @@ -136,8 +146,8 @@ typedef enum LogLevel { DEFAULT_LEVEL = 0, ALL_LEVEL = LOG_LEVEL_ALL, TRACE_LEVEL = LOG_LEVEL_TRACE, - LOG_LEVEL = LOG_LEVEL_TRACE, - DEBUG_LEVEL = LOG_LEVEL_TRACE, + LOG_LEVEL = LOG_LEVEL_TRACE, // Deprecated + DEBUG_LEVEL = LOG_LEVEL_TRACE, // Deprecated INFO_LEVEL = LOG_LEVEL_INFO, WARN_LEVEL = LOG_LEVEL_WARN, ERROR_LEVEL = LOG_LEVEL_ERROR, @@ -145,12 +155,37 @@ typedef enum LogLevel { NO_LOG_LEVEL = LOG_LEVEL_NONE } LogLevel; -// Application module needs to register following callbacks in order to handle generated logging output -// (see log_set_callbacks()): +// Log message attributes +// NOTE: Do not change types and order of the existent fields +typedef struct LogAttributes { + size_t size; // Structure size + union { // Attribute flags + uint32_t flags; + struct { + // 1 - attribute is set, 0 - attribute is not set + unsigned has_file: 1; + unsigned has_line: 1; + unsigned has_function: 1; + unsigned has_time: 1; + unsigned has_code: 1; + unsigned has_details: 1; + // <--- Add new attribute flag here + unsigned has_end: 1; // Keep this field at the end of the structure + }; + }; + const char *file; // Source file name + int line; // Line number + const char *function; // Function name + uint32_t time; // Timestamp + intptr_t code; // Status code + const char *details; // Additional information + // <--- Add new attribute field here + char end[0]; // Keep this field at the end of the structure +} LogAttributes; // Callback for message-based logging (used by log_message()) -typedef void (*log_message_callback_type)(const char *msg, int level, const char *category, uint32_t time, - const char *file, int line, const char *func, void *reserved); +typedef void (*log_message_callback_type)(const char *msg, int level, const char *category, const LogAttributes *attr, + void *reserved); // Callback for direct logging (used by log_write(), log_printf(), log_dump()) typedef void (*log_write_callback_type)(const char *data, size_t size, int level, const char *category, void *reserved); @@ -159,12 +194,11 @@ typedef void (*log_write_callback_type)(const char *data, size_t size, int level typedef int (*log_enabled_callback_type)(int level, const char *category, void *reserved); // Generates log message -void log_message(int level, const char *category, const char *file, int line, const char *func, void *reserved, - const char *fmt, ...); +void log_message(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, ...); // Variant of the log_message() function taking variable arguments via va_list -void log_message_v(int level, const char *category, const char *file, int line, const char *func, void *reserved, - const char *fmt, va_list args); +void log_message_v(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, + va_list args); // Forwards buffer to backend logger void log_write(int level, const char *category, const char *data, size_t size, void *reserved); @@ -202,6 +236,13 @@ extern void HAL_Delay_Microseconds(uint32_t delay); #define LOG_MAX_STRING_LENGTH 160 #endif +// Sets log message attribute +#define LOG_ATTR_SET(_attr, _name, _val) \ + do { \ + (_attr)._name = _val; \ + (_attr).has_##_name = 1; \ + } while (0) + #ifndef LOG_DISABLE #ifndef LOG_MODULE_CATEGORY @@ -268,16 +309,40 @@ static const char* const _log_category = NULL; #endif // !defined(__cplusplus) #ifdef LOG_INCLUDE_SOURCE_INFO -#define _LOG_SOURCE_INFO __FILE__, __LINE__, __PRETTY_FUNCTION__ +#define _LOG_ATTR_SET_SOURCE_INFO(_attr) \ + LOG_ATTR_SET(_attr, file, __FILE__); \ + LOG_ATTR_SET(_attr, line, __LINE__); \ + LOG_ATTR_SET(_attr, function, __PRETTY_FUNCTION__) #else -#define _LOG_SOURCE_INFO NULL, 0, NULL +#define _LOG_ATTR_SET_SOURCE_INFO(_attr) #endif -// Wrapper macros +#define _LOG_ATTR_INIT(_name) \ + LogAttributes _name; \ + _name.size = sizeof(LogAttributes); \ + _name.flags = 0; \ + _LOG_ATTR_SET_SOURCE_INFO(_name) + +// Generator macro for PP_FOR_EACH() +#define _LOG_ATTR_SET(_attr, _expr) \ + (_attr)._expr; /* attr.file = "logging.h"; */ \ + (_attr).has_##_expr ? 1 : 1; /* attr.has_file = "logging.h" ? 1 : 1; */ + +// Primary logging macros #define LOG_C(_level, _category, _fmt, ...) \ do { \ if (LOG_LEVEL_##_level >= LOG_COMPILE_TIME_LEVEL) { \ - log_message(LOG_LEVEL_##_level, _category, _LOG_SOURCE_INFO, NULL, _fmt, ##__VA_ARGS__); \ + _LOG_ATTR_INIT(_attr); \ + log_message(LOG_LEVEL_##_level, _category, &_attr, NULL, _fmt, ##__VA_ARGS__); \ + } \ + } while (0) + +#define LOG_ATTR_C(_level, _category, _attrs, _fmt, ...) \ + do { \ + if (LOG_LEVEL_##_level >= LOG_COMPILE_TIME_LEVEL) { \ + _LOG_ATTR_INIT(_attr); \ + PP_FOR_EACH(_LOG_ATTR_SET, _attr, PP_ARGS(_attrs)); \ + log_message(LOG_LEVEL_##_level, _category, &_attr, NULL, _fmt, ##__VA_ARGS__); \ } \ } while (0) @@ -313,59 +378,54 @@ static const char* const _log_category = NULL; #define LOG_ENABLED_C(_level, _category) \ (LOG_LEVEL_##_level >= LOG_COMPILE_TIME_LEVEL && log_enabled(LOG_LEVEL_##_level, _category, NULL)) -// Macros using current category -#define LOG(_level, _fmt, ...) LOG_C(_level, LOG_THIS_CATEGORY(), _fmt, ##__VA_ARGS__) -#define LOG_WRITE(_level, _data, _size) LOG_WRITE_C(_level, LOG_THIS_CATEGORY(), _data, _size) -#define LOG_PRINT(_level, _str) LOG_PRINT_C(_level, LOG_THIS_CATEGORY(), _str) -#define LOG_PRINTF(_level, _fmt, ...) LOG_PRINTF_C(_level, LOG_THIS_CATEGORY(), _fmt, ##__VA_ARGS__) -#define LOG_DUMP(_level, _data, _size) LOG_DUMP_C(_level, LOG_THIS_CATEGORY(), _data, _size) -#define LOG_ENABLED(_level) LOG_ENABLED_C(_level, LOG_THIS_CATEGORY()) - #else // LOG_DISABLE #define LOG_CATEGORY(_name) #define LOG_SOURCE_CATEGORY(_name) #define LOG_THIS_CATEGORY() NULL -#define LOG(_level, _fmt, ...) #define LOG_C(_level, _category, _fmt, ...) -#define LOG_WRITE(_level, _data, _size) +#define LOG_ATTR_C(_level, _category, _attrs, _fmt, ...) #define LOG_WRITE_C(_level, _category, _data, _size) -#define LOG_PRINT(_level, _str) #define LOG_PRINT_C(_level, _category, _str) -#define LOG_PRINTF(_level, _fmt, ...) #define LOG_PRINTF_C(_level, _category, _fmt, ...) -#define LOG_DUMP(_level, _data, _size) #define LOG_DUMP_C(_level, _category, _data, _size) -#define LOG_ENABLED(_level) (0) #define LOG_ENABLED_C(_level, _category) (0) #endif #ifdef DEBUG_BUILD -#define LOG_DEBUG(_level, _fmt, ...) LOG(_level, _fmt, ##__VA_ARGS__) #define LOG_DEBUG_C(_level, _category, _fmt, ...) LOG_C(_level, _category, _fmt, ##__VA_ARGS__) -#define LOG_DEBUG_WRITE(_level, _data, _size) LOG_WRITE(_level, _data, _size) +#define LOG_DEBUG_ATTR_C(_level, _category, _attrs, _fmt, ...) LOG_ATTR_C(_level, _category, _attrs, _fmt, ##__VA_ARGS__) #define LOG_DEBUG_WRITE_C(_level, _category, _data, _size) LOG_WRITE_C(_level, _category, _data, _size) -#define LOG_DEBUG_PRINT(_level, _str) LOG_PRINT(_level, _str) #define LOG_DEBUG_PRINT_C(_level, _category, _str) LOG_PRINT_C(_level, _category, _str) -#define LOG_DEBUG_PRINTF(_level, _fmt, ...) LOG_PRINTF(_level, _fmt, ##__VA_ARGS__) #define LOG_DEBUG_PRINTF_C(_level, _category, _fmt, ...) LOG_PRINTF_C(_level, _category, _fmt, ##__VA_ARGS__) -#define LOG_DEBUG_DUMP(_level, _data, _size) LOG_DUMP(_level, _data, _size) #define LOG_DEBUG_DUMP_C(_level, _category, _data, _size) LOG_DUMP_C(_level, _category, _data, _size) #else -#define LOG_DEBUG(_level, _fmt, ...) #define LOG_DEBUG_C(_level, _category, _fmt, ...) -#define LOG_DEBUG_WRITE(_level, _data, _size) +#define LOG_DEBUG_ATTR_C(_level, _category, _attrs, _fmt, ...) #define LOG_DEBUG_WRITE_C(_level, _category, _data, _size) -#define LOG_DEBUG_PRINT(_level, _str) #define LOG_DEBUG_PRINT_C(_level, _category, _str) -#define LOG_DEBUG_PRINTF(_level, _fmt, ...) #define LOG_DEBUG_PRINTF_C(_level, _category, _fmt, ...) -#define LOG_DEBUG_DUMP(_level, _data, _size) #define LOG_DEBUG_DUMP_C(_level, _category, _data, _size) #endif +// Macros using current category +#define LOG(_level, _fmt, ...) LOG_C(_level, LOG_THIS_CATEGORY(), _fmt, ##__VA_ARGS__) +#define LOG_ATTR(_level, _attrs, _fmt, ...) LOG_ATTR_C(_level, LOG_THIS_CATEGORY(), _attrs, _fmt, ##__VA_ARGS__) +#define LOG_WRITE(_level, _data, _size) LOG_WRITE_C(_level, LOG_THIS_CATEGORY(), _data, _size) +#define LOG_PRINT(_level, _str) LOG_PRINT_C(_level, LOG_THIS_CATEGORY(), _str) +#define LOG_PRINTF(_level, _fmt, ...) LOG_PRINTF_C(_level, LOG_THIS_CATEGORY(), _fmt, ##__VA_ARGS__) +#define LOG_DUMP(_level, _data, _size) LOG_DUMP_C(_level, LOG_THIS_CATEGORY(), _data, _size) +#define LOG_ENABLED(_level) LOG_ENABLED_C(_level, LOG_THIS_CATEGORY()) + +#define LOG_DEBUG(_level, _fmt, ...) LOG_DEBUG_C(_level, LOG_THIS_CATEGORY(), _fmt, ##__VA_ARGS__) +#define LOG_DEBUG_ATTR(_level, _attrs, _fmt, ...) LOG_DEBUG_ATTR_C(_level, LOG_THIS_CATEGORY(), _attrs, _fmt, ##__VA_ARGS__) +#define LOG_DEBUG_WRITE(_level, _data, _size) LOG_DEBUG_WRITE_C(_level, LOG_THIS_CATEGORY(), _data, _size) +#define LOG_DEBUG_PRINT(_level, _str) LOG_DEBUG_PRINT_C(_level, LOG_THIS_CATEGORY(), _str) +#define LOG_DEBUG_PRINTF(_level, _fmt, ...) LOG_DEBUG_PRINTF_C(_level, LOG_THIS_CATEGORY(), _fmt, ##__VA_ARGS__) +#define LOG_DEBUG_DUMP(_level, _data, _size) LOG_DEBUG_DUMP_C(_level, LOG_THIS_CATEGORY(), _data, _size) + #define PANIC(_code, _fmt, ...) \ do { \ LOG(PANIC, _fmt, ##__VA_ARGS__); \ diff --git a/services/inc/preprocessor.h b/services/inc/preprocessor.h new file mode 100644 index 0000000000..2fcf0b8ad4 --- /dev/null +++ b/services/inc/preprocessor.h @@ -0,0 +1,172 @@ +/* + * Copyright (c) 2016 Particle Industries, Inc. All rights reserved. + * + * This library is free software; you can redistribute it and/or + * modify it under the terms of the GNU Lesser General Public + * License as published by the Free Software Foundation, either + * version 3 of the License, or (at your option) any later version. + * + * This library is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU + * Lesser General Public License for more details. + * + * You should have received a copy of the GNU Lesser General Public + * License along with this library; if not, see . + */ + +#ifndef _PREPROCESSOR_H +#define _PREPROCESSOR_H + +/* + PP_STR(x) + + Expands and stringifies argument. + + #define A a + PP_STR(A) // Expands to "a" +*/ +#define PP_STR(x) \ + _PP_STR(x) + +#define _PP_STR(x) #x + +/* + PP_CAT(a, b) + + Expands and concatenates arguments. + + #define A a + #define B b + PP_CAT(A, B) // Expands to ab +*/ +#define PP_CAT(a, b) \ + _PP_CAT(a, b) + +#define _PP_CAT(a, b) a##b + +/* + PP_TUPLE(...) + + Encloses arguments in parentheses. + + PP_TUPLE(a, b) // Expands to (a, b) +*/ +#define PP_TUPLE(...) (__VA_ARGS__) + +/* + PP_ARGS(x) + + Removes enclosing parentheses. + + PP_ARGS((a, b)) // Expands to a, b +*/ +#define PP_ARGS(x) \ + _PP_ARGS x + +#define _PP_ARGS(...) __VA_ARGS__ + +/* + PP_COUNT(...) + + Expands to a number of arguments. This macro supports up to 30 arguments. + + PP_COUNT(a, b) // Expands to 2 +*/ +#define PP_COUNT(...) \ + _PP_COUNT(_, ##__VA_ARGS__, _PP_COUNT_N) + +#define _PP_COUNT(...) \ + _PP_COUNT_(__VA_ARGS__) + +#define _PP_COUNT_(_, \ + _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, \ + _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, \ + _21, _22, _23, _24, _25, _26, _27, _28, _29, _30, \ + n, ...) n + +#define _PP_COUNT_N \ + 30, 29, 28, 27, 26, 25, 24, 23, 22, 21, \ + 20, 19, 18, 17, 16, 15, 14, 13, 12, 11, \ + 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0 + +/* + PP_FOR_EACH(macro, data, ...) + + Expands macro for each argument. This macro supports up to 30 arguments. + + #define CALL(func, arg) func(arg); + PP_FOR_EACH(CALL, foo, 1, 2, 3) // Expands to foo(1); foo(2); foo(3); +*/ +#define PP_FOR_EACH(macro, data, ...) \ + _PP_FOR_EACH(PP_CAT(_PP_FOR_EACH_, PP_COUNT(__VA_ARGS__)), macro, data, ##__VA_ARGS__) + +#define _PP_FOR_EACH(...) \ + _PP_FOR_EACH_(__VA_ARGS__) + +#define _PP_FOR_EACH_(for_each, macro, data, ...) \ + for_each(macro, data, ##__VA_ARGS__) + +#define _PP_FOR_EACH_0(m, d, ...) +#define _PP_FOR_EACH_1(m, d, _1) \ + _PP_FOR_EACH_0(m, d) m(d, _1) +#define _PP_FOR_EACH_2(m, d, _1, _2) \ + _PP_FOR_EACH_1(m, d, _1) m(d, _2) +#define _PP_FOR_EACH_3(m, d, _1, _2, _3) \ + _PP_FOR_EACH_2(m, d, _1, _2) m(d, _3) +#define _PP_FOR_EACH_4(m, d, _1, _2, _3, _4) \ + _PP_FOR_EACH_3(m, d, _1, _2, _3) m(d, _4) +#define _PP_FOR_EACH_5(m, d, _1, _2, _3, _4, _5) \ + _PP_FOR_EACH_4(m, d, _1, _2, _3, _4) m(d, _5) +#define _PP_FOR_EACH_6(m, d, _1, _2, _3, _4, _5, _6) \ + _PP_FOR_EACH_5(m, d, _1, _2, _3, _4, _5) m(d, _6) +#define _PP_FOR_EACH_7(m, d, _1, _2, _3, _4, _5, _6, _7) \ + _PP_FOR_EACH_6(m, d, _1, _2, _3, _4, _5, _6) m(d, _7) +#define _PP_FOR_EACH_8(m, d, _1, _2, _3, _4, _5, _6, _7, _8) \ + _PP_FOR_EACH_7(m, d, _1, _2, _3, _4, _5, _6, _7) m(d, _8) +#define _PP_FOR_EACH_9(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9) \ + _PP_FOR_EACH_8(m, d, _1, _2, _3, _4, _5, _6, _7, _8) m(d, _9) +#define _PP_FOR_EACH_10(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10) \ + _PP_FOR_EACH_9(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9) m(d, _10) +#define _PP_FOR_EACH_11(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11) \ + _PP_FOR_EACH_10(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10) m(d, _11) +#define _PP_FOR_EACH_12(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12) \ + _PP_FOR_EACH_11(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11) m(d, _12) +#define _PP_FOR_EACH_13(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13) \ + _PP_FOR_EACH_12(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12) m(d, _13) +#define _PP_FOR_EACH_14(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14) \ + _PP_FOR_EACH_13(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13) m(d, _14) +#define _PP_FOR_EACH_15(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15) \ + _PP_FOR_EACH_14(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14) m(d, _15) +#define _PP_FOR_EACH_16(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16) \ + _PP_FOR_EACH_15(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15) m(d, _16) +#define _PP_FOR_EACH_17(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17) \ + _PP_FOR_EACH_16(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16) m(d, _17) +#define _PP_FOR_EACH_18(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18) \ + _PP_FOR_EACH_17(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17) m(d, _18) +#define _PP_FOR_EACH_19(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19) \ + _PP_FOR_EACH_18(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18) m(d, _19) +#define _PP_FOR_EACH_20(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20) \ + _PP_FOR_EACH_19(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19) m(d, _20) +#define _PP_FOR_EACH_21(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21) \ + _PP_FOR_EACH_20(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20) m(d, _21) +#define _PP_FOR_EACH_22(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22) \ + _PP_FOR_EACH_21(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21) m(d, _22) +#define _PP_FOR_EACH_23(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23) \ + _PP_FOR_EACH_22(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22) m(d, _23) +#define _PP_FOR_EACH_24(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24) \ + _PP_FOR_EACH_23(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23) m(d, _24) +#define _PP_FOR_EACH_25(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25) \ + _PP_FOR_EACH_24(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24) m(d, _25) +#define _PP_FOR_EACH_26(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26) \ + _PP_FOR_EACH_25(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25) m(d, _26) +#define _PP_FOR_EACH_27(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27) \ + _PP_FOR_EACH_26(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26) m(d, _27) +#define _PP_FOR_EACH_28(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27, _28) \ + _PP_FOR_EACH_27(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27) m(d, _28) +#define _PP_FOR_EACH_29(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27, _28, _29) \ + _PP_FOR_EACH_28(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27, _28) m(d, _29) +#define _PP_FOR_EACH_30(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27, _28, _29, _30) \ + _PP_FOR_EACH_29(m, d, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, _21, _22, _23, _24, _25, _26, _27, _28, _29) m(d, _30) + +#endif // _PREPROCESSOR_H diff --git a/services/inc/services_dynalib.h b/services/inc/services_dynalib.h index 563720bb79..995c02e06e 100644 --- a/services/inc/services_dynalib.h +++ b/services/inc/services_dynalib.h @@ -50,8 +50,8 @@ DYNALIB_FN(17, services, LED_RGB_SetChangeHandler, void(led_update_handler_fn, v DYNALIB_FN(18, services, log_print_direct_, void(int, void*, const char*, ...)) // Deprecated DYNALIB_FN(19, services, LED_GetColor, uint32_t(uint32_t, void*)) -DYNALIB_FN(20, services, log_message, void(int, const char*, const char*, int, const char*, void*, const char*, ...)) -DYNALIB_FN(21, services, log_message_v, void(int, const char*, const char*, int, const char*, void*, const char*, va_list)) +DYNALIB_FN(20, services, log_message, void(int, const char*, LogAttributes*, void*, const char*, ...)) +DYNALIB_FN(21, services, log_message_v, void(int, const char*, LogAttributes*, void*, const char*, va_list)) DYNALIB_FN(22, services, log_write, void(int, const char*, const char*, size_t, void*)) DYNALIB_FN(23, services, log_printf, void(int, const char*, void*, const char*, ...)) DYNALIB_FN(24, services, log_printf_v, void(int, const char*, void*, const char*, va_list)) diff --git a/services/src/logging.cpp b/services/src/logging.cpp index 16643390c8..6612302d2e 100644 --- a/services/src/logging.cpp +++ b/services/src/logging.cpp @@ -19,10 +19,48 @@ #include #include -#include -#include #include "timer_hal.h" #include "service_debug.h" +#include "static_assert.h" + +#define STATIC_ASSERT_FIELD_SIZE(struct, field, size) \ + STATIC_ASSERT(field_size_changed_##struct##_##field, sizeof(struct::field) == size); + +#define STATIC_ASSERT_FIELD_OFFSET(struct, field, offset) \ + STATIC_ASSERT(field_offset_changed_##struct##_##field, offsetof(struct, field) == offset); + +#define STATIC_ASSERT_FIELD_ORDER(struct, field1, field2) \ + STATIC_ASSERT(field_offset_changed_##struct##_##field2, \ + offsetof(struct, field2) == offsetof(struct, field1) + sizeof(struct::field1) + /* Padding */ \ + (__alignof__(struct::field2) - (offsetof(struct, field1) + sizeof(struct::field1)) % \ + __alignof__(struct::field2)) % __alignof__(struct::field2)); + +// LogAttributes::size +STATIC_ASSERT_FIELD_SIZE(LogAttributes, size, sizeof(size_t)); +STATIC_ASSERT_FIELD_OFFSET(LogAttributes, size, 0); +// LogAttributes::flags +STATIC_ASSERT_FIELD_SIZE(LogAttributes, flags, sizeof(uint32_t)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, size, flags); +// LogAttributes::file +STATIC_ASSERT_FIELD_SIZE(LogAttributes, file, sizeof(const char*)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, flags, file); +// LogAttributes::line +STATIC_ASSERT_FIELD_SIZE(LogAttributes, line, sizeof(int)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, file, line); +// LogAttributes::function +STATIC_ASSERT_FIELD_SIZE(LogAttributes, function, sizeof(const char*)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, line, function); +// LogAttributes::time +STATIC_ASSERT_FIELD_SIZE(LogAttributes, time, sizeof(uint32_t)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, function, time); +// LogAttributes::code +STATIC_ASSERT_FIELD_SIZE(LogAttributes, code, sizeof(intptr_t)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, time, code); +// LogAttributes::details +STATIC_ASSERT_FIELD_SIZE(LogAttributes, details, sizeof(const char*)); +STATIC_ASSERT_FIELD_ORDER(LogAttributes, code, details); +// LogAttributes::end +STATIC_ASSERT_FIELD_ORDER(LogAttributes, details, end); namespace { @@ -39,18 +77,13 @@ void log_set_callbacks(log_message_callback_type log_msg, log_write_callback_typ log_enabled_callback = log_enabled; } -void log_message_v(int level, const char *category, const char *file, int line, const char *func, void *reserved, - const char *fmt, va_list args) { - if (!log_write_callback && (!log_compat_callback || level < log_compat_level)) { +void log_message_v(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, va_list args) { + if (!log_msg_callback && (!log_compat_callback || level < log_compat_level)) { return; } - const uint32_t time = HAL_Timer_Get_Milli_Seconds(); - if (file) { - // Strip directory path - const char *p = strrchr(file, '/'); - if (p) { - file = p + 1; - } + // Set default attributes + if (!attr->has_time) { + LOG_ATTR_SET(*attr, time, HAL_Timer_Get_Milli_Seconds()); } char buf[LOG_MAX_STRING_LENGTH]; if (log_msg_callback) { @@ -58,15 +91,16 @@ void log_message_v(int level, const char *category, const char *file, int line, if (n > (int)sizeof(buf) - 1) { buf[sizeof(buf) - 2] = '~'; } - log_msg_callback(buf, level, category, time, file, line, func, 0); + log_msg_callback(buf, level, category, attr, 0); } else { // Using compatibility callback const char* const levelName = log_level_name(level, 0); int n = 0; - if (file && func) { - n = snprintf(buf, sizeof(buf), "%010u %s:%d, %s: %s", (unsigned)time, file, line, func, levelName); + if (attr->has_file && attr->has_line && attr->has_function) { + n = snprintf(buf, sizeof(buf), "%010u %s:%d, %s: %s", (unsigned)attr->time, attr->file, attr->line, + attr->function, levelName); } else { - n = snprintf(buf, sizeof(buf), "%010u %s", (unsigned)time, levelName); + n = snprintf(buf, sizeof(buf), "%010u %s", (unsigned)attr->time, levelName); } if (n > (int)sizeof(buf) - 1) { buf[sizeof(buf) - 2] = '~'; @@ -82,11 +116,10 @@ void log_message_v(int level, const char *category, const char *file, int line, } } -void log_message(int level, const char *category, const char *file, int line, const char *func, void *reserved, - const char *fmt, ...) { +void log_message(int level, const char *category, LogAttributes *attr, void *reserved, const char *fmt, ...) { va_list args; va_start(args, fmt); - log_message_v(level, category, file, line, func, reserved, fmt, args); + log_message_v(level, category, attr, reserved, fmt, args); va_end(args); } diff --git a/user/tests/unit/logging.cpp b/user/tests/unit/logging.cpp index fb7c4fa3dd..7a69f24811 100644 --- a/user/tests/unit/logging.cpp +++ b/user/tests/unit/logging.cpp @@ -1,7 +1,8 @@ #include #include +#include +#include -#include #include #include @@ -13,23 +14,50 @@ #include "spark_wiring_logging.h" #include "service_debug.h" +#define CHECK_LOG_ATTR_FLAG(flag, value) \ + do { \ + LogAttributes attr = { 0 }; \ + attr.flag = 1; \ + CATCH_CHECK(attr.flags == value); \ + } while (false) + // Source file's logging category -LOG_SOURCE_CATEGORY("source"); +LOG_SOURCE_CATEGORY("source") namespace { using namespace spark; +std::string fileName(const std::string &path); + class LogMessage { public: - LogMessage(const char *msg, LogLevel level, const char *category, uint32_t time, const LogHandler::SourceInfo &info) : - msg_(msg ? msg : ""), - cat_(category ? category : ""), - file_(info.file ? info.file : ""), - func_(info.function ? info.function : ""), - level_(level), - time_(time), - line_(info.line) { + LogMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) : + level_(level) { + if (msg) { + msg_ = msg; + } + if (category) { + cat_ = category; + } + if (attr.has_file) { + file_ = fileName(attr.file); // Strip directory path + } + if (attr.has_line) { + line_ = attr.line; + } + if (attr.has_function) { + func_ = attr.function; + } + if (attr.has_time) { + time_ = attr.time; + } + if (attr.has_code) { + code_ = attr.code; + } + if (attr.has_details) { + detail_ = attr.details; + } } const LogMessage& messageEquals(const std::string &msg) const { @@ -47,11 +75,7 @@ class LogMessage { return *this; } - const LogMessage& timeEquals(uint32_t time) const { - CATCH_CHECK(time_ == time); - return *this; - } - + // Default attributes const LogMessage& fileEquals(const std::string &file) const { CATCH_CHECK(file_ == file); return *this; @@ -67,11 +91,38 @@ class LogMessage { return *this; } + const LogMessage& timeEquals(uint32_t time) const { + CATCH_CHECK(time_ == time); + return *this; + } + + // Additional attributes + const LogMessage& codeEquals(intptr_t code) const { + CATCH_CHECK(code_ == code); + return *this; + } + + const LogMessage& hasCode(bool yes = true) const { + CATCH_CHECK((bool)code_ == yes); + return *this; + } + + const LogMessage& detailsEquals(const std::string &str) const { + CATCH_CHECK(detail_ == str); + return *this; + } + + const LogMessage& hasDetails(bool yes = true) const { + CATCH_CHECK((bool)detail_ == yes); + return *this; + } + private: - std::string msg_, cat_, file_, func_; + boost::optional msg_, cat_, file_, func_, detail_; + boost::optional code_; + boost::optional time_; + boost::optional line_; LogLevel level_; - uint32_t time_; - int line_; }; class TestLogHandler: public LogHandler { @@ -113,8 +164,8 @@ class TestLogHandler: public LogHandler { protected: // spark::LogHandler - virtual void logMessage(const char *msg, LogLevel level, const char *category, uint32_t time, const SourceInfo &info) override { - msgs_.push(LogMessage(msg, level, category, time, info)); + virtual void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) override { + msgs_.push(LogMessage(msg, level, category, attr)); } virtual void write(const char *data, size_t size) override { @@ -193,13 +244,12 @@ std::string randomBytes(size_t size = 0) { return s; } -std::string sourceFileName() { - const std::string s(__FILE__); - const size_t pos = s.rfind('/'); +std::string fileName(const std::string &path) { + const size_t pos = path.rfind('/'); if (pos != std::string::npos) { - return s.substr(pos + 1); + return path.substr(pos + 1); } - return s; + return path; } std::string toHex(const std::string &str) { @@ -210,14 +260,14 @@ std::string toHex(const std::string &str) { CompatLogHandler* CompatLogHandler::instance = nullptr; -const std::string SOURCE_FILE = sourceFileName(); +const std::string SOURCE_FILE = fileName(__FILE__); const std::string SOURCE_CATEGORY = LOG_THIS_CATEGORY(); } // namespace CATCH_TEST_CASE("Message logging") { TestLogHandler log(LOG_LEVEL_ALL); - CATCH_SECTION("attributes") { + CATCH_SECTION("default attributes") { LOG(TRACE, "trace"); log.next().messageEquals("trace").levelEquals(LOG_LEVEL_TRACE).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); LOG(INFO, "info"); @@ -227,7 +277,14 @@ CATCH_TEST_CASE("Message logging") { LOG(ERROR, "error"); log.next().messageEquals("error").levelEquals(LOG_LEVEL_ERROR).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE); } - CATCH_SECTION("formatting") { + CATCH_SECTION("additional attributes") { + LOG(INFO, "info"); + log.next().hasCode(false).hasDetails(false); // No additional attributes + LOG_ATTR(INFO, (code = -1, details = "details"), "info"); + log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_THIS_CATEGORY()).fileEquals(SOURCE_FILE) + .codeEquals(-1).detailsEquals("details"); + } + CATCH_SECTION("message formatting") { std::string s = ""; LOG(TRACE, "%s", s.c_str()); log.next().messageEquals(""); @@ -257,7 +314,7 @@ CATCH_TEST_CASE("Message logging") { CATCH_TEST_CASE("Message logging (compatibility callback)") { CompatLogHandler log(LOG_LEVEL_ALL); - CATCH_SECTION("attributes") { + CATCH_SECTION("default attributes") { LOG(TRACE, "trace"); log.bufferEndsWith("TRACE: trace\r\n"); LOG(INFO, "info"); @@ -268,7 +325,7 @@ CATCH_TEST_CASE("Message logging (compatibility callback)") { log.bufferEndsWith("ERROR: error\r\n"); CATCH_CHECK(log.buffer().find(SOURCE_FILE) != std::string::npos); } - CATCH_SECTION("formatting") { + CATCH_SECTION("message formatting") { std::string s = randomString(LOG_MAX_STRING_LENGTH / 2); // Smaller than the internal buffer LOG(INFO, "%s", s.c_str()); log.bufferEndsWith(s + "\r\n"); @@ -606,6 +663,15 @@ CATCH_TEST_CASE("Miscellaneous") { CATCH_CHECK(LOG_ENABLED_C(TRACE, "aaa")); CATCH_CHECK(LOG_ENABLED_C(ERROR, "x")); } + CATCH_SECTION("attribute flag values") { + CHECK_LOG_ATTR_FLAG(has_file, 0x01); + CHECK_LOG_ATTR_FLAG(has_line, 0x02); + CHECK_LOG_ATTR_FLAG(has_function, 0x04); + CHECK_LOG_ATTR_FLAG(has_time, 0x08); + CHECK_LOG_ATTR_FLAG(has_code, 0x10); + CHECK_LOG_ATTR_FLAG(has_details, 0x20); + CHECK_LOG_ATTR_FLAG(has_end, 0x40); + } } CATCH_TEST_CASE("Logger API") { @@ -620,10 +686,26 @@ CATCH_TEST_CASE("Logger API") { log.next().messageEquals("warn").levelEquals(LOG_LEVEL_WARN).categoryEquals(LOG_MODULE_CATEGORY); logger.error("%s", "error"); log.next().messageEquals("error").levelEquals(LOG_LEVEL_ERROR).categoryEquals(LOG_MODULE_CATEGORY); - logger(LOG_LEVEL_PANIC, "%s", "panic"); - log.next().messageEquals("panic").levelEquals(LOG_LEVEL_PANIC).categoryEquals(LOG_MODULE_CATEGORY); - logger("%s", "default"); // Uses default level + logger.log(LOG_LEVEL_INFO, "%s", "info"); + log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); + logger.log("%s", "default"); // Uses default level log.next().messageEquals("default").levelEquals(Logger::DEFAULT_LEVEL).categoryEquals(LOG_MODULE_CATEGORY); + logger(LOG_LEVEL_INFO, "%s", "info"); // Alias for Logger::log(LogLevel, const char *fmt) + log.next().messageEquals("info").levelEquals(LOG_LEVEL_INFO).categoryEquals(LOG_MODULE_CATEGORY); + logger("%s", "default"); // Alias for Logger::log(const char *fmt) + log.next().messageEquals("default").levelEquals(Logger::DEFAULT_LEVEL).categoryEquals(LOG_MODULE_CATEGORY); + } + CATCH_SECTION("additional attributes") { + TestLogHandler log(LOG_LEVEL_ALL); + Logger logger; + logger.log(""); + log.next().hasCode(false).hasDetails(false); // No additional attributes + // LogAttributes::code + logger.code(-1).log(""); + log.next().codeEquals(-1); + // LogAttributes::details + logger.details("details").info(""); + log.next().detailsEquals("details"); } CATCH_SECTION("direct logging") { TestLogHandler log(LOG_LEVEL_ALL); diff --git a/wiring/inc/spark_wiring_logging.h b/wiring/inc/spark_wiring_logging.h index 6e61142761..ad9c98e2b2 100644 --- a/wiring/inc/spark_wiring_logging.h +++ b/wiring/inc/spark_wiring_logging.h @@ -29,30 +29,24 @@ namespace spark { +class AttributedLogger; + /*! - \brief Log handler. + \brief Abstract log handler. - This class can be subclassed to implement custom log handlers. Log handlers act as "sinks" for - logging output generated by system and application modules and may have individual filtering - settings. + This class can be subclassed to implement custom log handlers. Log handlers act as "sinks" + for the overall logging output generated by the system and application modules, and may have + individual filtering settings. The library also provides several built-in handlers, such as \ref spark::SerialLogHandler and \ref spark::Serial1LogHandler. */ class LogHandler { public: - /*! - \brief Source file info. - */ - struct SourceInfo { - const char* file; //!< File name (can be null). - const char* function; //!< Function name (can be null). - int line; //!< Line number. - }; /*! \brief Category filter. - Describes minimal logging level allowed for category. + Specifies minimal logging level enabled for a matching category. */ typedef std::pair Filter; /*! @@ -75,7 +69,7 @@ class LogHandler { */ LogLevel defaultLevel() const; /*! - \brief Returns logging level for specified category. + \brief Returns logging level enabled for specified category. \param category Category name. */ LogLevel categoryLevel(const char *category) const; @@ -85,25 +79,21 @@ class LogHandler { */ static const char* levelName(LogLevel level); - // These methods are called by the LogManager instance - void message(const char *msg, LogLevel level, const char *category, uint32_t time, const SourceInfo &info); + // These methods are called by the LogManager + void message(const char *msg, LogLevel level, const char *category, const LogAttributes &attr); void write(const char *data, size_t size, LogLevel level, const char *category); protected: /*! - \brief Processes log message. + \brief Performs processing of a log message. \param msg Text message. \param level Logging level. \param category Category name (can be null). - \param time Timestamp (milliseconds since startup). - \param info Source file info. - - Default implementation generates messages in the following format: - `: [category]: [file]:[line], [function]: : `. + \param attr Message attributes. - Resulting string is then written to output stream via \ref write(const char*, size_t) method. + This method should be implemented by all subclasses. */ - virtual void logMessage(const char *msg, LogLevel level, const char *category, uint32_t time, const SourceInfo &info); + virtual void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) = 0; /*! \brief Writes character buffer to output stream. \param data Buffer. @@ -112,13 +102,6 @@ class LogHandler { Default implementation does nothing. */ virtual void write(const char *data, size_t size); - /*! - \brief Writes string to output stream. - \param str String. - - This method is equivalent to `write(str, strlen(str))`. - */ - void write(const char *str); private: struct FilterData; @@ -152,6 +135,17 @@ class StreamLogHandler: public LogHandler { Stream* stream() const; protected: + /*! + \brief Formats log message and writes it to output stream. + \param msg Text message. + \param level Logging level. + \param category Category name (can be null). + \param attr Message attributes. + + Default implementation generates messages in the following format: + ` [category] [file]:[line], [function]: : [attributes]`. + */ + virtual void logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) override; /*! \brief Writes character buffer to output stream. \param data Buffer. @@ -160,6 +154,13 @@ class StreamLogHandler: public LogHandler { This method is equivalent to `stream()->write((const uint8_t*)data, size)`. */ virtual void write(const char *data, size_t size) override; + /*! + \brief Writes string to output stream. + \param str String. + + This method is equivalent to `write(str, strlen(str))`. + */ + void write(const char *str); private: Stream *stream_; @@ -168,10 +169,10 @@ class StreamLogHandler: public LogHandler { /*! \brief Logger. - Primary interface for application logging. Most logging operations, except configuration, are - done through this class. + Primary interface for application logging. Most of the logging operations, except configuration, + are done through this class. - The library also declares default logger instance accessible as global \ref Log variable. + The library also declares default logger instance accessible as global \ref spark::Log variable. */ class Logger { public: @@ -207,6 +208,19 @@ class Logger { \param fmt Format string. */ void error(const char *fmt, ...) const __attribute__((format(printf, 2, 3))); + /*! + \brief Generates log message. + \param fmt Format string. + + This method uses default logging level (\ref DEFAULT_LEVEL). + */ + void log(const char *fmt, ...) const __attribute__((format(printf, 2, 3))); + /*! + \brief Generates log message. + \param level Logging level. + \param fmt Format string. + */ + void log(LogLevel level, const char *fmt, ...) const __attribute__((format(printf, 3, 4))); /*! \brief Writes formatted string to log. \param fmt Format string. @@ -289,25 +303,76 @@ class Logger { */ const char* name() const; /*! - \brief Generates log message. - \param fmt Format string. - - This method uses default logging level (\ref DEFAULT_LEVEL). + \brief Sets `LogAttributes::code` attribute. + \param code Code. + */ + AttributedLogger code(intptr_t code) const; + /*! + \brief Sets `LogAttributes::details` attribute. + \param str String. + */ + AttributedLogger details(const char *str) const; + /*! + \brief This method is an alias for \ref log(const char*, ...). */ void operator()(const char *fmt, ...) const __attribute__((format(printf, 2, 3))); /*! - \brief Generates log message. - \param level Logging level. - \param fmt Format string. + \brief This method is an alias for \ref log(LogLevel, const char*, ...). */ void operator()(LogLevel level, const char *fmt, ...) const __attribute__((format(printf, 3, 4))); private: - const char *name_; // Category name + const char* const name_; // Category name void log(LogLevel level, const char *fmt, va_list args) const; }; +/*! + \brief Attributed logger. + + Helper class allowing to set additional attributes for log messages. This class can be + instantiated only via \ref spark::Logger methods, e.g. \ref spark::Logger::code(): + + ``` + Logger log; + log.code(-1).details("details").info("This is info message"); + ``` +*/ +class AttributedLogger { +public: + /*! + \name Methods generating a log message. + + Refer to the \ref spark::Logger for the details. + */ + //! @{ + void trace(const char *fmt, ...) __attribute__((format(printf, 2, 3))); + void info(const char *fmt, ...) __attribute__((format(printf, 2, 3))); + void warn(const char *fmt, ...) __attribute__((format(printf, 2, 3))); + void error(const char *fmt, ...) __attribute__((format(printf, 2, 3))); + void log(const char *fmt, ...) __attribute__((format(printf, 2, 3))); + void log(LogLevel level, const char *fmt, ...) __attribute__((format(printf, 3, 4))); + //! @} + /*! + \name Setter methods for log message attributes. + + Refer to the \ref spark::Logger for the details. + */ + //! @{ + AttributedLogger& code(intptr_t code); + AttributedLogger& details(const char *str); + //! @} + +private: + const char* const name_; + LogAttributes attr_; + + explicit AttributedLogger(const char *name); + void log(LogLevel level, const char *fmt, va_list args); + + friend class Logger; +}; + /*! \brief Log manager. @@ -318,14 +383,14 @@ class LogManager { public: /*! \brief Registers log handler globally. - \param logger Handler instance. + \param handler Handler instance. Note that this method doesn't affect ownership over the handler object. */ void addHandler(LogHandler *handler); /*! \brief Unregisters log handler. - \param logger Handler instance. + \param handler Handler instance. */ void removeHandler(LogHandler *handler); /*! @@ -340,8 +405,7 @@ class LogManager { LogManager() = default; // System callbacks - static void logMessage(const char *msg, int level, const char *category, uint32_t time, const char *file, int line, - const char *func, void *reserved); + static void logMessage(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved); static void logWrite(const char *data, size_t size, int level, const char *category, void *reserved); static int logEnabled(int level, const char *category, void *reserved); }; @@ -354,9 +418,9 @@ extern const Logger Log; } // namespace spark // spark::LogHandler -inline void spark::LogHandler::message(const char *msg, LogLevel level, const char *category, uint32_t time, const SourceInfo &info) { +inline void spark::LogHandler::message(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) { if (level >= categoryLevel(category)) { - logMessage(msg, level, category, time, info); + logMessage(msg, level, category, attr); } } @@ -370,10 +434,6 @@ inline void spark::LogHandler::write(const char *data, size_t size) { // Default implementation does nothing } -inline void spark::LogHandler::write(const char *str) { - write(str, strlen(str)); -} - inline LogLevel spark::LogHandler::defaultLevel() const { return level_; } @@ -396,6 +456,10 @@ inline spark::StreamLogHandler::Stream* spark::StreamLogHandler::stream() const return stream_; } +inline void spark::StreamLogHandler::write(const char *str) { + write(str, strlen(str)); +} + // spark::Logger inline spark::Logger::Logger(const char *name) : name_(name) { @@ -429,6 +493,20 @@ inline void spark::Logger::error(const char *fmt, ...) const { va_end(args); } +inline void spark::Logger::log(const char *fmt, ...) const { + va_list args; + va_start(args, fmt); + log(DEFAULT_LEVEL, fmt, args); + va_end(args); +} + +inline void spark::Logger::log(LogLevel level, const char *fmt, ...) const { + va_list args; + va_start(args, fmt); + log(level, fmt, args); + va_end(args); +} + inline void spark::Logger::printf(const char *fmt, ...) const { va_list args; va_start(args, fmt); @@ -495,6 +573,18 @@ inline const char* spark::Logger::name() const { return name_; } +inline spark::AttributedLogger spark::Logger::code(intptr_t code) const { + AttributedLogger log(name_); + log.code(code); + return log; +} + +inline spark::AttributedLogger spark::Logger::details(const char *str) const { + AttributedLogger log(name_); + log.details(str); + return log; +} + inline void spark::Logger::operator()(const char *fmt, ...) const { va_list args; va_start(args, fmt); @@ -510,7 +600,73 @@ inline void spark::Logger::operator()(LogLevel level, const char *fmt, ...) cons } inline void spark::Logger::log(LogLevel level, const char *fmt, va_list args) const { - log_message_v(level, name_, nullptr, 0, nullptr, nullptr, fmt, args); + LogAttributes attr; + attr.size = sizeof(LogAttributes); + attr.flags = 0; + log_message_v(level, name_, &attr, nullptr, fmt, args); +} + +// spark::AttributedLogger +inline spark::AttributedLogger::AttributedLogger(const char *name) : + name_(name) { + attr_.size = sizeof(LogAttributes); + attr_.flags = 0; +} + +inline void spark::AttributedLogger::trace(const char *fmt, ...) { + va_list args; + va_start(args, fmt); + log(LOG_LEVEL_TRACE, fmt, args); + va_end(args); +} + +inline void spark::AttributedLogger::info(const char *fmt, ...) { + va_list args; + va_start(args, fmt); + log(LOG_LEVEL_INFO, fmt, args); + va_end(args); +} + +inline void spark::AttributedLogger::warn(const char *fmt, ...) { + va_list args; + va_start(args, fmt); + log(LOG_LEVEL_WARN, fmt, args); + va_end(args); +} + +inline void spark::AttributedLogger::error(const char *fmt, ...) { + va_list args; + va_start(args, fmt); + log(LOG_LEVEL_ERROR, fmt, args); + va_end(args); +} + +inline void spark::AttributedLogger::log(const char *fmt, ...) { + va_list args; + va_start(args, fmt); + log(Logger::DEFAULT_LEVEL, fmt, args); + va_end(args); +} + +inline void spark::AttributedLogger::log(LogLevel level, const char *fmt, ...) { + va_list args; + va_start(args, fmt); + log(level, fmt, args); + va_end(args); +} + +inline spark::AttributedLogger& spark::AttributedLogger::code(intptr_t code) { + LOG_ATTR_SET(attr_, code, code); + return *this; +} + +inline spark::AttributedLogger& spark::AttributedLogger::details(const char *str) { + LOG_ATTR_SET(attr_, details, str); + return *this; +} + +inline void spark::AttributedLogger::log(LogLevel level, const char *fmt, va_list args) { + log_message_v(level, name_, &attr_, nullptr, fmt, args); } #endif // SPARK_WIRING_LOGGING_H diff --git a/wiring/src/spark_wiring_logging.cpp b/wiring/src/spark_wiring_logging.cpp index be80a5ee1e..06e593fbdb 100644 --- a/wiring/src/spark_wiring_logging.cpp +++ b/wiring/src/spark_wiring_logging.cpp @@ -16,15 +16,32 @@ */ #include +#include #include #include "spark_wiring_logging.h" namespace { -inline const char* strchrend(const char* s, char c) { - const char* result = strchr(s, c); - return result ? result : s + strlen(s); +const char* extractFileName(const char *s) { + const char *s1 = strrchr(s, '/'); + if (s1) { + return s1 + 1; + } + return s; +} + +const char* extractFuncName(const char *s, size_t *size) { + const char *s1 = s; + for (; *s; ++s) { + if (*s == ' ') { + s1 = s + 1; // Skip return type + } else if (*s == '(') { + break; // Skip argument types + } + } + *size = s - s1; + return s1; } } // namespace @@ -156,50 +173,70 @@ LogLevel spark::LogHandler::categoryLevel(const char *category) const { return level; } -void spark::LogHandler::logMessage(const char *msg, LogLevel level, const char *category, uint32_t time, - const SourceInfo &info) { - // Timestamp +// spark::StreamLogHandler +void spark::StreamLogHandler::logMessage(const char *msg, LogLevel level, const char *category, const LogAttributes &attr) { char buf[16]; - snprintf(buf, sizeof(buf), "%010u ", (unsigned)time); - write(buf); - // Category (optional) + // Timestamp + if (attr.has_time) { + snprintf(buf, sizeof(buf), "%010u ", (unsigned)attr.time); + write(buf); + } + // Category if (category) { write("["); write(category); write("] "); } - // Source file (optional) - if (info.file) { - write(info.file); // File name - write(":"); - snprintf(buf, sizeof(buf), "%d", info.line); // Line number - write(buf); - if (info.function) { + // Source file + if (attr.has_file) { + // Strip directory path + const char *s = extractFileName(attr.file); + write(s); // File name + if (attr.has_line) { + write(":"); + snprintf(buf, sizeof(buf), "%d", attr.line); // Line number + write(buf); + } + if (attr.has_function) { write(", "); } else { write(": "); } } - // Function name (optional) - if (info.function) { + // Function name + if (attr.has_function) { // Strip argument and return types for better readability - int n = 0; - const char *p = strchrend(info.function, ' '); - if (*p) { - p += 1; - n = strchrend(p, '(') - p; - } else { - n = p - info.function; - p = info.function; - } - write(p, n); + size_t n = 0; + const char *s = extractFuncName(attr.function, &n); + write(s, n); write("(): "); } // Level write(levelName(level)); write(": "); // Message - write(msg); + if (msg) { + write(msg); + } + // Additional attributes + if (attr.has_code || attr.has_details) { + write(" ["); + if (attr.has_code) { + write("code"); + write(" = "); + snprintf(buf, sizeof(buf), "%" PRIiPTR, attr.code); + write(buf); + } + if (attr.has_details) { + if (attr.has_code) { + write(", "); + } + write("details"); + write(" = "); + write(attr.details); + } + write("]"); + } write("\r\n"); } @@ -229,12 +266,10 @@ spark::LogManager* spark::LogManager::instance() { return &mgr; } -void spark::LogManager::logMessage(const char *msg, int level, const char *category, uint32_t time, const char *file, - int line, const char *func, void *reserved) { - const LogHandler::SourceInfo info = {file, func, line}; +void spark::LogManager::logMessage(const char *msg, int level, const char *category, const LogAttributes *attr, void *reserved) { const auto &handlers = instance()->handlers_; for (size_t i = 0; i < handlers.size(); ++i) { - handlers[i]->message(msg, (LogLevel)level, category, time, info); + handlers[i]->message(msg, (LogLevel)level, category, *attr); } }