logging: Refactor LOG_MODULE_REGISTER and LOG_MODULE_DECLARE macros

Changed LOG_MODULE_REGISTER and LOG_MODULE_DECLARE macros to take log
level as optional parameter. LOG_MODULE_DECLARE can now also be used
in static inline functions in headers. Added LOG_LEVEL_SET macro
which is used when instance logging API is used to indicate maximal
log level compiled into the file.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>

doc/subsystems/logging/logger.rst

@@ -150,23 +150,45 @@ Logging in a module
 In order to use logger in the module, a unique name of a module must be
 specified and module must be registered with the logger core using
 :c:macro:`LOG_MODULE_REGISTER`. Optionally, a compile time log level for the
-module can be specified as well.
+module can be specified as the second parameter. Default log level
+(:option:`CONFIG_LOG_DEFAULT_LEVEL`) is used if custom log level is not
+provided.
 
 .. code-block:: c
 
-   #define LOG_LEVEL CONFIG_FOO_LOG_LEVEL /* From foo module Kconfig */
    #include <logging/log.h>
-   LOG_MODULE_REGISTER(foo); /* One per given log_module_name */
+   LOG_MODULE_REGISTER(foo, CONFIG_FOO_LOG_LEVEL);
 
 If the module consists of multiple files, then ``LOG_MODULE_REGISTER()`` should
 appear in exactly one of them. Each other file should use
 :c:macro:`LOG_MODULE_DECLARE` to declare its membership in the module.
+Optionally, a compile time log level for the module can be specified as
+the second parameter. Default log level (:option:`CONFIG_LOG_DEFAULT_LEVEL`)
+is used if custom log level is not provided.
 
 .. code-block:: c
 
-   #define LOG_LEVEL CONFIG_FOO_LOG_LEVEL /* From foo module Kconfig */
    #include <logging/log.h>
-   LOG_MODULE_DECLARE(foo); /* In all files comprising the module but one */
+   /* In all files comprising the module but one */
+   LOG_MODULE_DECLARE(foo, CONFIG_FOO_LOG_LEVEL);
+
+In order to use logger API in a function implemented in a header file
+:c:macro:`LOG_MODULE_DECLARE` macro must be used in the function body
+before logger API is called. Optionally, a compile time log level for the module
+can be specified as the second parameter. Default log level
+(:option:`CONFIG_LOG_DEFAULT_LEVEL`) is used if custom log level is not
+provided.
+
+.. code-block:: c
+
+   #include <logging/log.h>
+
+   static inline void foo(void)
+   {
+   	LOG_MODULE_DECLARE(foo, CONFIG_FOO_LOG_LEVEL);
+
+   	LOG_INF("foo");
+   }
 
 Dedicated Kconfig template (:file:`subsys/logging/Kconfig.template.log_config`)
 can be used to create local log level configuration.
@@ -216,15 +238,30 @@ In order to use instance level filtering following steps must be performed:
 Note that when logger is disabled logger instance and pointer to that instance
 are not created.
 
-- logger can be used in function
+In order to use the instance logging API in a source file, a compile-time log
+level must be set using :c:macro:`LOG_LEVEL_SET`.
 
 .. code-block:: c
 
+   LOG_LEVEL_SET(CONFIG_FOO_LOG_LEVEL);
+
    void foo_init(foo_object *f)
    {
    	LOG_INST_INF(f->log, "Initialized.");
    }
 
+In order to use the instance logging API in a header file, a compile-time log
+level must be set using :c:macro:`LOG_LEVEL_SET`.
+
+.. code-block:: c
+
+   static inline void foo_init(foo_object *f)
+   {
+   	LOG_LEVEL_SET(CONFIG_FOO_LOG_LEVEL);
+
+   	LOG_INST_INF(f->log, "Initialized.");
+   }
+
 Controlling the logger
 ======================
 

include/logging/log.h

@@ -269,39 +269,47 @@ int log_printk(const char *fmt, va_list ap);
  */
 char *log_strdup(const char *str);
 
