[Qemu-devel] [PATCH v5] Add timestamp to error_report()

[Seiji Aguchi <seiji.aguchi@hds.com>]

[Issue]
When we offer a customer support service and a problem happens
in a customer's system, we try to understand the problem by
comparing what the customer reports with message logs of the
customer's system.

In this case, we often need to know when the problem happens.

But, currently, there is no timestamp in qemu's error messages.
Therefore, we may not be able to understand the problem based on
error messages.

[Solution]
Add a timestamp to qemu's error message logged by
error_report() with g_time_val_to_iso8601().

Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
---
Changelog
 v4 -> v5
 - Use sizeof() to define TIMESTAMP_LEN.
 - Fix descriptions of msg option.
 - Rename TIME_H to QEMU_TIME_H. (avoiding double inclusion of qemu/time.h)
 - Change argument of qemu_get_timestamp_str to "char *" and "size_t".
 - Confirmed msg option is displayed by query-command-line-options.

 v3 -> v4
 - Correct email address of Signed-off-by.

 v2 -> v3
 - Use g_time_val_to_iso8601() to get timestamp instead of
   copying libvirt's time-handling functions.

   According to discussion below, qemu doesn't need to take care
   if timestamp functions are async-signal safe or not.

   http://marc.info/?l=qemu-devel&m=136741841921265&w=2

   Also, In the review of v2 patch, strftime() are recommended to
   format string. But it is not a suitable function to handle msec.

   Then, simply call g_time_val_to_iso8601().

 - Intoroduce a common time-handling function to util/qemu-time.c.
   (Suggested by Daniel P. Berrange)

 - Add testing for g_time_val_to_iso8601() to tests/test-time.c.
   The test cases are copied from libvirt's virtimetest.
   (Suggested by Daniel P. Berrange)

 v1 -> v2

 - add an option, -msg timestamp={on|off}, to enable output message with timestamp
---
 include/qemu/time.h |   10 ++++++++++
 qemu-options.hx     |   12 ++++++++++++
 util/Makefile.objs  |    1 +
 util/qemu-error.c   |    8 ++++++++
 util/qemu-time.c    |   26 ++++++++++++++++++++++++++
 vl.c                |   28 ++++++++++++++++++++++++++++
 6 files changed, 85 insertions(+), 0 deletions(-)
 create mode 100644 include/qemu/time.h
 create mode 100644 util/qemu-time.c

diff --git a/include/qemu/time.h b/include/qemu/time.h
new file mode 100644
index 0000000..ce3903e
--- /dev/null
+++ b/include/qemu/time.h
@@ -0,0 +1,10 @@
+#ifndef QEMU_TIME_H
+#define QEMU_TIME_H
+
+#include "qemu-common.h"
+
+#define TIMESTAMP_LEN sizeof("1970-01-01T00:00:00.999999Z")
+extern void qemu_get_timestamp_str(char *, size_t);
+extern bool enable_timestamp_msg;
+
+#endif /* QEMU_TIME_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index ca6fdf6..a6dac1a 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
 STEXI
 @end table
 ETEXI
