logging: add 'logging timezone (localtime|utc)'

Add ability to print logging timestamps in UTC.

I want to test logging timestamps in vty transcript tests. To get
deterministic timestamps, I can use osmo_gettimeofday_override().
However, so far we log in the server's local time zone: the dates
printed after osmo_gettimeofday_override() still change according to the
locally configured timezone -- not good for regression testing. For UTC,
it is always the same.

The intended use is for regression testing of timestamps, but maybe
logging in UTC may be useful to some user out there, too.

Change-Id: I7f868b47bf8f8dfcf85e735f490ae69b18111af4

configure.ac

@@ -130,6 +130,7 @@ CFLAGS="$saved_CFLAGS"
 AC_SUBST(SYMBOL_VISIBILITY)
 
 AC_CHECK_FUNCS(localtime_r)
+AC_CHECK_FUNCS(gmtime_r)
 
 AC_DEFUN([CHECK_TM_INCLUDES_TM_GMTOFF], [
   AC_CACHE_CHECK(

include/osmocom/core/logging.h

@@ -295,6 +295,11 @@ enum log_filename_pos {
 	LOG_FILENAME_POS_LINE_END,
 };
 
+enum log_timezone {
+	LOG_TIMEZONE_LOCALTIME,
+	LOG_TIMEZONE_UTC,
+};
+
 /*! structure representing a logging target */
 struct log_target {
 	struct llist_head entry;		/*!< linked list */
@@ -391,6 +396,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;
+
+	/* Set timezone for timestamps (if at all enabled) */
+	enum log_timezone timezone;
 };
 
 /* use the above macros */
@@ -412,6 +420,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_timezone(struct log_target *target, enum log_timezone timezone);
 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);

src/core/libosmocore.map

@@ -83,6 +83,7 @@ log_set_print_level;
 log_set_print_tid;
 log_set_print_timestamp;
 log_set_use_color;
+log_set_timezone;
 log_target_create;
 log_target_create_file;
 log_target_create_file_stream;

src/core/logging.c

@@ -464,6 +464,25 @@ 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);
+	switch (target->timezone) {
+	case LOG_TIMEZONE_LOCALTIME:
+#ifdef HAVE_LOCALTIME_R
+		return (localtime_r(&tv->tv_sec, tm) != NULL) ? 0 : -1;
+#endif
+		/* If there is no localtime_r() function, then maybe gmtime_r() is available instead? */
+	case LOG_TIMEZONE_UTC:
+#ifdef HAVE_GMTIME_R
+		return (gmtime_r(&tv->tv_sec, tm) != NULL) ? 0 : -1;
+#endif
+		/* If there is no gmtime_r() function, then print no timestamp. */
+	default:
+		return -1;
+	}
+}
+
 /*! 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
@@ -494,12 +513,9 @@ static int _output_buf(char *buf, int buf_len, struct log_target *target, unsign
 		}
 	}
 	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);
+		struct timeval tv;
+		struct tm tm;
+		if (target->print_ext_timestamp && get_timestamp(&tv, &tm, target) == 0) {
 			ret = snprintf(buf + offset, rem, "%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,
@@ -507,14 +523,10 @@ static int _output_buf(char *buf, int buf_len, struct log_target *target, unsign
 			if (ret < 0)
 				goto err;
 			OSMO_SNPRINTF_RET(ret, rem, offset, len);
-#endif
-		} else if (target->print_timestamp) {
-			time_t tm;
-			if ((tm = time(NULL)) == (time_t) -1)
-				goto err;
+		} else if (target->print_timestamp && get_timestamp(&tv, &tm, target) == 0) {
 			/* Get human-readable representation of time.
 			   man ctime: we need at least 26 bytes in buf */
-			if (rem < 26 || !ctime_r(&tm, buf + offset))
+			if (rem < 26 || !asctime_r(&tm, buf + offset))
 				goto err;
 			ret = strlen(buf + offset);
 			if (ret <= 0)
@@ -851,6 +863,15 @@ void log_set_print_timestamp(struct log_target *target, int print_timestamp)
 	target->print_timestamp = print_timestamp;
 }
 