-#define __DYNAMIC_MODULE_REGISTER(_name)\
-	struct log_source_dynamic_data LOG_ITEM_DYNAMIC_DATA(_name)	\
-	__attribute__ ((section("." STRINGIFY(				\
-				     LOG_ITEM_DYNAMIC_DATA(_name))))	\
-				     )					\
-	__attribute__((used));						\
-	static inline const struct log_source_dynamic_data  *		\
-				__log_current_dynamic_data_get(void)	\
-	{								\
-		return &LOG_ITEM_DYNAMIC_DATA(_name);			\
-	}
+/* Macro expects that optionally on second argument local log level is provided.
+ * If provided it is returned, otherwise default log level is returned.
+ */
+#if defined(LOG_LEVEL) && defined(CONFIG_LOG)
+#define _LOG_LEVEL_RESOLVE(...) \
+	__LOG_ARG_2(__VA_ARGS__, LOG_LEVEL)
+#else
+#define _LOG_LEVEL_RESOLVE(...) \
+	__LOG_ARG_2(__VA_ARGS__, CONFIG_LOG_DEFAULT_LEVEL)
+#endif
 
-#define _LOG_RUNTIME_MODULE_REGISTER(_name)				\
-	_LOG_EVAL(							\
-		CONFIG_LOG_RUNTIME_FILTERING,				\
-		(; __DYNAMIC_MODULE_REGISTER(_name)),			\
-		()							\
-	)
+/* Return first argument */
+#define _LOG_ARG1(arg1, ...) arg1
 
-#define _LOG_MODULE_REGISTER(_name, _level)				     \
+
+#define _LOG_MODULE_CONST_DATA_CREATE(_name, _level)			     \
 	const struct log_source_const_data LOG_ITEM_CONST_DATA(_name)	     \
 	__attribute__ ((section("." STRINGIFY(LOG_ITEM_CONST_DATA(_name))))) \
 	__attribute__((used)) = {					     \
 		.name = STRINGIFY(_name),				     \
 		.level = _level						     \
-	}								     \
-	_LOG_RUNTIME_MODULE_REGISTER(_name);				     \
-	static inline const struct log_source_const_data *		     \
-				__log_current_const_data_get(void)	     \
-	{								     \
-		return &LOG_ITEM_CONST_DATA(_name);			     \
 	}
 
+#define _LOG_MODULE_DYNAMIC_DATA_CREATE(_name)				\
+	struct log_source_dynamic_data LOG_ITEM_DYNAMIC_DATA(_name)	\
+	__attribute__ ((section("." STRINGIFY(				\
+				     LOG_ITEM_DYNAMIC_DATA(_name))))	\
+				     )					\
+	__attribute__((used))
+
+#define _LOG_MODULE_DYNAMIC_DATA_COND_CREATE(_name)		\
+	_LOG_EVAL(						\
+		IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING),	\
+		(_LOG_MODULE_DYNAMIC_DATA_CREATE(_name);),	\
+		()						\
+		)
+
+#define _LOG_MODULE_DATA_CREATE(_name, _level)			\
+	_LOG_MODULE_CONST_DATA_CREATE(_name, _level);		\
+	_LOG_MODULE_DYNAMIC_DATA_COND_CREATE(_name)
+
 /**
  * @brief Create module-specific state and register the module with Logger.
  *
@@ -313,7 +321,19 @@ char *log_strdup(const char *str);
  * - The module consists of more than one file, and another file
  *   invokes this macro. (LOG_MODULE_DECLARE() should be used instead
  *   in all of the module's other files.)
- * - Instance logging is used and there is no need to create module entry.
+ * - Instance logging is used and there is no need to create module entry. In
+ *   that case LOG_LEVEL_SET() should be used to set log level used within the
+ *   file.
+ *
+ * Macro accepts one or two parameters:
+ * - module name
+ * - optional log level. If not provided then default log level is used in
+ *  the file.
+ *
+ * Example usage:
+ * - LOG_MODULE_REGISTER(foo, CONFIG_FOO_LOG_LEVEL)
+ * - LOG_MODULE_REGISTER(foo)
+ *
  *
  * @note The module's state is defined, and the module is registered,
  *       only if LOG_LEVEL for the current source file is non-zero or
@@ -321,36 +341,16 @@ char *log_strdup(const char *str);
  *       In other cases, this macro has no effect.
  * @see LOG_MODULE_DECLARE
  */
