logging: add mechanism for handling transient strings
Extending logger to support logging transient strings (with %s).
With dedicated call (log_strdup), string is duplicated to a buffer
from internal logger pool. Logger implicitly manages the pool.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
diff --git a/doc/subsystems/logging/logger.rst b/doc/subsystems/logging/logger.rst
index 46f402d..dcf475e 100644
--- a/doc/subsystems/logging/logger.rst
+++ b/doc/subsystems/logging/logger.rst
@@ -19,6 +19,7 @@
- Additional run time filtering on module instance level.
- Timestamping with user provided function.
- Dedicated API for dumping data
+- Dedicated API for handling transient strings
- Panic support - in panic mode logger switches to blocking, in-place
processing.
- Printk support - printk message can be redirected to the logger.
@@ -120,6 +121,12 @@
message pool. Single message capable of storing standard log with up to 3
arguments or hexdump message with 12 bytes of data take 32 bytes.
+:option:`CONFIG_LOG_STRDUP_MAX_STRING`: Longest string that can be duplicated
+using log_strdup().
+
+:option:`CONFIG_LOG_STRDUP_BUF_COUNT`: Number of buffers in the pool used by
+log_strdup().
+
:option:`CONFIG_LOG_DOMAIN_ID`: Domain ID. Valid in multi-domain systems.
:option:`CONFIG_LOG_BACKEND_UART`: Enabled build-in UART backend.
@@ -347,6 +354,30 @@
is considered processed by the logger, but the message may still be in use by a
backend.
+.. _logger_strings:
+
+Logging strings
+===============
+Logger stores the address of a log message string argument passed to it. Because
+a string variable argument could be transient, allocated on the stack, or
+modifiable, logger provides a mechanism and a dedicated buffer pool to hold
+copies of strings. The buffer size and count is configurable
+(see :option:`CONFIG_LOG_STRDUP_MAX_STRING` and
+:option:`CONFIG_LOG_STRDUP_BUF_COUNT`).
+
+If a string argument is transient, the user must call cpp:func:`log_strdup` to
+duplicate the passed string into a buffer from the pool. See the examples below.
+If a strdup buffer cannot be allocated, a warning message is logged and an error
+code returned indicating :option:`CONFIG_LOG_STRDUP_BUF_COUNT` should be
+increased. Buffers are freed together with the log message.
+
+.. code-block:: c
+
+ char local_str[] = "abc";
+
+ LOG_INF("logging transient string: %s", log_strdup(local_str));
+ local_str[0] = '\0'; /* String can be modified, logger will use duplicate."
+
Logger backends
===============
@@ -403,17 +434,12 @@
Limitations
***********
-The Logger architecture implies following limitations:
+The Logger architecture has the following limitations:
-- Using *%s* for strings which content may be changed before log is processed
- e.g. strings allocated on stack because logger is storing only argument value
- and does not perform any string analysis to detect that argument is a
- pointer. It is recommended to use hexdump in that case. Optionally, user can
- enable in place processing :option:`CONFIG_LOG_INPLACE_PROCESS`. However,
- this feature has many limitations and is not recommended when logger is used
- in multiple contexts.
+- Strings as arguments (*%s*) require special treatment (see
+ :ref:`logger_strings`).
- Logging double floating point variables is not possible because arguments are
32 bit values.
-- Number of arguments in the string is limited to 6.
+- Number of arguments in the string is limited to 9.
diff --git a/include/logging/log.h b/include/logging/log.h
index 4dd8d76..8491bfa 100644
--- a/include/logging/log.h
+++ b/include/logging/log.h
@@ -255,6 +255,19 @@
*/
int log_printk(const char *fmt, va_list ap);
+/** @brief Copy transient string to a buffer from internal, logger pool.
+ *
+ * Function should be used when transient string is intended to be logged.
+ * Logger allocates a buffer and copies input string returning a pointer to the
+ * copy. Logger ensures that buffer is freed when logger message is freed.
+ *
+ * @param str Transient string.
+ *
+ * @return Copy of the string or default string if buffer could not be
+ * allocated. String may be truncated if input string does not fit in
+ * a buffer from the pool (see CONFIG_LOG_STRDUP_MAX_STRING).
+ */
+char *log_strdup(char *str);
#define __DYNAMIC_MODULE_REGISTER(_name)\
struct log_source_dynamic_data LOG_ITEM_DYNAMIC_DATA(_name) \
diff --git a/include/logging/log_core.h b/include/logging/log_core.h
index 03986b0..6cfd8b5 100644
--- a/include/logging/log_core.h
+++ b/include/logging/log_core.h
@@ -472,6 +472,20 @@
*/
void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap);
+/** @brief Check if address belongs to the memory pool used for transient.
+ *
+ * @param buf Buffer.
+ *
+ * @return True if address within the pool, false otherwise.
+ */
+bool log_is_strdup(void *buf);
+
+/** @brief Free allocated buffer.
+ *
+ * @param buf Buffer.
+ */
+void log_free(void *buf);
+
#ifdef __cplusplus
}
#endif
diff --git a/include/logging/log_msg.h b/include/logging/log_msg.h
index 6d99c4a..6b0dd37 100644
--- a/include/logging/log_msg.h
+++ b/include/logging/log_msg.h
@@ -23,7 +23,7 @@
*/
/** @brief Maximum number of arguments in the standard log entry. */
-#define LOG_MAX_NARGS 6
+#define LOG_MAX_NARGS 9
/** @brief Number of arguments in the log entry which fits in one chunk.*/
#define LOG_MSG_NARGS_SINGLE_CHUNK 3
diff --git a/samples/subsys/logging/logger/src/main.c b/samples/subsys/logging/logger/src/main.c
index d84815c..73e8fbd 100644
--- a/samples/subsys/logging/logger/src/main.c
+++ b/samples/subsys/logging/logger/src/main.c
@@ -152,6 +152,24 @@
}
/**
+ * @brief Function demonstrates how transient strings can be logged.
+ *
+ * Logger ensures that allocated buffers are freed when log message is
+ * processed.
+ */
+static void log_strdup_showcase(void)
+{
+ char transient_str[] = "transient_string";
+
+ printk("String logging showcase.\n");
+
+ LOG_INF("Logging transient string:%s", log_strdup(transient_str));
+
+ /* Overwrite transient string to show that the logger has a copy. */
+ transient_str[0] = '\0';
+}
+
+/**
* @brief Function demonstrates how fast data can be logged.
*
* Messages are logged and counted in a loop for 2 ticks (same clock source as
@@ -236,6 +254,10 @@
severity_levels_showcase();
+ log_strdup_showcase();
+
+ severity_levels_showcase();
+
wait_on_log_flushed();
performance_showcase();
diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig
index b427ce6..55ed07e 100644
--- a/subsys/logging/Kconfig
+++ b/subsys/logging/Kconfig
@@ -256,6 +256,20 @@
help
Number of bytes dedicated for the logger internal buffer.
+config LOG_STRDUP_MAX_STRING
+ int "Longest string that can be duplicated using log_strdup()"
+ default 46 if NETWORKING
+ default 32
+ help
+ Longer strings are truncated.
+
+config LOG_STRDUP_BUF_COUNT
+ int "Number of buffers in the pool used by log_strdup()"
+ default 4
+ help
+ When pool is empty log_strdup() returns warning string instead of the
+ copy.
+
config LOG_DOMAIN_ID
int "Domain ID"
default 0
diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c
index 1586e19..56f424f 100644
--- a/subsys/logging/log_core.c
+++ b/subsys/logging/log_core.c
@@ -17,6 +17,20 @@
#define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 1
#endif
+#define LOG_STRBUF_STR_SIZE \
+ (CONFIG_LOG_STRDUP_MAX_STRING + 1) /* additional byte for termination */
+
+#define LOG_STRBUF_BUF_SIZE \
+ ROUND_UP(LOG_STRBUF_STR_SIZE + 1, sizeof(u32_t))
+
+#define LOG_STRDUP_POOL_BUFFER_SIZE \
+ (LOG_STRBUF_BUF_SIZE * CONFIG_LOG_STRDUP_BUF_COUNT)
+
+static const char *log_strdup_fail_msg = "log_strdup pool empty!";
+struct k_mem_slab log_strdup_pool;
+static u8_t __noinit __aligned(sizeof(u32_t))
+ log_strdup_pool_buf[LOG_STRDUP_POOL_BUFFER_SIZE];
+
static struct log_list_t list;
static atomic_t initialized;
static bool panic_mode;
@@ -242,6 +256,10 @@
return;
}
+ k_mem_slab_init(&log_strdup_pool, log_strdup_pool_buf,
+ CONFIG_LOG_STRDUP_MAX_STRING,
+ CONFIG_LOG_STRDUP_BUF_COUNT);
+
/* Set default timestamp. */
timestamp_func = timestamp_get;
log_output_timestamp_freq_set(CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC);
@@ -482,6 +500,55 @@
}
}
+char *log_strdup(char *str)
+{
+ u32_t *dupl;
+ char *sdupl;
+ int err;
+
+ err = k_mem_slab_alloc(&log_strdup_pool, (void **)&dupl, K_NO_WAIT);
+ if (err) {
+ /* failed to allocate */
+ return (char *)log_strdup_fail_msg;
+ }
+
+ /* Set 'allocated' flag. */
+ *dupl = 1;
+ dupl++;
+ sdupl = (char *)dupl;
+
+ strncpy(sdupl, str, CONFIG_LOG_STRDUP_MAX_STRING - 1);
+ sdupl[LOG_STRBUF_STR_SIZE - 1] = '\0';
+ sdupl[LOG_STRBUF_STR_SIZE - 2] = '~';
+
+ return sdupl;
+}
+
+bool log_is_strdup(void *buf)
+{
+ /* Lowest possible address is located at the second word of the first
+ * buffer in the pool. First word is dedicated for 'allocated' flag.
+ *
+ * Highest possible address is the second word of the last buffer in the
+ * pool.
+ */
+ static const void *start = log_strdup_pool_buf + sizeof(u32_t);
+ static const void *end = &log_strdup_pool_buf[LOG_STRDUP_POOL_BUFFER_SIZE
+ - LOG_STRBUF_BUF_SIZE
+ + sizeof(u32_t)];
+ return (buf >= start) && (buf <= end);
+}
+
+void log_free(void *str)
+{
+ u32_t *buf = (u32_t *)str;
+
+ buf--;
+ if (atomic_dec((atomic_t *)buf) == 1) {
+ k_mem_slab_free(&log_strdup_pool, (void **)&buf);
+ }
+}
+
#ifdef CONFIG_LOG_PROCESS_THREAD
static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
{
diff --git a/subsys/logging/log_msg.c b/subsys/logging/log_msg.c
index 45ec86b..02c8aea 100644
--- a/subsys/logging/log_msg.c
+++ b/subsys/logging/log_msg.c
@@ -6,6 +6,7 @@
#include <kernel.h>
#include <logging/log_msg.h>
#include <logging/log_ctrl.h>
+#include <logging/log_core.h>
#include <string.h>
#define MSG_SIZE sizeof(union log_msg_chunk)
@@ -38,9 +39,25 @@
static void msg_free(struct log_msg *msg)
{
+ u32_t nargs = msg->hdr.params.std.nargs;
+
+ /* Free any transient string found in arguments. */
+ if (log_msg_is_std(msg) && nargs) {
+ int i;
+
+ for (i = 0; i < nargs; i++) {
+ void *buf = (void *)log_msg_arg_get(msg, i);
+
+ if (log_is_strdup(buf)) {
+ log_free(buf);
+ }
+ }
+ }
+
if (msg->hdr.params.generic.ext == 1) {
cont_free(msg->payload.ext.next);
}
+
k_mem_slab_free(&log_msg_pool, (void **)&msg);
}
diff --git a/tests/subsys/logging/log_core/prj.conf b/tests/subsys/logging/log_core/prj.conf
index a851e28..519b8c2 100644
--- a/tests/subsys/logging/log_core/prj.conf
+++ b/tests/subsys/logging/log_core/prj.conf
@@ -4,6 +4,6 @@
CONFIG_LOG_PRINTK=n
CONFIG_LOG_RUNTIME_FILTERING=y
CONFIG_LOG_BACKEND_UART=n
-CONFIG_LOG_BUFFER_SIZE=1024
+CONFIG_LOG_BUFFER_SIZE=512
CONFIG_LOG_INPLACE_PROCESS=n
CONFIG_LOG_PROCESS_THREAD=y
\ No newline at end of file
