logging: use enum to set timestamp format

In preparation of adding a new timestamp format, refactor to use an enum to
pick the timestamp style.

Introduce log_set_print_timestamp2() to be able to pass an enum value directly
(for future additions). Deprecate previous API of
log_set_print_timestamp() and log_set_print_extended_timestamp().

Remove the old members of struct log_target members:
- print_timestamp and
- print_ext_timestamp (bool flags),
instead add member
- timestamp_format (enum).
This is an API and ABI incompatibility. (An original patch version
preserved the unused struct members, but code review suggested it makes
more sense to drop them.)

The old API functions log_set_print_timestamp() and
log_set_print_extended_timestamp() still work, but setting
log_set_print_*timestamp(0) changes its behavior: now passing zero to
either of these functions sets LOG_TIMESTAMP_NONE, so it now always
switches off all timestamps, instead of previously maybe going back to
another timestamp depending on the other flag being set or not.

Change-Id: I70ecee543c266df54191d3e86401466cd1a5c0a6

13 files changed, 110 insertions, 55 deletions

diff --git a/TODO-RELEASE b/TODO-RELEASE
index eea31407..851e16e8 100644
--- a/TODO-RELEASE
+++ b/TODO-RELEASE
@@ -23,3 +23,12 @@ gsm		ABI change		add UI queue to struct lapdm_datalink
 gsm		ADD			gsup.h: struct osmo_gsup_pdp_info fields pdp_type_nr, pdp_type_org, deprecate pdp_type.
 gsm		ABI change			gsup.h: Add field pdp_address in struct osmo_gsup_pdp_info shifts the struct, and in turn fields in struct osmo_gsup_message.
 gsm		ABI change		gsup.h: Add field pco in struct osmo_gsup_message. Length of the struct osmo_gsup_message increase.
+libosmocore	replace API	flags log_target.print_timestamp, log_target.print_ext_timestamp replaced by log_target.timestamp_format.
+
+libosmocore	deprecate API	log_set_print_timestamp() replaced by log_set_print_timestamp2().
+libosmocore	deprecate API	log_set_print_extended_timestamp() replaced by log_set_print_timestamp2().
+						Since the 'print timestamp' settings are now stored as a single enum,
+						the behavior of calling log_set_print_timestamp(0) and
+						log_set_print_extended_timestamp(0) changes: when calling with zero
+						argument, logging now always snaps back to LOG_TIMSTAMP_NONE, instead of
+						the current behavior: maybe go to LOG_TIMSTAMP_CTIME, depending on what flags were otherwise set.
diff --git a/include/osmocom/core/logging.h b/include/osmocom/core/logging.h
index e58c25c3..26162bff 100644
--- a/include/osmocom/core/logging.h
+++ b/include/osmocom/core/logging.h
@@ -296,6 +296,13 @@ enum log_filename_pos {
 	LOG_FILENAME_POS_LINE_END,
 };
 