-#define LOG_MODULE_REGISTER(log_module_name)				\
-	_LOG_EVAL(							\
-		_LOG_LEVEL(),						\
-		(_LOG_MODULE_REGISTER(log_module_name, _LOG_LEVEL())),	\
-		()/*Empty*/						\
-	)
-
-#define __DYNAMIC_MODULE_DECLARE(_name)					   \
-	extern struct log_source_dynamic_data LOG_ITEM_DYNAMIC_DATA(_name);\
-	static inline struct log_source_dynamic_data *			   \
-				__log_current_dynamic_data_get(void)	   \
-	{								   \
-		return &LOG_ITEM_DYNAMIC_DATA(_name);			   \
-	}
 
-#define _LOG_RUNTIME_MODULE_DECLARE(_name)			\
-	_LOG_EVAL(						\
-		CONFIG_LOG_RUNTIME_FILTERING,			\
-		(; __DYNAMIC_MODULE_DECLARE(_name)),		\
-		()						\
-		)
 
-#define _LOG_MODULE_DECLARE(_name, _level)				     \
-	extern const struct log_source_const_data LOG_ITEM_CONST_DATA(_name) \
-	_LOG_RUNTIME_MODULE_DECLARE(_name);				     \
-	static inline const struct log_source_const_data *		     \
-				__log_current_const_data_get(void)	     \
-	{								     \
-		return &LOG_ITEM_CONST_DATA(_name);			     \
-	}
+#define LOG_MODULE_REGISTER(...)					\
+	_LOG_EVAL(							\
+		_LOG_LEVEL_RESOLVE(__VA_ARGS__),			\
+		(_LOG_MODULE_DATA_CREATE(_LOG_ARG1(__VA_ARGS__),	\
+				      _LOG_LEVEL_RESOLVE(__VA_ARGS__))),\
+		()/*Empty*/						\
+	)								\
+	LOG_MODULE_DECLARE(__VA_ARGS__)
 
 /**
  * @brief Macro for declaring a log module (not registering it).
@@ -363,18 +363,50 @@ char *log_strdup(const char *str);
  * declare that same state. (Otherwise, LOG_INF() etc. will not be
  * able to refer to module-specific state variables.)
  *
+ * Macro accepts one or two parameters:
+ * - module name
+ * - optional log level. If not provided then default log level is used in
+ *  the file.
+ *
+ * Example usage:
+ * - LOG_MODULE_DECLARE(foo, CONFIG_FOO_LOG_LEVEL)
+ * - LOG_MODULE_DECLARE(foo)
+ *
  * @note The module's state is declared only if LOG_LEVEL for the
  *       current source file is non-zero or it is not defined and
  *       CONFIG_LOG_DEFAULT_LOG_LEVEL is non-zero.  In other cases,
  *       this macro has no effect.
  * @see LOG_MODULE_REGISTER
  */
