logging: Allow prefixing thread ID to each log line

Related: OS#5032
Change-Id: I38fc93ab0182b4edbd639c7ed0f31ce51964ee18

include/osmocom/core/logging.h

@@ -281,6 +281,8 @@ struct log_target {
 	unsigned int use_color:1;
 	/*! should log messages be prefixed with a timestamp? */
 	unsigned int print_timestamp:1;
+	/*! should log messages be prefixed with the logger Thread ID? */
+	unsigned int print_tid:1;
 	/*! DEPRECATED: use print_filename2 instead. */
 	unsigned int print_filename:1;
 	/*! should log messages be prefixed with a category name? */
@@ -374,6 +376,7 @@ void log_set_all_filter(struct log_target *target, int);
 void log_set_use_color(struct log_target *target, int);
 void log_set_print_extended_timestamp(struct log_target *target, int);
 void log_set_print_timestamp(struct log_target *target, int);
+void log_set_print_tid(struct log_target *target, int);
 void log_set_print_filename(struct log_target *target, int);
 void log_set_print_filename2(struct log_target *target, enum log_filename_type lft);
 void log_set_print_filename_pos(struct log_target *target, enum log_filename_pos pos);

src/logging.c

@@ -64,6 +64,7 @@
 #include <osmocom/core/utils.h>
 #include <osmocom/core/logging.h>
 #include <osmocom/core/timer.h>
+#include <osmocom/core/thread.h>
 
 #include <osmocom/vty/logging.h>	/* for LOGGING_STR. */
 
@@ -83,6 +84,8 @@ static struct log_context log_context;
 void *tall_log_ctx = NULL;
 LLIST_HEAD(osmo_log_target_list);
 
+static __thread long int logging_tid;
+
 #if (!EMBEDDED)
 /*! This mutex must be held while using osmo_log_target_list or any of its
   log_targets in a multithread program. Prevents race conditions between threads
@@ -473,6 +476,14 @@ static void _output(struct log_target *target, unsigned int subsys,
 			buf[offset + ret - 1] = ' ';
 			OSMO_SNPRINTF_RET(ret, rem, offset, len);
 		}
+		if (target->print_tid) {
+			if (logging_tid == 0)
+				logging_tid = (long int)osmo_gettid();
+			ret = snprintf(buf + offset, rem, "%ld ", logging_tid);
+			if (ret < 0)
+				goto err;
+			OSMO_SNPRINTF_RET(ret, rem, offset, len);
+		}
 		if (target->print_category) {
 			ret = snprintf(buf + offset, rem, "%s%s%s%s ",
 				       target->use_color ? level_color(level) : "",
@@ -778,6 +789,15 @@ void log_set_print_extended_timestamp(struct log_target *target, int print_times
 	target->print_ext_timestamp = print_timestamp;
 }
 
+/*! Enable or disable printing of timestamps while logging
+ *  \param[in] target Log target to be affected
+ *  \param[in] print_tid Enable (1) or disable (0) Thread ID logging
+ */
+void log_set_print_tid(struct log_target *target, int print_tid)
+{
+	target->print_tid = print_tid;
+}
+
 /*! Use log_set_print_filename2() instead.
  * Call log_set_print_filename2() with LOG_FILENAME_PATH or LOG_FILENAME_NONE, *as well as* call
  * log_set_print_category_hex() with the argument passed to this function. This is to mirror legacy
@@ -917,6 +937,7 @@ struct log_target *log_target_create(void)
 	/* global settings */
 	target->use_color = 1;
 	target->print_timestamp = 0;
+	target->print_tid = 0;
 	target->print_filename2 = LOG_FILENAME_PATH;
 	target->print_category_hex = true;
 

src/vty/logging_vty.c

@@ -225,6 +225,22 @@ DEFUN(logging_prnt_ext_timestamp,
 	RET_WITH_UNLOCK(CMD_SUCCESS);
 }
 
+DEFUN(logging_prnt_tid,
+      logging_prnt_tid_cmd,
+      "logging print thread-id (0|1)",
+	LOGGING_STR "Log output settings\n"
+	"Configure log message logging Thread ID\n"
+	"Don't prefix each log message\n"
+	"Prefix each log message with current Thread ID\n")
+{
+	struct log_target *tgt;
+
+	ACQUIRE_VTY_LOG_TGT_WITH_LOCK(vty, tgt);
+
+	log_set_print_tid(tgt, atoi(argv[0]));
+	RET_WITH_UNLOCK(CMD_SUCCESS);
+}
+
 DEFUN(logging_prnt_cat,
       logging_prnt_cat_cmd,
       "logging print category (0|1)",
@@ -1003,6 +1019,8 @@ static int config_write_log_single(struct vty *vty, struct log_target *tgt)
 		tgt->print_category_hex ? 1 : 0, VTY_NEWLINE);
 	vty_out(vty, " logging print category %d%s",
 		tgt->print_category ? 1 : 0, VTY_NEWLINE);
+	vty_out(vty, " logging print thread-id %d%s",
+		tgt->print_tid ? 1 : 0, VTY_NEWLINE);
 	if (tgt->print_ext_timestamp)
 		vty_out(vty, " logging print extended-timestamp 1%s", VTY_NEWLINE);
 	else
@@ -1134,6 +1152,7 @@ void logging_vty_add_cmds()
 	install_lib_element_ve(&logging_use_clr_cmd);
 	install_lib_element_ve(&logging_prnt_timestamp_cmd);
 	install_lib_element_ve(&logging_prnt_ext_timestamp_cmd);
+	install_lib_element_ve(&logging_prnt_tid_cmd);
 	install_lib_element_ve(&logging_prnt_cat_cmd);
 	install_lib_element_ve(&logging_prnt_cat_hex_cmd);
 	install_lib_element_ve(&logging_prnt_level_cmd);
@@ -1168,6 +1187,7 @@ void logging_vty_add_cmds()
 	install_lib_element(CFG_LOG_NODE, &logging_use_clr_cmd);
 	install_lib_element(CFG_LOG_NODE, &logging_prnt_timestamp_cmd);
 	install_lib_element(CFG_LOG_NODE, &logging_prnt_ext_timestamp_cmd);
+	install_lib_element(CFG_LOG_NODE, &logging_prnt_tid_cmd);
 	install_lib_element(CFG_LOG_NODE, &logging_prnt_cat_cmd);
 	install_lib_element(CFG_LOG_NODE, &logging_prnt_cat_hex_cmd);
 	install_lib_element(CFG_LOG_NODE, &logging_prnt_level_cmd);

tests/logging/logging_vty_test.vty

@@ -48,6 +48,7 @@ logging_vty_test# list
   logging color (0|1)
   logging timestamp (0|1)
   logging print extended-timestamp (0|1)
+  logging print thread-id (0|1)
   logging print category (0|1)
   logging print category-hex (0|1)
   logging print level (0|1)