+/*! Switch logging timezone between UTC or local time.
+ *  \param[in] target Log target to be affected.
+ *  \param[in] timezone Timezone to set.
+ */
+void log_set_timezone(struct log_target *target, enum log_timezone timezone)
+{
+	target->timezone = timezone;
+}
+
 /*! 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

src/vty/logging_vty.c

@@ -190,6 +190,22 @@ DEFUN(logging_use_clr,
 	RET_WITH_UNLOCK(CMD_SUCCESS);
 }
 
+DEFUN(logging_timezone,
+      logging_timezone_cmd,
+      "logging timezone (localtime|utc)",
+	LOGGING_STR "Configure time zone for log message timestamping\n"
+	"Log timestamps in the system's local time\n"
+	"Log timestamps in Coordinated Universal Time (UTC)\n")
+{
+	struct log_target *tgt;
+	ACQUIRE_VTY_LOG_TGT_WITH_LOCK(vty, tgt);
+	if (strcmp(argv[0], "utc") == 0)
+		log_set_timezone(tgt, LOG_TIMEZONE_UTC);
+	else
+		log_set_timezone(tgt, LOG_TIMEZONE_LOCALTIME);
+	RET_WITH_UNLOCK(CMD_SUCCESS);
+}
+
 DEFUN(logging_prnt_timestamp,
       logging_prnt_timestamp_cmd,
       "logging timestamp (0|1)",
@@ -1061,6 +1077,17 @@ static int config_write_log_single(struct vty *vty, struct log_target *tgt)
 	else
 		vty_out(vty, " logging timestamp %u%s",
 			tgt->print_timestamp ? 1 : 0, VTY_NEWLINE);
+
+	switch (tgt->timezone) {
+	case LOG_TIMEZONE_UTC:
+		vty_out(vty, " logging timezone utc%s", VTY_NEWLINE);
+		break;
+	default:
+	case LOG_TIMEZONE_LOCALTIME:
+		/* write nothing, since LOG_TIMEZONE_LOCALTIME is the default */
+		break;
+	}
+
 	if (tgt->print_level)
 		vty_out(vty, " logging print level 1%s", VTY_NEWLINE);
 	vty_out(vty, " logging print file %s%s%s",
@@ -1204,6 +1231,7 @@ void logging_vty_add_cmds(void)
 	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_timezone_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);
@@ -1239,6 +1267,7 @@ void logging_vty_add_cmds(void)
 	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_timezone_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);

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 timezone (localtime|utc)
   logging print thread-id (0|1)
   logging print category (0|1)
   logging print category-hex (0|1)
@@ -67,6 +68,7 @@ logging_vty_test# logging ?
   color         Configure color-printing for log messages
   timestamp     Configure log message timestamping
   print         Log output settings
+  timezone      Configure time zone for log message timestamping
   set-log-mask  Set the logmask of this logging target
   level         Set the log level for a specified category
 
@@ -74,6 +76,10 @@ logging_vty_test# logging timestamp ?
   0  Don't prefix each log message
   1  Prefix each log message with current timestamp
 
+logging_vty_test# logging timezone ?
+  localtime  Log timestamps in the system's local time
+  utc        Log timestamps in Coordinated Universal Time (UTC)
+
 logging_vty_test# logging level ?
 ... ! all
   aa         Antropomorphic Armadillos (AA)
@@ -151,6 +157,24 @@ logging_vty_test# logging print file basename ?
 
 logging_vty_test# configure terminal
 logging_vty_test(config)# log stderr
+
+logging_vty_test(config-log)# show running-config
+...
+log stderr
+... !logging timezone
+logging_vty_test(config-log)# logging timezone utc
+logging_vty_test(config-log)# show running-config
+...
+log stderr
+... !logging timezone
+ logging timezone utc
+... !logging timezone
+logging_vty_test(config-log)# logging timezone localtime
+logging_vty_test(config-log)# show running-config
+...
+log stderr
+... !logging timezone
+
 logging_vty_test(config-log)# show running-config
 ...
 log stderr