-#define LOG_MODULE_DECLARE(log_module_name)				\
-	_LOG_EVAL(							\
-		_LOG_LEVEL(),						\
-		(_LOG_MODULE_DECLARE(log_module_name, _LOG_LEVEL())),	\
-		()							\
-		)							\
+#define LOG_MODULE_DECLARE(...)						      \
+	extern const struct log_source_const_data			      \
+			LOG_ITEM_CONST_DATA(_LOG_ARG1(__VA_ARGS__));	      \
+	extern struct log_source_dynamic_data				      \
+			LOG_ITEM_DYNAMIC_DATA(_LOG_ARG1(__VA_ARGS__));	      \
+									      \
+	static const struct log_source_const_data *			      \
+		__log_current_const_data __attribute__((unused)) =	      \
+			_LOG_LEVEL_RESOLVE(__VA_ARGS__) ?		      \
+			&LOG_ITEM_CONST_DATA(_LOG_ARG1(__VA_ARGS__)) : NULL;  \
+									      \
+	static struct log_source_dynamic_data *				      \
+		__log_current_dynamic_data __attribute__((unused)) =	      \
+			(_LOG_LEVEL_RESOLVE(__VA_ARGS__) &&		      \
+			IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) ?	      \
+			&LOG_ITEM_DYNAMIC_DATA(_LOG_ARG1(__VA_ARGS__)) : NULL;\
+									      \
+	static const u32_t __log_level __attribute__((unused)) =	      \
+					_LOG_LEVEL_RESOLVE(__VA_ARGS__)
+
+/**
+ * @brief Macro for setting log level in the file or function where instance
+ * logging API is used.
+ *
+ * @param level Level used in file or in function.
+ *
+ */
+#define LOG_LEVEL_SET(level) \
+	static const u32_t __log_level __attribute__((unused)) = level
 
 /**
  * @}

include/logging/log_core.h

@@ -55,8 +55,8 @@ extern "C" {
 /**
  * @brief Macro for conditional code generation if provided log level allows.
  *
- * Macro behaves similarly to standard #if #else #endif clause. The difference is
- * that it is evaluated when used and not when header file is included.
+ * Macro behaves similarly to standard #if #else #endif clause. The difference
+ * is that it is evaluated when used and not when header file is included.
  *
  * @param _eval_level Evaluated level. If level evaluates to one of existing log
  *		      log level (1-4) then macro evaluates to _iftrue.
@@ -112,44 +112,39 @@ extern "C" {
  *
  *  @param _addr Address of the element.
  */
-#define LOG_CONST_ID_GET(_addr)						       \
-	_LOG_EVAL(							       \
-	  _LOG_LEVEL(),							       \
-	  (log_const_source_id((const struct log_source_const_data *)_addr)),  \
-	  (0)								       \
+#define LOG_CONST_ID_GET(_addr) \
+	_LOG_EVAL(\
+	  CONFIG_LOG,\
+	  (__log_level ? \
+	  log_const_source_id((const struct log_source_const_data *)_addr) : \
+	  0),\
+	  (0)\
 	)
 
 /**
  * @def LOG_CURRENT_MODULE_ID
  * @brief Macro for getting ID of current module.
  */
-#define LOG_CURRENT_MODULE_ID()						\
-	_LOG_EVAL(							\
-	  _LOG_LEVEL(),							\
-	  (log_const_source_id(__log_current_const_data_get())),	\
-	  (0)								\
-	)
+#define LOG_CURRENT_MODULE_ID() (__log_level ? \
+	log_const_source_id(__log_current_const_data) : 0)
 
 /**
  * @def LOG_CURRENT_DYNAMIC_DATA_ADDR
  * @brief Macro for getting address of dynamic structure of current module.
  */
-#define LOG_CURRENT_DYNAMIC_DATA_ADDR()			\
-	_LOG_EVAL(					\
-	  _LOG_LEVEL(),					\
-	  (__log_current_dynamic_data_get()),		\
-	  ((struct log_source_dynamic_data *)0)		\
-	)
+#define LOG_CURRENT_DYNAMIC_DATA_ADDR()	(__log_level ? \
+	__log_current_dynamic_data : (struct log_source_dynamic_data *)0)
 
 /** @brief Macro for getting ID of the element of the section.
  *
  *  @param _addr Address of the element.
  */
