Date
1 - 11 of 11
RFC[2/2] Common logging infrastructure and API
|
Saucedo Tejada, Genaro <genaro.saucedo.tejada@...>
From 9baee79d211bfb94aeed970c55f31cd3c4b2a8ad Mon Sep 17 00:00:00 2001
From: Genaro Saucedo Tejada <genaro.saucedo.tejada(a)intel.com> Date: Fri, 19 February 2016 23:10:28 +0000 Subject: [PATCH] Log macros unified in a common API Introduces a header to concentrate logging macro definitions for all code to reuse, change aims to provide all currently existing logging functionality so every C file can replace it's compile-unit definitions by common code. Later enhancements to log can now be performed in a single file. Features: * Optional printing of thread pointer * Optional printing of colored messages * Optional printing of a label to indicate logging level (info, error, warning, debug) * Caller function name printing * Incremental log levels * One point log disable Change-Id: Ibe542d69912778703bb43c7afef0889f0591ba6a Signed-off-by: Genaro Saucedo Tejada <genaro.saucedo.tejada(a)intel.com> --- drivers/grove/lcd_rgb.c | 14 +--- include/bluetooth/log.h | 28 +++---- include/logging.h | 166 ++++++++++++++++++++++++++++++++++++++++ misc/debug/Kconfig | 66 ++++++++++++++++ net/bluetooth/Kconfig | 3 +- net/bluetooth/hci_core.c | 5 -- tests/bluetooth/tester/prj.conf | 2 + 7 files changed, 250 insertions(+), 34 deletions(-) create mode 100644 include/logging.h diff --git a/drivers/grove/lcd_rgb.c b/drivers/grove/lcd_rgb.c index 58b86c5..7ef6a78 100644 --- a/drivers/grove/lcd_rgb.c +++ b/drivers/grove/lcd_rgb.c @@ -29,17 +29,9 @@ #define GROVE_LCD_DISPLAY_ADDR (0x3E) #define GROVE_RGB_BACKLIGHT_ADDR (0x62) -#ifndef CONFIG_GROVE_DEBUG -#define DBG(...) { ; } -#else -#if defined(CONFIG_STDOUT_CONSOLE) -#include <stdio.h> -#define DBG printf -#else -#include <misc/printk.h> -#define DBG printk -#endif /* CONFIG_STDOUT_CONSOLE */ -#endif /* CONFIG_GROVE_DEBUG */ +/* module specific logging check */ +#define LOG_THIS_MODULE CONFIG_GROVE_DEBUG +#include <logging.h> struct command { uint8_t control; diff --git a/include/bluetooth/log.h b/include/bluetooth/log.h index e47453a..e5abbab 100644 --- a/include/bluetooth/log.h +++ b/include/bluetooth/log.h @@ -26,25 +26,19 @@ extern "C" { #endif -#if defined(CONFIG_BLUETOOTH_DEBUG_COLOR) -#define BT_COLOR_OFF "\x1B[0m" -#define BT_COLOR_RED "\x1B[0;31m" -#define BT_COLOR_YELLOW "\x1B[0;33m" -#else -#define BT_COLOR_OFF "" -#define BT_COLOR_RED "" -#define BT_COLOR_YELLOW "" -#endif - #if defined(CONFIG_BLUETOOTH_DEBUG) + +/* module specific logging check */ +#define LOG_THIS_MODULE CONFIG_BLUETOOTH_DEBUG_HCI_CORE +/* specify logging domain */ +#define LOG_DMN "bt" +#include <logging.h> + #include <nanokernel.h> -#define BT_DBG(fmt, ...) printf("bt: %s (%p): " fmt "\n", __func__, \ - sys_thread_self_get(), ##__VA_ARGS__) -#define BT_ERR(fmt, ...) printf("bt: %s: %s" fmt "%s\n", __func__, \ - BT_COLOR_RED, ##__VA_ARGS__, BT_COLOR_OFF) -#define BT_WARN(fmt, ...) printf("bt: %s: %s" fmt "%s\n", __func__, \ - BT_COLOR_YELLOW, ##__VA_ARGS__, BT_COLOR_OFF) -#define BT_INFO(fmt, ...) printf("bt: " fmt "\n", ##__VA_ARGS__) +#define BT_DBG(fmt, ...) DBG(fmt, ##__VA_ARGS__) +#define BT_ERR(fmt, ...) ERR(fmt, ##__VA_ARGS__) +#define BT_WARN(fmt, ...) WRN(fmt, ##__VA_ARGS__) +#define BT_INFO(fmt, ...) INF(fmt, ##__VA_ARGS__) #define BT_ASSERT(cond) if (!(cond)) { \ BT_ERR("assert: '" #cond "' failed"); \ } diff --git a/include/logging.h b/include/logging.h new file mode 100644 index 0000000..d778da9 --- /dev/null +++ b/include/logging.h @@ -0,0 +1,166 @@ +/* + * Copyright (c) 2015 Intel Corporation + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +/** @file logging.h + * @brief Logging macros. + */ +#ifndef __LOGGING_H +#define __LOGGING_H + +#if !defined LOG_THIS_MODULE +#error DO NOT include this header without defining LOG_THIS_MODULE +#endif + +#if defined CONFIG_USE_COMPILE_LOG && (1 == LOG_THIS_MODULE) + +#define IS_LOGGING_ACTIVE 1 +#define THREAD_FN_CALL sys_thread_self_get() + +/* decide print func */ +#if defined(CONFIG_STDOUT_CONSOLE) +#include <stdio.h> +#define LOG_FN printf +#else +#include <misc/printk.h> +#define LOG_FN printk +#endif /* CONFIG_STDOUT_CONSOLE */ + +/* Should use color? */ +#if defined(CONFIG_USE_LOG_COLOR) +#define LOG_COLOR_OFF "\x1B[0m" +#define LOG_COLOR_RED "\x1B[0;31m" +#define LOG_COLOR_YELLOW "\x1B[0;33m" +#else +#define LOG_COLOR_OFF "" +#define LOG_COLOR_RED "" +#define LOG_COLOR_YELLOW "" +#endif /* CONFIG_BLUETOOTH_DEBUG_COLOR */ + +/* Should use log lv labels? */ +#if defined(CONFIG_USE_LOG_LV_TAGS) +#define LOG_LV_ERR "ERR " +#define LOG_LV_WRN "WRN " +#define LOG_LV_INF "INF " +#define LOG_LV_DBG "DBG " +#else +#define LOG_LV_ERR "" +#define LOG_LV_WRN "" +#define LOG_LV_INF "" +#define LOG_LV_DBG "" +#endif /* CONFIG_USE_LOG_LV_TAGS */ + +/* Log domain name */ +#if defined LOG_DMN +#define LOG_DMN_TAG LOG_DMN ":\t" +#else +#define LOG_DMN_TAG "" +#endif /* LOG_DMN */ + +/* Should thread be printed on log? */ +#if defined CONFIG_PRINT_THREAD_LOG +#define LOG_LAYOUT LOG_DMN_TAG "%s%s\t%p: %s" /* label func thread */ +#define LOG_FN_CALL(log_lv, log_color, log_format, color_off, ...) \ + LOG_FN(LOG_LAYOUT log_format "%s\n", \ + log_lv, __func__, THREAD_FN_CALL, log_color, ##__VA_ARGS__, color_off) +#else +#define LOG_LAYOUT LOG_DMN_TAG "%s%s\t: %s" /* label func */ +#define LOG_FN_CALL(log_lv, log_color, log_format, color_off, ...) \ + LOG_FN(LOG_LAYOUT log_format "%s\n", \ + log_lv, __func__, log_color, ##__VA_ARGS__, color_off) +#endif /* CONFIG_PRINT_THREAD_LOG */ + +#define LOG_NO_COLOR(log_lv, log_format, ...) \ + LOG_FN_CALL(log_lv, "", log_format, "", ##__VA_ARGS__) +#define LOG_COLOR(log_lv, log_color, log_format, ...) \ + LOG_FN_CALL(log_lv, log_color, log_format, LOG_COLOR_OFF, \ + ##__VA_ARGS__) + +/** + * @def INF + * + * @brief Writes information to log + * + * @details Lowest logging lv, these messages are not disabled unless whole + * logging gets disabled. + * + * @param A kprint valid format string and optinally, kprint formateable + * arguments. + */ +#define INF(...) LOG_NO_COLOR(LOG_LV_INF, ##__VA_ARGS__) + +#if defined(CONFIG_LOG_LV_ERR) || defined(CONFIG_LOG_LV_WRN) \ + || defined(CONFIG_LOG_LV_DBG) +/** + * @def ERR + * + * @brief Writes Errors to log + * + * @details available if CONFIG_USE_COMPILE_LOG is CONFIG_LOG_LV_ERR or higiher, + * it's meant to report fatal errors that can't be recovered from. + * + * @param A kprint valid format string and optinally, kprint formateable + * arguments. + */ +#define ERR(...) LOG_COLOR(LOG_LV_ERR, LOG_COLOR_RED, ##__VA_ARGS__) +#else +#define ERR(...) { ; } +#endif + +#if defined(CONFIG_LOG_LV_WRN) || defined(CONFIG_LOG_LV_DBG) +/** + * @def WRN + * + * @brief Writes warnings to log + * + * @details available if CONFIG_USE_COMPILE_LOG is CONFIG_LOG_LV_WRN or higiher, + * it's meant to print unexpedted situations that are not necesarily an error. + * + * @param A kprint valid format string and optinally, kprint formateable + * arguments. + */ +#define WRN(...) LOG_COLOR(LOG_LV_WRN, LOG_COLOR_YELLOW, ##__VA_ARGS__) +#else +#define WRN(...) { ; } +#endif + +#if defined(CONFIG_LOG_LV_DBG) +/** + * @def DBG + * + * @brief Writes debugging information to log + * + * @details highest logging level, available if CONFIG_USE_COMPILE_LOG is + * CONFIG_LOG_LV_DBG, it's meant to print developer information. + * + * @param A kprint valid format string and optinally, kprint formateable + * arguments. + */ +#define DBG(...) LOG_NO_COLOR(LOG_LV_DBG, ##__VA_ARGS__) +#else +#define DBG(...) { ; } +#endif + +#else +#define IS_LOGGING_ACTIVE 0 +/* create dummy macros */ +#define DBG(...) { ; } +#define ERR(...) { ; } +#define WRN(...) { ; } +#define INF(...) { ; } + +#endif /*USE_COMPILE_LOG*/ + +#endif /* __LOGGING_H */ diff --git a/misc/debug/Kconfig b/misc/debug/Kconfig index 51a3d3f..716a361 100644 --- a/misc/debug/Kconfig +++ b/misc/debug/Kconfig @@ -16,6 +16,72 @@ # limitations under the License. # +config USE_COMPILE_LOG + bool + prompt "Enable Logging" + default n + help + Global switch for logging. + +config USE_LOG_LV_TAGS + bool + prompt "Prepend level tags to logs" + depends on USE_COMPILE_LOG + default y + help + Log lines will beging with one of INF, ERR, WRN or DBG, depending on the + macro used at C code. + +config USE_LOG_COLOR + bool + prompt "Use colored logs" + depends on USE_COMPILE_LOG + default n + help + Use color in the logs. This requires an ANSI capable terminal. + +config PRINT_THREAD_LOG + bool + prompt "Include thread on log messages" + depends on USE_COMPILE_LOG + default n + help + Each log line will include the pointer of the thread that printed it + +choice +depends on USE_COMPILE_LOG +prompt "Log level" + +config LOG_LV_INF + bool + prompt "Info" + help + Print just unfiltered logging. + +config LOG_LV_ERR + bool + prompt "Error" + help + Do not filter printing of ERR logging macro, it is meant to report fatal + errors. + +config LOG_LV_WRN + bool + prompt "Warning" + help + Do not filter printing of WRN and above logging macros, WRN marcro is + meant to print messages generated under unexpedted circumstances, not + necesarily errors. + +config LOG_LV_DBG + bool + prompt "Debug" + help + Enable printing of all logging macros, DBG is meant to print developer + information. + +endchoice + menu "Safe memory access" diff --git a/net/bluetooth/Kconfig b/net/bluetooth/Kconfig index 8dcbbcf..222199d 100644 --- a/net/bluetooth/Kconfig +++ b/net/bluetooth/Kconfig @@ -218,7 +218,8 @@ config BLUETOOTH_DEBUG serial console. if BLUETOOTH_DEBUG -config BLUETOOTH_DEBUG_COLOR +config BLUETOOTH_DEBUG_COLOR + select USE_LOG_COLOR bool "Use colored logs" default y help diff --git a/net/bluetooth/hci_core.c b/net/bluetooth/hci_core.c index d5b6d24..00ad8d2 100644 --- a/net/bluetooth/hci_core.c +++ b/net/bluetooth/hci_core.c @@ -50,11 +50,6 @@ #include "smp.h" #endif /* CONFIG_BLUETOOTH_SMP */ -#if !defined(CONFIG_BLUETOOTH_DEBUG_HCI_CORE) -#undef BT_DBG -#define BT_DBG(fmt, ...) -#endif - /* Stacks for the fibers */ static BT_STACK_NOINIT(rx_fiber_stack, CONFIG_BLUETOOTH_RX_STACK_SIZE); static BT_STACK_NOINIT(rx_prio_fiber_stack, 256); diff --git a/tests/bluetooth/tester/prj.conf b/tests/bluetooth/tester/prj.conf index 617e07c..af53ace 100644 --- a/tests/bluetooth/tester/prj.conf +++ b/tests/bluetooth/tester/prj.conf @@ -1,5 +1,7 @@ CONFIG_UART_PIPE=y CONFIG_CONSOLE_HANDLER=y +CONFIG_USE_COMPILE_LOG=y +CONFIG_LOG_LV_DBG=y CONFIG_BLUETOOTH=y CONFIG_BLUETOOTH_LE=y CONFIG_BLUETOOTH_CENTRAL=y -- 2.5.0
|
|
|
|
Luiz Augusto von Dentz
Hi Genaro,
On Thu, Feb 25, 2016 at 12:13 AM, Saucedo Tejada, Genaro <genaro.saucedo.tejada(a)intel.com> wrote: From 9baee79d211bfb94aeed970c55f31cd3c4b2a8ad Mon Sep 17 00:00:00 2001I welcome these changes but Im not so sure logging levels are actually necessary if one can define different domains, at least in case of Bluetooth when you turn on debug for one particular domain you just get everything, if that is too much perhaps the domain needs to be split in sub-domains, anyway since your changes was based in Bluetooth and we did not have levels in the first place I assume it is no needed right now and can be added later provided someone make a case.
|
|
|
|
Tomasz Bursztyka
Hi Genaro,
The idea is nice, at least it will prevent to declare debug macros everywhere. However, split the patch: - first provide a patch with the logging.h and it's related Kconfig file - and only then whatever usage of it in further patch. I have small comments about logging.h and Kconfig: diff --git a/include/logging.h b/include/logging.hI wouldn't use LOG_THIS_MODULE also, rather something like LOG_ENABLE (Ok taste issue here, but a short name is nicer imo) And I do want to be able to include logging.h even if don't define it. So instead of the above just do: #ifdef LOG_ENABLE and add a relevant #endif below. Then I could use it like: #ifdef CONFIG_SPI_DEBUG #define LOG_ENABLE 1 #endif #include <logging.h> It avoids thes superfluous lines #else #define LOG_ENABLE 0 +Better something like LOG_COMPILE_TIME Thus it will ease grep on CONFIG_LOG_* for instance. + boolJust do bool "Enable Logging" No need of the prompt. You can apply that at all options below. + default nLOG_USE_LV_TAGS + boolLOG_USE_COLOR + boolLOG_PRINT_THREAD + boolIn the end we only have to deal with CONFIG_LOG_* prefixed options. Tomasz
|
|
|
|
Dirk Brandewie <dirk.j.brandewie@...>
On 02/24/2016 02:13 PM, Saucedo Tejada, Genaro wrote:
From 9baee79d211bfb94aeed970c55f31cd3c4b2a8ad Mon Sep 17 00:00:00 2001I like this in general we need a common set of debug output macros that all drivers can use. Currently we have a *bunch* of different versions of the same thing in use throughout the driver tree. I don't like the naming, we already have a kernel event logging API people may assume that the two facilities are connected based on the name. Can we change the names to debug_* or something else? Change-Id: Ibe542d69912778703bb43c7afef0889f0591ba6a
|
|
|
|
Benjamin Walsh <benjamin.walsh@...>
On Thu, Feb 25, 2016 at 07:05:49AM -0800, Dirk Brandewie wrote:
Again, do we want to take over _another_ namespace ? Maybe it should be sys_debug or sys_dbg or sys_dbg_log ? The sample implementation is adding all these in logging.h, which is a public API file: DBG, ERR, INF, WRN, THREAD_FN_CALL, IS_LOGGING_ACTIVE which are very generic names. Don't forget that the application writer is operating in the same C namespace, and we have been trying to keep the namespaces the kernel owns to a minimum to minimize the number or potential clashes: See doc/collaboration/code/naming_conventions.rst.
|
|
|
|
Dirk Brandewie <dirk.j.brandewie@...>
On 02/25/2016 07:47 AM, Benjamin Walsh wrote:
On Thu, Feb 25, 2016 at 07:05:49AM -0800, Dirk Brandewie wrote:It's the MACRO names the need fixed up IMO. Any functions that areAgain, do we want to take over _another_ namespace ? Maybe it should be added should be in the sys_* space sure. I didn't see any new C functions being added.
|
|
|
|
Nashif, Anas
Hi
toggle quoted messageShow quoted text
On 24/02/2016, 17:13, "Saucedo Tejada, Genaro" <genaro.saucedo.tejada(a)intel.com> wrote:
From 9baee79d211bfb94aeed970c55f31cd3c4b2a8ad Mon Sep 17 00:00:00 2001 From: Genaro Saucedo Tejada <genaro.saucedo.tejada(a)intel.com> See my comments on the first email.. - we need to make all existing code use this feature and how it was defined and avoid designing it to match EVERY existing custom logging and debugging implementation we currently have. - support multiple logging backends - split this patch, add the feature and testcases then add a sample that can be used for as a reference by developers - need to work on better variable names, avoid extreme abbreviations (LV -> LEVEL, DMN -> DOMAIN,...) few comments below.. The above should be defined using backend support. +/* Should use color? */ Use LEVEL instead of LV + DOMAIN +
|
|
|
|
Saucedo Tejada, Genaro <genaro.saucedo.tejada@...>
On Thu, 2016-02-25 at 07:54 -0800, Dirk Brandewie wrote:
Although a namespace is needed (as noted bellow) debug is not the only goal of this infrastructure INFO and ERROR level might be used for big production environments in the future. I reused some existing Kconfig variables but, as Anas pointed out, they should be updated to reflect the wider nature of logging, some of them do control debugging and should be split. I propose 'LOG_' as the prefix of all the function-like macros andIt's the MACRO names the need fixed up IMO. Any functions that are Kconfig variables, I'm using it for the improved patch set as place holder anyway but expect to mass rename if, for example, it gets decided to keep such name for the kernel event logger facility. An actual name space would be needed for a run-time implementation of a more complex logging facility, such as sys_log() instead of printf.
|
|
|
|
Kalowsky, Daniel <daniel.kalowsky@...>
toggle quoted messageShow quoted text
-----Original Message-----Can you share what a "production environment in the future" means? <... snip ...> I propose 'LOG_' as the prefix of all the function-like macros andRight. I think you're overlooking that by selecting LOG_, you're selecting the most obvious name for such a feature. By doing so, you're now taking that namespace away from any application developer. This is why we are suggesting the macros and any code functionality all start with the SYS_ prefix as that is already reserved by the kernel.
|
|
|
|
Saucedo Tejada, Genaro <genaro.saucedo.tejada@...>
On Wed, 2016-03-02 at 01:29 +0000, Kalowsky, Daniel wrote:
I mean applications could rely on log API to report the most important-----Original Message-----Can you share what a "production environment in the future" means? messages even in a complete application (that's what I meant by production), it wouldn't make sense to expect a terminal in that case but a rollover log on a file system could store these messages (future work), in this case a developer wouldn't be debugging the application, instead a user could be dealing with problems caused by external factors or simply monitoring. Other "logging" examples not exclusive to debugging were mentioned by Anas in another thread: "...send messages to a remote endpoint or write messages to a connected display". Got it, will change it to 'SYS_LOG_'.I propose 'LOG_' as the prefix of all the function-like macros andRight. I think you're overlooking that by selecting LOG_, you're
|
|
|
|
Tomasz Bursztyka
Hi,
How is this logging infra RFC going? :) Just noticed one thing to change as well: include/misc/__assert.h Would be nice if those __ASSERT macros would use this logging facilities as well. Tomasz
|
|
|