+/*! Format of the timestamp printed */
+enum log_timestamp_format {
+	LOG_TIMESTAMP_NONE,
+	LOG_TIMESTAMP_DATE_PACKED,
+	LOG_TIMESTAMP_CTIME,
+};
+
 /*! structure representing a logging target */
 struct log_target {
 	struct llist_head entry;		/*!< linked list */
@@ -312,16 +319,12 @@ struct log_target {
 	uint8_t loglevel;
 	/*! should color be used when printing log messages? */
 	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? */
 	unsigned int print_category:1;
-	/*! should log messages be prefixed with an extended timestamp? */
-	unsigned int print_ext_timestamp:1;
 
 	/*! the type of this log taget */
 	enum log_target_type type;
@@ -392,6 +395,9 @@ struct log_target {
 	enum log_filename_type print_filename2;
 	/* Where on a log line to put the source file info. */
 	enum log_filename_pos print_filename_pos;
+
+	/* Timestamp format */
+	enum log_timestamp_format timestamp_format;
 };
 
 /* use the above macros */
@@ -412,8 +418,11 @@ void log_set_all_filter(struct log_target *target, int);
 int log_cache_enable(void);
 void log_cache_update(int mapped_subsys, uint8_t enabled, uint8_t level);
 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_extended_timestamp(struct log_target *target, int flag)
+	OSMO_DEPRECATED("Use log_set_print_timestamp2(LOG_TIMESTAMP_DATE_PACKED) instead");
+void log_set_print_timestamp(struct log_target *target, int flag)
+	OSMO_DEPRECATED("Use log_set_print_timestamp2(LOG_TIMESTAMP_CTIME) instead");
+void log_set_print_timestamp2(struct log_target *target, enum log_timestamp_format format);
 void log_set_print_tid(struct log_target *target, int);
 void log_set_print_filename(struct log_target *target, int) OSMO_DEPRECATED("Use log_set_print_filename2() instead");
 void log_set_print_filename2(struct log_target *target, enum log_filename_type lft);
diff --git a/src/core/libosmocore.map b/src/core/libosmocore.map
index 54eae925..3a344474 100644
--- a/src/core/libosmocore.map
+++ b/src/core/libosmocore.map
@@ -82,6 +82,7 @@ log_set_log_level;
 log_set_print_category;
 log_set_print_category_hex;
 log_set_print_extended_timestamp;
+log_set_print_timestamp2;
 log_set_print_filename;
 log_set_print_filename2;
 log_set_print_filename_pos;
diff --git a/src/core/logging.c b/src/core/logging.c
index ba229147..04bd34e5 100644
--- a/src/core/logging.c
+++ b/src/core/logging.c
@@ -576,6 +576,16 @@ static const char *const_basename(const char *path)
 	return bn + 1;
 }
 
+static int get_timestamp(struct timeval *tv, struct tm *tm, const struct log_target *target)
+{
+	osmo_gettimeofday(tv, NULL);
+#ifdef HAVE_LOCALTIME_R
+	return (localtime_r(&tv->tv_sec, tm) != NULL) ? 0 : -1;
+#else
+	return -1;
+#endif
+}
+
 /*! main output formatting function for log lines.
  *  \param[out] buf caller-allocated output buffer for the generated string
  *  \param[in] buf_len number of bytes available in buf
@@ -606,33 +616,36 @@ static int _output_buf(char *buf, int buf_len, struct log_target *target, unsign
 			OSMO_STRBUF_PRINTF(sb, "%s", c_subsys);
 	}
 	if (!cont) {
-		if (target->print_ext_timestamp) {
-#ifdef HAVE_LOCALTIME_R
-			struct tm tm;
-			struct timeval tv;
-			osmo_gettimeofday(&tv, NULL);
-			localtime_r(&tv.tv_sec, &tm);
-			OSMO_STRBUF_PRINTF(sb, "%04d%02d%02d%02d%02d%02d%03d ",
-					   tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
-					   tm.tm_hour, tm.tm_min, tm.tm_sec,
-					   (int)(tv.tv_usec / 1000));
-#endif
-		} else if (target->print_timestamp) {
-			time_t tm;
-			if ((tm = time(NULL)) == (time_t) -1)
-				goto err;
-			/* Get human-readable representation of time.
-			   man ctime: we need at least 26 bytes in buf */
-			if (OSMO_STRBUF_REMAIN(sb) < 26 || !ctime_r(&tm, sb.pos))
-				goto err;
-			ret = strnlen(sb.pos, 26);
-			if (ret <= 0)
-				goto err;
-			OSMO_STRBUF_ADDED_TAIL(sb, ret);
-			/* Get rid of useless final '\n' added by ctime_r. We want a space instead. */
-			OSMO_STRBUF_DROP_TAIL(sb, 1);
-			OSMO_STRBUF_PRINTF(sb, " ");
+		struct timeval tv;
+		struct tm tm;
+
+		switch (target->timestamp_format) {
+		case LOG_TIMESTAMP_NONE:
+			break;
+		case LOG_TIMESTAMP_CTIME:
+			if (get_timestamp(&tv, &tm, target) == 0) {
+				/* Get human-readable representation of time.
+				   man ctime: we need at least 26 bytes in buf */
+				if (OSMO_STRBUF_REMAIN(sb) < 26 || !asctime_r(&tm, sb.pos))
+					goto err;
+				ret = strnlen(sb.pos, 26);
+				if (ret <= 0)
+					goto err;
+				OSMO_STRBUF_ADDED_TAIL(sb, ret);
+				/* Get rid of useless final '\n' added by asctime_r. We want a space instead. */
+				OSMO_STRBUF_DROP_TAIL(sb, 1);
+				OSMO_STRBUF_PRINTF(sb, " ");
+			}
+			break;
+		case LOG_TIMESTAMP_DATE_PACKED:
+			if (get_timestamp(&tv, &tm, target) == 0)
+				OSMO_STRBUF_PRINTF(sb, "%04d%02d%02d%02d%02d%02d%03d ",
+						   tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+						   tm.tm_hour, tm.tm_min, tm.tm_sec,
+						   (int)(tv.tv_usec / 1000));
+			break;
 		}
+
 		if (target->print_tid) {
 			if (logging_tid == 0)
 				logging_tid = (long int)osmo_gettid();
@@ -933,16 +946,18 @@ void log_set_use_color(struct log_target *target, int use_color)
 	target->use_color = use_color;
 }
 
-/*! Enable or disable printing of timestamps while logging
+/*! Use log_set_print_timestamp2(LOG_TIMESTAMP_CTIME) instead.
+ * Enable or disable printing of timestamps while logging.
  *  \param[in] target Log target to be affected
  *  \param[in] print_timestamp Enable (1) or disable (0) timestamps
  */
 void log_set_print_timestamp(struct log_target *target, int print_timestamp)
 {
-	target->print_timestamp = print_timestamp;
+	log_set_print_timestamp2(target, print_timestamp ? LOG_TIMESTAMP_CTIME : LOG_TIMESTAMP_NONE);
 }
 
-/*! Enable or disable printing of extended timestamps while logging
+/*! Use log_set_print_timestamp2(LOG_TIMESTAMP_DATE_PACKED) instead.
+ * Enable or disable printing of extended timestamps while logging.
  *  \param[in] target Log target to be affected
  *  \param[in] print_timestamp Enable (1) or disable (0) timestamps
  *
@@ -952,7 +967,20 @@ void log_set_print_timestamp(struct log_target *target, int print_timestamp)
  */
 void log_set_print_extended_timestamp(struct log_target *target, int print_timestamp)
 {
-	target->print_ext_timestamp = print_timestamp;
+	log_set_print_timestamp2(target, print_timestamp ? LOG_TIMESTAMP_DATE_PACKED : LOG_TIMESTAMP_NONE);
+}
+
+/*! Enable or disable printing of timestamps while logging.
+ *  \param[in] target Log target to be affected
+ *  \param[in] fmt LOG_TIMESTAMP_* value to indicate the format.
+ *
+ * LOG_TIMESTAMP_NONE switches off the timestamp output.
+ * LOG_TIMESTAMP_DATE_PACKED prints YYYYMMDDhhmmssnnn.
+ * LOG_TIMESTAMP_CTIME prints a verbose date format as returned by ctime().
+ */
+void log_set_print_timestamp2(struct log_target *target, enum log_timestamp_format fmt)
+{
+	target->timestamp_format = fmt;
 }
 
 /*! Enable or disable printing of timestamps while logging
@@ -1163,7 +1191,7 @@ struct log_target *log_target_create(void)
 
 	/* global settings */
 	target->use_color = 1;
-	target->print_timestamp = 0;
+	target->timestamp_format = LOG_TIMESTAMP_NONE;
 	target->print_tid = 0;
 	target->print_filename2 = LOG_FILENAME_PATH;
 	target->print_category_hex = true;
diff --git a/src/vty/logging_vty.c b/src/vty/logging_vty.c
index 23980f5d..0f2ca8c7 100644
--- a/src/vty/logging_vty.c
+++ b/src/vty/logging_vty.c
@@ -201,7 +201,7 @@ DEFUN(logging_timestamp,
 
 	ACQUIRE_VTY_LOG_TGT_WITH_LOCK(vty, tgt);
 
-	log_set_print_timestamp(tgt, atoi(argv[0]));
+	log_set_print_timestamp2(tgt, atoi(argv[0]) ? LOG_TIMESTAMP_CTIME : LOG_TIMESTAMP_NONE);
 	RET_WITH_UNLOCK(CMD_SUCCESS);
 }
 
@@ -217,7 +217,7 @@ DEFUN(logging_prnt_ext_timestamp,
 
 	ACQUIRE_VTY_LOG_TGT_WITH_LOCK(vty, tgt);
 
-	log_set_print_extended_timestamp(tgt, atoi(argv[0]));
+	log_set_print_timestamp2(tgt, atoi(argv[0]) ? LOG_TIMESTAMP_DATE_PACKED : LOG_TIMESTAMP_NONE);
 	RET_WITH_UNLOCK(CMD_SUCCESS);
 }
 
@@ -519,7 +519,7 @@ static void vty_print_logtarget(struct vty *vty, const struct log_info *info,
 		log_level_str(tgt->loglevel), VTY_NEWLINE);
 	vty_out(vty, " Use color: %s, Print Timestamp: %s%s",
 		tgt->use_color ? "On" : "Off",
-		tgt->print_timestamp ? "On" : "Off", VTY_NEWLINE);
+		tgt->timestamp_format != LOG_TIMESTAMP_NONE ? "On" : "Off", VTY_NEWLINE);
 
 	vty_out(vty, " Log Level specific information:%s", VTY_NEWLINE);
 
