From 8cdaa0798b68c8c25660cbd39f0b4b7192ac25fd Mon Sep 17 00:00:00 2001 From: Moody Liu Date: Thu, 1 Aug 2024 23:30:52 +0100 Subject: [PATCH] syslog: migrate structured logging --- kernel/CMakeLists.txt | 3 + kernel/include/private/mos/syslog/debug.h | 14 +++- kernel/include/private/mos/syslog/printk.h | 32 +++----- .../private/mos/syslog/printk_prefix.h | 73 ------------------- kernel/include/private/mos/syslog/syslog.h | 19 +++++ kernel/misc/kutils.c | 2 +- kernel/syslog/debug.c | 15 ++-- kernel/syslog/syslog.c | 71 ++++++++++++++++++ proto/syslog.proto | 55 ++++++++++++++ 9 files changed, 179 insertions(+), 105 deletions(-) delete mode 100644 kernel/include/private/mos/syslog/printk_prefix.h create mode 100644 kernel/include/private/mos/syslog/syslog.h create mode 100644 kernel/syslog/syslog.c create mode 100644 proto/syslog.proto diff --git a/kernel/CMakeLists.txt b/kernel/CMakeLists.txt index dce23789..c11719c0 100644 --- a/kernel/CMakeLists.txt +++ b/kernel/CMakeLists.txt @@ -101,4 +101,7 @@ add_kernel_source(kmain.c ksyscall_entry.c ksyscall.c) generate_nanopb_proto(FILESYSTEM_PROTO_SRCS FILESYSTEM_PROTO_HEADERS ${CMAKE_SOURCE_DIR}/proto/mos_rpc.proto ${CMAKE_SOURCE_DIR}/proto/filesystem.proto) add_kernel_source(${FILESYSTEM_PROTO_SRCS} ${FILESYSTEM_PROTO_HEADERS}) +generate_nanopb_proto(SYSLOG_PROTO_SRCS SYSLOG_PROTO_HEADERS ${CMAKE_SOURCE_DIR}/proto/syslog.proto) +add_kernel_source(${SYSLOG_PROTO_SRCS} ${SYSLOG_PROTO_HEADERS}) + add_subdirectory(tests) diff --git a/kernel/include/private/mos/syslog/debug.h b/kernel/include/private/mos/syslog/debug.h index cf563d51..f786953b 100644 --- a/kernel/include/private/mos/syslog/debug.h +++ b/kernel/include/private/mos/syslog/debug.h @@ -50,15 +50,23 @@ // clang-format on #if MOS_CONFIG(MOS_DYNAMIC_DEBUG) + +typedef struct _debug_info_entry +{ + u32 id; + const char *name; + bool enabled; +} debug_info_entry; + extern struct _mos_debug_info { -#define _expand_field(name) bool name; +#define _expand_field(name) debug_info_entry name; MOS_ALL_DEBUG_MODULES(_expand_field) #undef _expand_field } mos_debug_info; -#define mos_debug_enabled(name) (mos_debug_info.name) -#define mos_debug_enabled_ptr(name) (&mos_debug_info.name) +#define mos_debug_enabled(name) (mos_debug_info.name.enabled) +#define mos_debug_enabled_ptr(name) (&mos_debug_info.name.enabled) #else #define mos_debug_enabled(name) MOS_DEBUG_FEATURE(name) #define mos_debug_enabled_ptr(name) NULL diff --git a/kernel/include/private/mos/syslog/printk.h b/kernel/include/private/mos/syslog/printk.h index 97ed921c..695d8b19 100644 --- a/kernel/include/private/mos/syslog/printk.h +++ b/kernel/include/private/mos/syslog/printk.h @@ -3,31 +3,23 @@ #pragma once #include "mos/syslog/debug.h" -#include "mos/syslog/printk_prefix.h" +#include "mos/syslog/syslog.h" #include #include -typedef enum -{ - MOS_LOG_FATAL = 6, - MOS_LOG_EMERG = 5, - MOS_LOG_WARN = 4, - MOS_LOG_EMPH = 3, - MOS_LOG_INFO = 2, - MOS_LOG_INFO2 = 1, - MOS_LOG_UNSET = 0, -} loglevel_t; - #ifndef pr_fmt #define pr_fmt(fmt) fmt // default format string #endif +#define emit_syslog(level, feat, fmt, ...) do_syslog(level, current_thread, __FILE_NAME__, __func__, __LINE__, &mos_debug_info.feat, fmt, ##__VA_ARGS__) +#define emit_syslog_nofeat(level, fmt, ...) do_syslog(level, current_thread, __FILE_NAME__, __func__, __LINE__, NULL, fmt, ##__VA_ARGS__) + #define lprintk_debug_wrapper(feat, level, fmt, ...) \ do \ { \ if (mos_debug_enabled(feat)) \ - lprintk_wrapper(level, "%-10s | " fmt, #feat, ##__VA_ARGS__); \ + emit_syslog(level, feat, fmt, ##__VA_ARGS__); \ } while (0) // clang-format off @@ -39,13 +31,13 @@ typedef enum #define pr_dfatal(feat, fmt, ...) lprintk_debug_wrapper(feat, MOS_LOG_FATAL, pr_fmt(fmt), ##__VA_ARGS__) #define pr_dcont(feat, fmt, ...) do { if (mos_debug_enabled(feat)) pr_cont(fmt, ##__VA_ARGS__); } while (0) -#define pr_info(fmt, ...) lprintk_wrapper(MOS_LOG_INFO, pr_fmt(fmt), ##__VA_ARGS__) -#define pr_info2(fmt, ...) lprintk_wrapper(MOS_LOG_INFO2, pr_fmt(fmt), ##__VA_ARGS__) -#define pr_emph(fmt, ...) lprintk_wrapper(MOS_LOG_EMPH, pr_fmt(fmt), ##__VA_ARGS__) -#define pr_warn(fmt, ...) lprintk_wrapper(MOS_LOG_WARN, pr_fmt(fmt), ##__VA_ARGS__) -#define pr_emerg(fmt, ...) lprintk_wrapper(MOS_LOG_EMERG, pr_fmt(fmt), ##__VA_ARGS__) -#define pr_fatal(fmt, ...) lprintk_wrapper(MOS_LOG_FATAL, pr_fmt(fmt), ##__VA_ARGS__) -#define pr_cont(fmt, ...) lprintk(MOS_LOG_UNSET, "" fmt, ##__VA_ARGS__) +#define pr_info(fmt, ...) emit_syslog_nofeat(MOS_LOG_INFO, pr_fmt(fmt), ##__VA_ARGS__) +#define pr_info2(fmt, ...) emit_syslog_nofeat(MOS_LOG_INFO2, pr_fmt(fmt), ##__VA_ARGS__) +#define pr_emph(fmt, ...) emit_syslog_nofeat(MOS_LOG_EMPH, pr_fmt(fmt), ##__VA_ARGS__) +#define pr_warn(fmt, ...) emit_syslog_nofeat(MOS_LOG_WARN, pr_fmt(fmt), ##__VA_ARGS__) +#define pr_emerg(fmt, ...) emit_syslog_nofeat(MOS_LOG_EMERG, pr_fmt(fmt), ##__VA_ARGS__) +#define pr_fatal(fmt, ...) emit_syslog_nofeat(MOS_LOG_FATAL, pr_fmt(fmt), ##__VA_ARGS__) +#define pr_cont(fmt, ...) emit_syslog_nofeat(MOS_LOG_UNSET, "" fmt, ##__VA_ARGS__) // clang-format off __BEGIN_DECLS diff --git a/kernel/include/private/mos/syslog/printk_prefix.h b/kernel/include/private/mos/syslog/printk_prefix.h deleted file mode 100644 index bd68e534..00000000 --- a/kernel/include/private/mos/syslog/printk_prefix.h +++ /dev/null @@ -1,73 +0,0 @@ -// SPDX-License-Identifier: GPL-3.0-or-later - -#pragma once - -#include "mos/platform/platform.h" - -#include - -#if MOS_CONFIG(MOS_PRINTK_WITH_TIMESTAMP) -#define _lprintk_timestamp_fmt "%-16llu | " -#define _lprintk_timestamp_arg platform_get_timestamp() -#else -#define _lprintk_timestamp_fmt -#define _lprintk_timestamp_arg -#endif - -#if MOS_CONFIG(MOS_PRINTK_WITH_DATETIME) -#define _lprintk_datetime_fmt "%s | " -#define _lprintk_datetime_arg (const char *) platform_get_datetime_str() -#else -#define _lprintk_datetime_fmt -#define _lprintk_datetime_arg -#endif - -#if MOS_CONFIG(MOS_PRINTK_WITH_CPU_ID) -#define _lprintk_cpuid_fmt "cpu %2d | " -#define _lprintk_cpuid_arg platform_current_cpu_id() -#else -#define _lprintk_cpuid_fmt -#define _lprintk_cpuid_arg -#endif - -#if MOS_CONFIG(MOS_PRINTK_WITH_FILENAME) -#define _lprintk_filename_fmt "%-20s | " -#define _lprintk_filename_arg MOS_FILE_LOCATION -#else -#define _lprintk_filename_fmt -#define _lprintk_filename_arg -#endif - -#if MOS_CONFIG(MOS_PRINTK_WITH_THREAD_ID) -#define _lprintk_threadid_fmt "%pt\t| " -#define _lprintk_threadid_arg ((void *) current_thread) -#else -#define _lprintk_threadid_fmt -#define _lprintk_threadid_arg -#endif - -// don't use MOS_CONFIG(MOS_PRINTK_HAS_SOME_PREFIX) here as it may not be defined -#if MOS_PRINTK_HAS_SOME_PREFIX -#define __add_comma(...) __VA_OPT__(, (__VA_ARGS__)) -// clang-format off -#define _lprintk_prefix_fmt \ - _lprintk_timestamp_fmt \ - _lprintk_datetime_fmt \ - _lprintk_cpuid_fmt \ - _lprintk_filename_fmt \ - _lprintk_threadid_fmt - -#define _lprintk_prefix_arg \ - __add_comma(_lprintk_timestamp_arg) \ - __add_comma(_lprintk_datetime_arg) \ - __add_comma(_lprintk_cpuid_arg) \ - __add_comma(_lprintk_filename_arg) \ - __add_comma(_lprintk_threadid_arg) -// clang-format on -#else -#define _lprintk_prefix_fmt -#define _lprintk_prefix_arg // empty so that the comma after fmt is not included -#endif - -// ! comma after fmt is included in '_lprintk_prefix_arg', careful when changing this macro -#define lprintk_wrapper(level, fmt, ...) lprintk(level, "\r\n" _lprintk_prefix_fmt fmt _lprintk_prefix_arg, ##__VA_ARGS__) diff --git a/kernel/include/private/mos/syslog/syslog.h b/kernel/include/private/mos/syslog/syslog.h new file mode 100644 index 00000000..d0f9b1ea --- /dev/null +++ b/kernel/include/private/mos/syslog/syslog.h @@ -0,0 +1,19 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +#pragma once + +#include "mos/platform/platform.h" +#include "mos/syslog/debug.h" + +typedef enum +{ + MOS_LOG_FATAL = 6, + MOS_LOG_EMERG = 5, + MOS_LOG_WARN = 4, + MOS_LOG_EMPH = 3, + MOS_LOG_INFO = 2, + MOS_LOG_INFO2 = 1, + MOS_LOG_UNSET = 0, +} loglevel_t; + +long do_syslog(loglevel_t level, thread_t *thread, const char *file, const char *func, int line, debug_info_entry *feat, const char *fmt, ...); diff --git a/kernel/misc/kutils.c b/kernel/misc/kutils.c index 75c48f80..30e1a976 100644 --- a/kernel/misc/kutils.c +++ b/kernel/misc/kutils.c @@ -38,5 +38,5 @@ void hexdump(const char *data, const size_t len) } } - pr_info(); + pr_info(""); } diff --git a/kernel/syslog/debug.c b/kernel/syslog/debug.c index 44b40035..eec62262 100644 --- a/kernel/syslog/debug.c +++ b/kernel/syslog/debug.c @@ -19,8 +19,8 @@ MOS_ALL_DEBUG_MODULES(_check_debug_macro_defined_) #if MOS_CONFIG(MOS_DYNAMIC_DEBUG) // populate default debug settings -typeof(mos_debug_info) mos_debug_info = { -#define X(name) .name = MOS_DEBUG_FEATURE(name), +struct _mos_debug_info mos_debug_info = { +#define X(_name) ._name = { .id = __COUNTER__ + 1, .name = #_name, .enabled = MOS_DEBUG_FEATURE(_name) }, MOS_ALL_DEBUG_MODULES(X) #undef X }; @@ -35,7 +35,7 @@ void debug_print_action(const char *name, bool newstate) #define debug_show_function(name) \ bool debug_show_##name(sysfs_file_t *file) \ { \ - sysfs_printf(file, "%d\n", mos_debug_info.name); \ + sysfs_printf(file, "%d\n", mos_debug_info.name.enabled); \ return true; \ } @@ -47,14 +47,13 @@ void debug_print_action(const char *name, bool newstate) if (count < 1) \ return -EINVAL; \ const bool on = buf[0] == '1'; \ - mos_debug_info.name = on; \ + mos_debug_info.name.enabled = on; \ debug_print_action(#name, on); \ return count; \ } -#define X(name) debug_show_function(name) debug_store_function(name) -MOS_ALL_DEBUG_MODULES(X) -#undef X +MOS_ALL_DEBUG_MODULES(debug_show_function) +MOS_ALL_DEBUG_MODULES(debug_store_function) static sysfs_item_t sys_debug_items[] = { #define X(name) SYSFS_RW_ITEM(#name, debug_show_##name, debug_store_##name), @@ -67,7 +66,7 @@ SYSFS_AUTOREGISTER(debug, sys_debug_items); #define SETUP_DEBUG_MODULE(name) \ static bool setup_debug_##name(const char *value) \ { \ - mos_debug_info.name = cmdline_string_truthiness(value, true); \ + mos_debug_info.name.enabled = cmdline_string_truthiness(value, true); \ return true; \ } \ MOS_SETUP("debug." #name, setup_debug_##name); diff --git a/kernel/syslog/syslog.c b/kernel/syslog/syslog.c new file mode 100644 index 00000000..3994fa55 --- /dev/null +++ b/kernel/syslog/syslog.c @@ -0,0 +1,71 @@ +// SPDX-License-Identifier: GPL-3.0-or-later + +#include "mos/syslog/syslog.h" + +#include "mos/platform/platform.h" +#include "mos/tasks/task_types.h" +#include "proto/syslog.pb.h" + +#include +#include +#include +#include + +static spinlock_t global_syslog_lock = SPINLOCK_INIT; + +long do_syslog(loglevel_t level, thread_t *thread, const char *file, const char *func, int line, debug_info_entry *feat, const char *fmt, ...) +{ + pb_syslog_message msg = { + .timestamp = platform_get_timestamp(), + .cpu_id = platform_current_cpu_id(), + }; + + msg.info.level = (syslog_level) level; + msg.info.featid = feat ? feat->id : 0; + msg.info.source_location.line = line; + strncpy(msg.info.source_location.filename, file, sizeof(msg.info.source_location.filename)); + strncpy(msg.info.source_location.function, func, sizeof(msg.info.source_location.function)); + + if (thread) + { + msg.thread.tid = thread->tid; + msg.process.pid = thread->owner->pid; + strncpy(msg.thread.name, thread->name, sizeof(msg.thread.name)); + strncpy(msg.process.name, thread->owner->name, sizeof(msg.process.name)); + } + + va_list args; + va_start(args, fmt); + vsnprintf(msg.message, sizeof(msg.message), fmt, args); + va_end(args); + + spinlock_acquire(&global_syslog_lock); + + lprintk(level, "\r\n"); + +#if MOS_CONFIG(MOS_PRINTK_WITH_TIMESTAMP) + lprintk(MOS_LOG_UNSET, "%-16llu | ", platform_get_timestamp()); +#endif + +#if MOS_CONFIG(MOS_PRINTK_WITH_DATETIME) + lprintk(MOS_LOG_UNSET, "%s | ", (const char *) platform_get_datetime_str()); +#endif + +#if MOS_CONFIG(MOS_PRINTK_WITH_CPU_ID) + lprintk(MOS_LOG_UNSET, "cpu %2d | ", msg.cpu_id); +#endif + +#if MOS_CONFIG(MOS_PRINTK_WITH_FILENAME) + lprintk(MOS_LOG_UNSET, "%-15s | ", msg.info.source_location.filename); +#endif + +#if MOS_CONFIG(MOS_PRINTK_WITH_THREAD_ID) + lprintk(MOS_LOG_UNSET, "%pt\t| ", ((void *) thread)); +#endif + + lprintk(MOS_LOG_UNSET, "%s", msg.message); + + spinlock_release(&global_syslog_lock); + + return 0; +} diff --git a/proto/syslog.proto b/proto/syslog.proto new file mode 100644 index 00000000..f4bd1b75 --- /dev/null +++ b/proto/syslog.proto @@ -0,0 +1,55 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +syntax = "proto3"; +import "nanopb.proto"; + +option (nanopb_fileopt).fallback_type = FT_STATIC; +option (nanopb_fileopt).proto3_singular_msgs = true; + +enum syslog_level +{ + UNSET = 0; + INFO2 = 1; + INFO = 2; + EMPH = 3; + WARN = 4; + EMERG = 5; + FATAL = 6; +} + +message pb_thread +{ + uint32 tid = 1; + string name = 2 [ (nanopb).max_size = 32 ]; +} + +message pb_process +{ + uint32 pid = 1; + string name = 2 [ (nanopb).max_size = 32 ]; +} + +message pb_source_location +{ + string filename = 1 [ (nanopb).max_size = 32 ]; + uint32 line = 2; + string function = 3 [ (nanopb).max_size = 32 ]; +} + +message pb_syslog_source_info +{ + syslog_level level = 1; + uint32 featid = 2; + pb_source_location source_location = 3; +} + +message pb_syslog_message +{ + uint64 timestamp = 1; + pb_syslog_source_info info = 2; + string message = 3 [ (nanopb).max_size = 512 ]; + + pb_thread thread = 4; + pb_process process = 5; + + uint32 cpu_id = 6; +}