-#define LOG_DYNAMIC_ID_GET(_addr)					     \
-	_LOG_EVAL(							     \
-	  _LOG_LEVEL(),							     \
-	  (log_dynamic_source_id((struct log_source_dynamic_data *)_addr)),  \
-	  (0)								     \
+#define LOG_DYNAMIC_ID_GET(_addr) \
+	_LOG_EVAL(\
+	  CONFIG_LOG,\
+	  (__log_level ? \
+	  log_dynamic_source_id((struct log_source_dynamic_data *)_addr) : 0),\
+	  (0)\
 	)
 
 /**
@@ -230,7 +225,7 @@ extern "C" {
 	_LOG_LEVEL_CHECK(_level, CONFIG_LOG_OVERRIDE_LEVEL, LOG_LEVEL_NONE) \
 	||								    \
 	(!IS_ENABLED(CONFIG_LOG_OVERRIDE_LEVEL) &&			    \
-	_LOG_LEVEL_CHECK(_level, LOG_LEVEL, CONFIG_LOG_DEFAULT_LEVEL) &&    \
+	(_level <= __log_level) &&					    \
 	(_level <= CONFIG_LOG_MAX_LEVEL)				    \
 	)								    \
 	))

samples/subsys/logging/logger/src/main.c

@@ -81,6 +81,7 @@ static void module_logging_showcase(void)
 	printk("Module logging showcase.\n");
 
 	sample_module_func();
+	inline_func();
 
 	if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
 		printk("Disabling logging in the %s module\n",
@@ -111,7 +112,9 @@ static void instance_logging_showcase(void)
 {
 	printk("Instance level logging showcase.\n");
 
+	sample_instance_inline_call(&inst1);
 	sample_instance_call(&inst1);
+	sample_instance_inline_call(&inst2);
 	sample_instance_call(&inst2);
 
 	if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
@@ -121,7 +124,9 @@ static void instance_logging_showcase(void)
 		log_filter_set(NULL, 0,
 			       log_source_id_get(INST1_NAME), LOG_LEVEL_WRN);
 
+		sample_instance_inline_call(&inst1);
 		sample_instance_call(&inst1);
+		sample_instance_inline_call(&inst2);
 		sample_instance_call(&inst2);
 
 		printk("Disabling logging on both instances.\n");
@@ -134,7 +139,9 @@ static void instance_logging_showcase(void)
 			       log_source_id_get(INST2_NAME),
 			       LOG_LEVEL_NONE);
 
+		sample_instance_inline_call(&inst1);
 		sample_instance_call(&inst1);
+		sample_instance_inline_call(&inst2);
 		sample_instance_call(&inst2);
 
 		printk("Function call on both instances with logging disabled.\n");

samples/subsys/logging/logger/src/sample_instance.c

@@ -11,6 +11,8 @@
  */
 #include <logging/log.h>
 
+LOG_LEVEL_SET(LOG_LEVEL_INF);
+
 void sample_instance_call(struct sample_instance *inst)
 {
 	u8_t data[4] = { 1, 2, 3, 4 };

samples/subsys/logging/logger/src/sample_instance.h

@@ -8,6 +8,7 @@
 
 #include <kernel.h>
 #include <logging/log_instance.h>
+#include <logging/log.h>
 
 #define SAMPLE_INSTANCE_NAME sample_instance
 
@@ -16,12 +17,19 @@ struct sample_instance {
 	u32_t cnt;
 };
 
-#define SAMPLE_INSTANCE_DEFINE(_name)					\
-	LOG_INSTANCE_REGISTER(SAMPLE_INSTANCE_NAME, _name, 3);		\
-	struct sample_instance _name = {				\
-		LOG_INSTANCE_PTR_INIT(log, SAMPLE_INSTANCE_NAME, _name)	\
+#define SAMPLE_INSTANCE_DEFINE(_name)					   \
+	LOG_INSTANCE_REGISTER(SAMPLE_INSTANCE_NAME, _name, LOG_LEVEL_INF); \
+	struct sample_instance _name = {				   \
+		LOG_INSTANCE_PTR_INIT(log, SAMPLE_INSTANCE_NAME, _name)	   \
 	}
 
 void sample_instance_call(struct sample_instance *inst);
 
+static inline void sample_instance_inline_call(struct sample_instance *inst)
+{
+	LOG_LEVEL_SET(LOG_LEVEL_INF);
+
+	LOG_INST_INF(inst->log, "Inline call.");
+}
+
 #endif /*SAMPLE_INSTANCE_H*/

samples/subsys/logging/logger/src/sample_module.c

@@ -5,14 +5,13 @@
  */
 #include <zephyr.h>
 #include <logging/log.h>
+#include "sample_module.h"
 
-#define LOG_MODULE_NAME sample_module
-#define LOG_LEVEL CONFIG_SAMPLE_MODULE_LOG_LEVEL
-LOG_MODULE_REGISTER(LOG_MODULE_NAME);
+LOG_MODULE_REGISTER(MODULE_NAME, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
 
 const char *sample_module_name_get(void)
 {
-	return STRINGIFY(LOG_MODULE_NAME);
+	return STRINGIFY(MODULE_NAME);
 }
 
 void sample_module_func(void)

samples/subsys/logging/logger/src/sample_module.h

@@ -9,10 +9,20 @@
 #ifdef __cplusplus
 extern "C" {
 #endif
+#include <logging/log.h>
+
+#define MODULE_NAME sample_module
 
 const char *sample_module_name_get(void);
 void sample_module_func(void);
 
+static inline void inline_func(void)
+{
+	LOG_MODULE_DECLARE(MODULE_NAME, CONFIG_SAMPLE_MODULE_LOG_LEVEL);
+
+	LOG_INF("Inline function.");
+}
+
 #ifdef __cplusplus
 }
 #endif

subsys/power/Kconfig

@@ -9,5 +9,9 @@ config PM_CONTROL_OS_DEBUG
 	help
 	  Enable OS Power Management debugging hooks.
 
+module = PM
+module-str = Power Management
+source "subsys/logging/Kconfig.template.log_config"
+
 endmenu
 endif # PM_CONTROL_OS

subsys/power/power.c

@@ -11,7 +11,7 @@
 #include <soc.h>
 #include "policy/pm_policy.h"
 
-#define LOG_LEVEL CONFIG_PM_LOG_LEVEL /* From power module Kconfig */
+#define LOG_LEVEL CONFIG_PM_LOG_LEVEL
 #include <logging/log.h>
 LOG_MODULE_REGISTER(power);
 

tests/subsys/logging/log_core/src/log_core_test.c

@@ -17,10 +17,10 @@
 #include <ztest.h>
 #include <logging/log_backend.h>
 #include <logging/log_ctrl.h>
+#include <logging/log.h>
+#include "test_module.h"
 
 #define LOG_MODULE_NAME test
-#include "logging/log.h"
-
 LOG_MODULE_REGISTER(LOG_MODULE_NAME);
 
 typedef void (*custom_put_callback_t)(struct log_backend const *const backend,
@@ -152,6 +152,8 @@ static void log_setup(bool backend2_enable)
 		memset(&backend2_cb, 0, sizeof(backend2_cb));
 
 		log_backend_enable(&backend2, &backend2_cb, LOG_LEVEL_DBG);
+	} else {
+		log_backend_disable(&backend2);
 	}
 
 	test_source_id = log_source_id_get(STRINGIFY(LOG_MODULE_NAME));
@@ -314,11 +316,10 @@ static void test_log_panic(void)
 		      "Unexpected amount of messages received by the backend.");
 }
 
-/* extern function comes from the file which is part of test module. It is
+/* Function comes from the file which is part of test module. It is
  * expected that logs coming from it will have same source_id as current
  * module (this file).
  */
-extern void test_func(void);
 static void test_log_from_declared_module(void)
 {
 	log_setup(false);
@@ -326,13 +327,15 @@ static void test_log_from_declared_module(void)
 	/* Setup log backend to validate source_id of the message. */
 	backend1_cb.check_id = true;
 	backend1_cb.exp_id[0] = LOG_CURRENT_MODULE_ID();
+	backend1_cb.exp_id[1] = LOG_CURRENT_MODULE_ID();
 
 	test_func();
+	test_inline_func();
 
 	while (log_process(false)) {
 	}
 
-	zassert_equal(1, backend1_cb.counter,
+	zassert_equal(2, backend1_cb.counter,
 		      "Unexpected amount of messages received by the backend.");
 }
 

tests/subsys/logging/log_core/src/test_module.c

@@ -11,6 +11,7 @@
  */
 
 #include <logging/log.h>
+
 LOG_MODULE_DECLARE(test);
 
 void test_func(void)

tests/subsys/logging/log_core/src/test_module.h

@@ -0,0 +1,21 @@
+/*
+ * Copyright (c) 2018 Nordic Semiconductor ASA
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+
+#ifndef TEST_MODULE_H
+#define TEST_MODULE_H
+
+#include <logging/log.h>
+
+void test_func(void);
+
+static inline void test_inline_func(void)
+{
+	LOG_MODULE_DECLARE(test);
+
+	LOG_ERR("inline");
+}
+
+#endif /* TEST_MODULE_H */