@@ -1062,11 +1062,19 @@ static int config_write_log_single(struct vty *vty, struct log_target *tgt)
 		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)
+
+	switch (tgt->timestamp_format) {
+	case LOG_TIMESTAMP_DATE_PACKED:
 		vty_out(vty, " logging print extended-timestamp 1%s", VTY_NEWLINE);
-	else
-		vty_out(vty, " logging timestamp %u%s",
-			tgt->print_timestamp ? 1 : 0, VTY_NEWLINE);
+		break;
+	case LOG_TIMESTAMP_CTIME:
+		vty_out(vty, " logging timestamp 1%s", VTY_NEWLINE);
+		break;
+	default:
+		vty_out(vty, " logging timestamp 0%s", VTY_NEWLINE);
+		break;
+	}
+
 	if (tgt->print_level)
 		vty_out(vty, " logging print level 1%s", VTY_NEWLINE);
 	vty_out(vty, " logging print file %s%s%s",
diff --git a/tests/gsup/gsup_test.c b/tests/gsup/gsup_test.c
index fb3708ac..641b77fd 100644
--- a/tests/gsup/gsup_test.c
+++ b/tests/gsup/gsup_test.c
@@ -750,7 +750,7 @@ int main(int argc, char **argv)
 	void *ctx = talloc_named_const(NULL, 0, "gsup_test");
 	osmo_init_logging2(ctx, &info);
 	log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);
