From 9ee806d1a80d7aa9d85fc91dca48e7b37efcb053 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 29 Sep 2020 13:06:12 +0200 Subject: [PATCH 1/2] log: optionally display thread ID in log output to tty This is very useful when playing around with threaded tests, but should be useful in other cases too. --- man/systemd.xml | 46 +++++++++++++++++++++++----------------------- src/basic/log.c | 40 ++++++++++++++++++++++++++++++++++++++-- src/basic/log.h | 3 +++ 3 files changed, 64 insertions(+), 25 deletions(-) diff --git a/man/systemd.xml b/man/systemd.xml index a9040545c2..5e7dc5be73 100644 --- a/man/systemd.xml +++ b/man/systemd.xml @@ -614,37 +614,38 @@ $SYSTEMD_LOG_COLOR - Controls whether systemd highlights important - log messages. This can be overridden with - . + Controls whether systemd highlights important log messages. This can be overridden + with . $SYSTEMD_LOG_LEVEL - systemd reads the log level from this - environment variable. This can be overridden with - . + systemd reads the log level from this environment variable. This can be overridden + with . $SYSTEMD_LOG_LOCATION - Controls whether systemd prints the code - location along with log messages. This can be overridden with - . + Controls whether systemd prints the code location along with log messages. This can + be overridden with . $SYSTEMD_LOG_TARGET - systemd reads the log target from this - environment variable. This can be overridden with - . + systemd reads the log target from this environment variable. This can be overridden + with . $SYSTEMD_LOG_TIME - Controls whether systemd prefixes log - messages with the current time. This can be overridden with - . + Controls whether systemd prefixes log messages with the current time. This can be + overridden with . + + + + $SYSTEMD_LOG_TID + Controls whether systemd prefixes log messages with the current thread ID + (TID). @@ -845,16 +846,15 @@ systemd.log_location systemd.log_target= systemd.log_time + systemd.log_tid Controls log output, with the same effect as the - $SYSTEMD_LOG_COLOR, - $SYSTEMD_LOG_LEVEL, - $SYSTEMD_LOG_LOCATION, - $SYSTEMD_LOG_TARGET, - $SYSTEMD_LOG_TIME, environment variables described above. - systemd.log_color, systemd.log_location, and - systemd.log_time can be specified without an argument, with the - same effect as a positive boolean. + $SYSTEMD_LOG_COLOR, $SYSTEMD_LOG_LEVEL, + $SYSTEMD_LOG_LOCATION, $SYSTEMD_LOG_TARGET, + $SYSTEMD_LOG_TIME, $SYSTEMD_LOG_TID environment variables + described above. systemd.log_color, systemd.log_location, + systemd.log_time and systemd.log_tid= can be specified without + an argument, with the same effect as a positive boolean. diff --git a/src/basic/log.c b/src/basic/log.c index 899a8423f2..89d26a4a43 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -22,6 +22,7 @@ #include "io-util.h" #include "log.h" #include "macro.h" +#include "missing_syscall.h" #include "parse-util.h" #include "proc-cmdline.h" #include "process-util.h" @@ -53,6 +54,7 @@ static bool syslog_is_stream = false; static bool show_color = false; static bool show_location = false; static bool show_time = false; +static bool show_tid = false; static bool upgrade_syslog_to_journal = false; static bool always_reopen_console = false; @@ -360,8 +362,9 @@ static int write_to_console( char location[256], header_time[FORMAT_TIMESTAMP_MAX], - prefix[1 + DECIMAL_STR_MAX(int) + 2]; - struct iovec iovec[8] = {}; + prefix[1 + DECIMAL_STR_MAX(int) + 2], + tid_string[3 + DECIMAL_STR_MAX(pid_t) + 1]; + struct iovec iovec[9]; const char *on = NULL, *off = NULL; size_t n = 0; @@ -380,6 +383,11 @@ static int write_to_console( } } + if (show_tid) { + xsprintf(tid_string, "(" PID_FMT ") ", gettid()); + iovec[n++] = IOVEC_MAKE_STRING(tid_string); + } + if (show_color) get_log_colors(LOG_PRI(level), &on, &off, NULL); @@ -1133,6 +1141,11 @@ static int parse_proc_cmdline_item(const char *key, const char *value, void *dat if (log_show_location_from_string(value ?: "1") < 0) log_warning("Failed to parse log location setting '%s'. Ignoring.", value); + } else if (proc_cmdline_key_streq(key, "systemd.log_tid")) { + + if (log_show_tid_from_string(value ?: "1") < 0) + log_warning("Failed to parse log tid setting '%s'. Ignoring.", value); + } else if (proc_cmdline_key_streq(key, "systemd.log_time")) { if (log_show_time_from_string(value ?: "1") < 0) @@ -1177,6 +1190,10 @@ void log_parse_environment_cli_realm(LogRealm realm) { e = getenv("SYSTEMD_LOG_TIME"); if (e && log_show_time_from_string(e) < 0) log_warning("Failed to parse log time '%s'. Ignoring.", e); + + e = getenv("SYSTEMD_LOG_TID"); + if (e && log_show_tid_from_string(e) < 0) + log_warning("Failed to parse log tid '%s'. Ignoring.", e); } LogTarget log_get_target(void) { @@ -1211,6 +1228,14 @@ bool log_get_show_time(void) { return show_time; } +void log_show_tid(bool b) { + show_tid = b; +} + +bool log_get_show_tid(void) { + return show_tid; +} + int log_show_color_from_string(const char *e) { int t; @@ -1244,6 +1269,17 @@ int log_show_time_from_string(const char *e) { return 0; } +int log_show_tid_from_string(const char *e) { + int t; + + t = parse_boolean(e); + if (t < 0) + return t; + + log_show_tid(t); + return 0; +} + bool log_on_console(void) { if (IN_SET(log_target, LOG_TARGET_CONSOLE, LOG_TARGET_CONSOLE_PREFIXED)) diff --git a/src/basic/log.h b/src/basic/log.h index 137d21005d..c65419b699 100644 --- a/src/basic/log.h +++ b/src/basic/log.h @@ -61,10 +61,13 @@ void log_show_location(bool b); bool log_get_show_location(void) _pure_; void log_show_time(bool b); bool log_get_show_time(void) _pure_; +void log_show_tid(bool b); +bool log_get_show_tid(void) _pure_; int log_show_color_from_string(const char *e); int log_show_location_from_string(const char *e); int log_show_time_from_string(const char *e); +int log_show_tid_from_string(const char *e); LogTarget log_get_target(void) _pure_; int log_get_max_level_realm(LogRealm realm) _pure_; From 38ffc7d18aa05c2be6bd3d26fdcd8efbb9bab255 Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 29 Sep 2020 13:07:07 +0200 Subject: [PATCH 2/2] log: include TID= field in structred log output It always was the intention to expose this as trusted field _TID=, i.e. automatically determine it from journald via some SCM_xyz field or so, but this is never happened, and it's unlikely this will be added anytime soon to the kernel either, hence let's just generate this sender side, even if it means it's untrusted. --- man/systemd.journal-fields.xml | 7 +++++++ src/basic/log.c | 2 ++ 2 files changed, 9 insertions(+) diff --git a/man/systemd.journal-fields.xml b/man/systemd.journal-fields.xml index 197a468f25..31e3d8b210 100644 --- a/man/systemd.journal-fields.xml +++ b/man/systemd.journal-fields.xml @@ -149,6 +149,13 @@ file:/, man: or info: URL. + + + TID= + + The numeric thread ID (TID) the log message originates from. + + diff --git a/src/basic/log.c b/src/basic/log.c index 89d26a4a43..7c68258ea8 100644 --- a/src/basic/log.c +++ b/src/basic/log.c @@ -547,6 +547,7 @@ static int log_do_header( r = snprintf(header, size, "PRIORITY=%i\n" "SYSLOG_FACILITY=%i\n" + "TID=" PID_FMT "\n" "%s%.256s%s" /* CODE_FILE */ "%s%.*i%s" /* CODE_LINE */ "%s%.256s%s" /* CODE_FUNC */ @@ -556,6 +557,7 @@ static int log_do_header( "SYSLOG_IDENTIFIER=%.256s\n", LOG_PRI(level), LOG_FAC(level), + gettid(), isempty(file) ? "" : "CODE_FILE=", isempty(file) ? "" : file, isempty(file) ? "" : "\n",