+
+DEF("msg", HAS_ARG, QEMU_OPTION_msg,
+    "-msg [timestamp=on|off]\n"
+    "  change the format of messages\n"
+    "  timestamp=on|off enables leading timestamps (default:on)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -msg timestamp=on|off
+@findex -msg
+prepend a timestamp to each log message.
+(disabled by default)
+ETEXI
diff --git a/util/Makefile.objs b/util/Makefile.objs
index dc72ab0..063db56 100644
--- a/util/Makefile.objs
+++ b/util/Makefile.objs
@@ -11,3 +11,4 @@ util-obj-y += iov.o aes.o qemu-config.o qemu-sockets.o uri.o notify.o
 util-obj-y += qemu-option.o qemu-progress.o
 util-obj-y += hexdump.o
 util-obj-y += crc32c.o
+util-obj-y += qemu-time.o
diff --git a/util/qemu-error.c b/util/qemu-error.c
index 08a36f4..c65fdfd 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -12,6 +12,7 @@
 
 #include <stdio.h>
 #include "monitor/monitor.h"
+#include "qemu/time.h"
 
 /*
  * Print to current monitor if we have one, else to stderr.
@@ -196,6 +197,7 @@ void error_print_loc(void)
     }
 }
 
+bool enable_timestamp_msg;
 /*
  * Print an error message to current monitor if we have one, else to stderr.
  * Format arguments like sprintf().  The result should not contain
@@ -206,6 +208,12 @@ void error_print_loc(void)
 void error_report(const char *fmt, ...)
 {
     va_list ap;
+    char timestr[TIMESTAMP_LEN];
+
+    if (enable_timestamp_msg) {
+        qemu_get_timestamp_str(timestr, sizeof(timestr));
+        error_printf("%s ", timestr);
+    }
 
     error_print_loc();
     va_start(ap, fmt);
diff --git a/util/qemu-time.c b/util/qemu-time.c
new file mode 100644
index 0000000..3862788
--- /dev/null
+++ b/util/qemu-time.c
@@ -0,0 +1,26 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <seiji.aguchi@hds.com>
+ *
+ * This work is licensed under the terms of the GNU GPL, version 2 or later.
+ * See the COPYING file in the top-level directory.
+ */
+#include "qemu/time.h"
+
+void qemu_get_timestamp_str(char *timestr, size_t len)
+{
+    GTimeVal tv;
+    gchar *tmp_str = NULL;
+
+    /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */
+    assert(len >= TIMESTAMP_LEN);
+
+    g_get_current_time(&tv);
+    tmp_str = g_time_val_to_iso8601(&tv);
+    g_strlcpy((gchar *)timestr, tmp_str, len);
+    g_free(tmp_str);
+}
diff --git a/vl.c b/vl.c
index 0a8f056..aee7350 100644
--- a/vl.c
+++ b/vl.c
@@ -171,6 +171,8 @@ int main(int argc, char **argv)
 #include "ui/qemu-spice.h"
 #include "qapi/string-input-visitor.h"
 
+#include "qemu/time.h"
+
 //#define DEBUG_NET
 //#define DEBUG_SLIRP
 
@@ -516,6 +518,18 @@ static QemuOptsList qemu_realtime_opts = {
     },
 };
 
+static QemuOptsList qemu_msg_opts = {
+    .name = "msg",
+    .head = QTAILQ_HEAD_INITIALIZER(qemu_msg_opts.head),
+    .desc = {
+        {
+            .name = "timestamp",
+            .type = QEMU_OPT_BOOL,
+        },
+        { /* end of list */ }
+    },
+};
+
 const char *qemu_get_vm_name(void)
 {
     return qemu_name;
@@ -1459,6 +1473,12 @@ static void configure_realtime(QemuOpts *opts)
     }
 }
 
+
+static void configure_msg(QemuOpts *opts)
+{
+    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
+}
+
 /***********************************************************/
 /* USB devices */
 
@@ -2901,6 +2921,7 @@ int main(int argc, char **argv, char **envp)
     qemu_add_opts(&qemu_object_opts);
     qemu_add_opts(&qemu_tpmdev_opts);
     qemu_add_opts(&qemu_realtime_opts);
+    qemu_add_opts(&qemu_msg_opts);
 
     runstate_init();
 
@@ -3808,6 +3829,13 @@ int main(int argc, char **argv, char **envp)
                 }
                 configure_realtime(opts);
                 break;
+            case QEMU_OPTION_msg:
+                opts = qemu_opts_parse(qemu_find_opts("msg"), optarg, 0);
+                if (!opts) {
+                    exit(1);
+                }
+                configure_msg(opts);
+                break;
             default:
                 os_parse_cmd_args(popt->index, optarg);
             }
-- 1.7.1