-	log_set_print_timestamp(osmo_stderr_target, 0);
+	log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_NONE);
 	log_set_use_color(osmo_stderr_target, 0);
 	log_set_print_category_hex(osmo_stderr_target, 0);
 	log_set_print_category(osmo_stderr_target, 1);
diff --git a/tests/logging/logging_vty_test.c b/tests/logging/logging_vty_test.c
index c1a28533..5bb5aaae 100644
--- a/tests/logging/logging_vty_test.c
+++ b/tests/logging/logging_vty_test.c
@@ -178,7 +178,7 @@ static void handle_options(int argc, char **argv)
 			cmdline_config.config_file = optarg;
 			break;
 		case 'T':
-			log_set_print_timestamp(osmo_stderr_target, 1);
+			log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_CTIME);
 			break;
 		case 'e':
 			log_set_log_level(osmo_stderr_target, atoi(optarg));
diff --git a/tests/logging/logging_vty_test.vty b/tests/logging/logging_vty_test.vty
index da09be76..a14616c1 100644
--- a/tests/logging/logging_vty_test.vty
+++ b/tests/logging/logging_vty_test.vty
@@ -175,23 +175,23 @@ log stderr
  logging print extended-timestamp 1
 ... !timestamp
 
-logging_vty_test(config-log)# ### 'logging timestamp 0' effect not shown while 'extended-timestamp' == 1
+logging_vty_test(config-log)# ### 'timestamp 0' also removes 'extended-timestamp 1'
 logging_vty_test(config-log)# logging timestamp 0
 logging_vty_test(config-log)# show running-config
 ...
 log stderr
 ... !timestamp
- logging print extended-timestamp 1
+ logging timestamp 0
 ... !timestamp
 
-logging_vty_test(config-log)# ### 'logging timestamp 1' remains set upon 'extended-timestamp 0'
+logging_vty_test(config-log)# ### 'extended-timestamp 0' also removes 'timestamp 1'
 logging_vty_test(config-log)# logging timestamp 1
 logging_vty_test(config-log)# logging print extended-timestamp 0
 logging_vty_test(config-log)# show running-config
 ...
 log stderr
 ... !timestamp
- logging timestamp 1
+ logging timestamp 0
 ... !timestamp
 
 logging_vty_test(config-log)# logging timestamp 0
diff --git a/tests/oap/oap_client_test.c b/tests/oap/oap_client_test.c
index 622912f9..e7924527 100644
--- a/tests/oap/oap_client_test.c
+++ b/tests/oap/oap_client_test.c
@@ -259,7 +259,7 @@ int main(int argc, char **argv)
 
 	OSMO_ASSERT(osmo_stderr_target);
 	log_set_use_color(osmo_stderr_target, 0);
-	log_set_print_timestamp(osmo_stderr_target, 0);
+	log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_NONE);
 	log_set_print_filename2(osmo_stderr_target, LOG_FILENAME_NONE);
 	log_set_print_category_hex(osmo_stderr_target, 0);
 	log_set_print_category(osmo_stderr_target, 1);
diff --git a/tests/tdef/tdef_vty_config_root_test.c b/tests/tdef/tdef_vty_config_root_test.c
index 8c46d958..10534687 100644
--- a/tests/tdef/tdef_vty_config_root_test.c
+++ b/tests/tdef/tdef_vty_config_root_test.c
@@ -180,7 +180,7 @@ static void handle_options(int argc, char **argv)
 			cmdline_config.config_file = optarg;
 			break;
 		case 'T':
-			log_set_print_timestamp(osmo_stderr_target, 1);
+			log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_CTIME);
 			break;
 		case 'e':
 			log_set_log_level(osmo_stderr_target, atoi(optarg));
diff --git a/tests/tdef/tdef_vty_config_subnode_test.c b/tests/tdef/tdef_vty_config_subnode_test.c
index e3e165da..bdc4cd13 100644
--- a/tests/tdef/tdef_vty_config_subnode_test.c
+++ b/tests/tdef/tdef_vty_config_subnode_test.c
@@ -173,7 +173,7 @@ static void handle_options(int argc, char **argv)
 			cmdline_config.config_file = optarg;
 			break;
 		case 'T':
-			log_set_print_timestamp(osmo_stderr_target, 1);
+			log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_CTIME);
 			break;
 		case 'e':
 			log_set_log_level(osmo_stderr_target, atoi(optarg));
diff --git a/tests/tdef/tdef_vty_dynamic_test.c b/tests/tdef/tdef_vty_dynamic_test.c
index b646c54e..f8441cc9 100644
--- a/tests/tdef/tdef_vty_dynamic_test.c
+++ b/tests/tdef/tdef_vty_dynamic_test.c
@@ -247,7 +247,7 @@ static void handle_options(int argc, char **argv)
 			cmdline_config.config_file = optarg;
 			break;
 		case 'T':
-			log_set_print_timestamp(osmo_stderr_target, 1);
+			log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_CTIME);
 			break;
 		case 'e':
 			log_set_log_level(osmo_stderr_target, atoi(optarg));
diff --git a/tests/vty/vty_transcript_test.c b/tests/vty/vty_transcript_test.c
index 5602c505..df604d7c 100644
--- a/tests/vty/vty_transcript_test.c
+++ b/tests/vty/vty_transcript_test.c
@@ -94,7 +94,7 @@ static void handle_options(int argc, char **argv)
 			cmdline_config.config_file = optarg;
 			break;
 		case 'T':
-			log_set_print_timestamp(osmo_stderr_target, 1);
+			log_set_print_timestamp2(osmo_stderr_target, LOG_TIMESTAMP_CTIME);
 			break;
 		case 'e':
 			log_set_log_level(osmo_stderr_target, atoi(optarg));