Skip to contentSkip to conversation

Add timestamp to error_report()

PATCH Superseded Seiji Aguchi 3 participants 9 messages Jul 1, 2013 – Jul 4, 2013

v5 of 6 Superseded Latest is v6 →

lore
Share & tools
lore
#0 lore raw

PATCH v5 1/1 Add timestamp to error_report()

[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().

---
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
include/qemu/time.h new file +10 -0
new file mode 100644
index 0000000..ce3903e
@@ -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 */
qemu-options.hx +12 -0
index ca6fdf6..a6dac1a 100644
@@ -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
util/Makefile.objs +1 -0
index dc72ab0..063db56 100644
@@ -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
util/qemu-error.c +8 -0
index 08a36f4..c65fdfd 100644
@@ -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);
util/qemu-time.c new file +26 -0
new file mode 100644
index 0000000..3862788
@@ -0,0 +1,26 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <[email protected]>
+ *
+ * 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);
+}
vl.c +28 -0
index 0a8f056..aee7350 100644
@@ -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

Reviewed-by on v5 1/1
#1 lore raw
Quoted 17 lines · Seiji Aguchi

[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().

Quoted 8 lines

---
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.

Since you plan to post followup patches, please at that time include a one-liner modification: the STEXI-ETEXI section in "qemu-options.hx" still says (right before ETEXI) "(disabled by default)". I think it should be fixed in a followup, not by posting v6.

Thanks!
Laszlo

#2 lore raw
In reply to Seiji Aguchi
Quoted 10 lines · Seiji Aguchi
qemu-options.hx +2 -0
index ca6fdf6..a6dac1a 100644
@@ -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,

qemu-options.hx HXCOMM This is the last statement. Insert new options before this line! · line 3116

Quoted 10 lines
qemu-options.hx +10 -0
+    "-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

I am confused. If the user specifies -msg then enable_timestamp_msg is on by default. If the user does not specify -msg then enable_timestmap_msg is off. Did I get that right?

This means that the default behavior of QEMU does not change but you can add -msg to enable timestamps.

I'm happy with this but find the documentation confusing.

Quoted 22 lines
util/qemu-time.c new file +16 -0
new file mode 100644
index 0000000..3862788
@@ -0,0 +1,26 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <[email protected]>
+ *
+ * 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;

util/qemu-time.c line 26

Quoted 10 lines
util/qemu-time.c new file +10 -0
+    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);
+}

Why strcpy into a fixed-size buffer when glib gives us a heap-allocated string?

This patch would be simpler by dropping qemu-time.c/time.h and simply doing:

if (enable_timestamp_msg) {
    GTimeVal tv;
    gchar *timestamp;

    g_get_current_time(&tv);
    timestamp = g_time_val_to_iso8601(&tv);
    error_printf("%s ", timestamp);
    g_free(timestamp);
}
#3 lore raw
Quoted 17 lines

qemu-options.hx HXCOMM This is the last statement. Insert new options before this line! · line 3116

Quoted 13 lines
qemu-options.hx +11 -0
+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

I am confused. If the user specifies -msg then enable_timestamp_msg is on by default. If the user does not specify -msg then enable_timestmap_msg is off. Did I get that right?

Yes.

Quoted 5 lines

This means that the default behavior of QEMU does not change but you can add -msg to enable timestamps.

I'm happy with this but find the documentation confusing.

I can remove "(disabled by default)" if needed.

Quoted 37 lines
Quoted 23 lines
util/qemu-time.c new file +16 -0
new file mode 100644
index 0000000..3862788
@@ -0,0 +1,26 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <[email protected]>
+ *
+ * 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;

util/qemu-time.c line 26

Quoted 10 lines
util/qemu-time.c new file +10 -0
+    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);
+}

Why strcpy into a fixed-size buffer when glib gives us a heap-allocated string?

Quoted 1 line

This patch would be simpler by dropping qemu-time.c/time.h

I plan to introduce timestamp to monitor_printf() and fprintf() near future.

In this case, it is better from a maintenance POV to keep time-handling
functionality in a file that's separate from the qemu error file, so it can be reused
elsewhere in QEMU if needed.

It is suggested by Daniel.
http://marc.info/?l=qemu-devel&m=136741113218944&w=2

Quoted 11 lines

and simply
doing:

if (enable_timestamp_msg) {
    GTimeVal tv;
    gchar *timestamp;

    g_get_current_time(&tv);
    timestamp = g_time_val_to_iso8601(&tv);
    error_printf("%s ", timestamp);
    g_free(timestamp);

I'm concerned that we may have potential memory leak If someone neglect to call the g_free(). That is why I use the fixed-size buffer.

Seiji

#4 lore raw
Quoted 41 lines · Seiji Aguchi
Quoted 36 lines
Quoted 22 lines
util/qemu-time.c new file +16 -0
new file mode 100644
index 0000000..3862788
@@ -0,0 +1,26 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <[email protected]>
+ *
+ * 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;

util/qemu-time.c line 26

Quoted 10 lines
util/qemu-time.c new file +10 -0
+    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);
+}

Why strcpy into a fixed-size buffer when glib gives us a heap-allocated string?

Quoted 1 line

This patch would be simpler by dropping qemu-time.c/time.h

I plan to introduce timestamp to monitor_printf() and fprintf() near future.

Quoted 6 lines

In this case, it is better from a maintenance POV to keep time-handling
functionality in a file that's separate from the qemu error file, so it can be reused
elsewhere in QEMU if needed.

It is suggested by Daniel.
http://marc.info/?l=qemu-devel&m=136741113218944&w=2

Daniel's statement was about the code you copied from libvirt. It was not about using the glib function, which simplifies things greatly and avoids the need for a test suite.

Patches need to make sense today, please do not add extra code with potential future use in mind:

1. Other developers must be able to read and modify the current codebase on its own. They do not know what potential future changes you were thinking about.

2. You may never end up submitting or getting the future stuff upstream. Then we'd be left with extra layers that are never used.

Stefan

#5 lore raw
Quoted 9 lines

Patches need to make sense today, please do not add extra code with potential future use in mind:

1. Other developers must be able to read and modify the current codebase on its own. They do not know what potential future changes you were thinking about.

2. You may never end up submitting or getting the future stuff upstream. Then we'd be left with extra layers that are never used.

I understand what you are concerned.
I will remove utils/qemu-time.c and its header file.

Quoted 3 lines

Daniel's statement was about the code you copied from libvirt. It was not about using the glib function, which simplifies things greatly and avoids the need for a test suite.

Honestly, I still think it is reasonable to introduce the common time-handling functionality. You seem to say that using the glib function is simple, so we don't need to introduce the common functionality.

However, "commonly useful" is not related whether it is simple or not.
I'm concerned that we may duplicate same code by "focusing on today too much".

But, I don't stick to my opinion on this patch.

Seiji

#6 lore raw
In reply to Seiji Aguchi
Quoted 21 lines · Seiji Aguchi
Quoted 17 lines

qemu-options.hx HXCOMM This is the last statement. Insert new options before this line! · line 3116

Quoted 13 lines
qemu-options.hx +11 -0
+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

I am confused. If the user specifies -msg then enable_timestamp_msg is on by default. If the user does not specify -msg then enable_timestmap_msg is off. Did I get that right?

Yes.

Quoted 1 line
Quoted 6 lines
Quoted 4 lines

This means that the default behavior of QEMU does not change but you can add -msg to enable timestamps.

I'm happy with this but find the documentation confusing.

I can remove "(disabled by default)" if needed.

Perhaps the simplest solution is timestamp=off by default. Then there can be no confusion and users must do -msg timestamp=on to enable timestamps.

If you really want to keep -msg as a shortcut for -msg timestamp=on, then please document explicitly that:
1. Without -msg timestamps are off.
1. With -msg timestamps are on.
2. -msg timestamp=off can be used to turn timestamps off again.

Stefan

#7 lore raw
Quoted 44 lines

-----Original Message-----
From: Stefan Hajnoczi [mailto:[email protected]]
Sent: Wednesday, July 03, 2013 5:14 AM
To: Seiji Aguchi
Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; Tomoki Sekiyama; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Subject: Re: [PATCH v5] Add timestamp to error_report()

Quoted 21 lines · Seiji Aguchi
Quoted 17 lines

qemu-options.hx HXCOMM This is the last statement. Insert new options before this line! · line 3116

Quoted 13 lines
qemu-options.hx +11 -0
+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

I am confused. If the user specifies -msg then enable_timestamp_msg is on by default. If the user does not specify -msg then enable_timestmap_msg is off. Did I get that right?

Yes.

Quoted 1 line
Quoted 6 lines
Quoted 4 lines

This means that the default behavior of QEMU does not change but you can add -msg to enable timestamps.

I'm happy with this but find the documentation confusing.

I can remove "(disabled by default)" if needed.

Perhaps the simplest solution is timestamp=off by default. Then there can be no confusion and users must do -msg timestamp=on to enable timestamps.

Quoted 5 lines

If you really want to keep -msg as a shortcut for -msg timestamp=on, then please document explicitly that:
1. Without -msg timestamps are off.
1. With -msg timestamps are on.
2. -msg timestamp=off can be used to turn timestamps off again.

My apologies for the confusion.

The syntax, "-msg [timestamp=on|off]", was wrong.
"-msg timestamp[=on|off]" is correct.

And there is no way to make "timestamp" optional, as far as I looked into a source code. Therefore, the explanation should be as below.
(I think it is reasonable to keep "-msg timestamp" as a shortcut for -msg timestamp=on.)

<snip>
+DEF("msg", HAS_ARG, QEMU_OPTION_msg,

+    "-msg timestamp[=on|off]\n"
+    "                change the format of messages\n"
+    "                on|off controls leading timestamps (default:on)\n",
+    QEMU_ARCH_ALL)

+STEXI
+@item -msg timestamp[=on|off]
+@findex -msg
+prepend a timestamp to each log message.(default:on) +ETEXI
<snip>

To be simpler, we may be able to introduce just a single -msg-timestamp. But I think current "-msg timestamp[=on|off]" is reasonable because other options may be introduced to msg, like log_level or debug.

Seiji

#8 lore raw
Quoted 50 lines · Seiji Aguchi
Quoted 44 lines

-----Original Message-----
From: Stefan Hajnoczi [mailto:[email protected]]
Sent: Wednesday, July 03, 2013 5:14 AM
To: Seiji Aguchi
Cc: [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]; Tomoki Sekiyama; [email protected]; [email protected]; [email protected]; [email protected]; [email protected]
Subject: Re: [PATCH v5] Add timestamp to error_report()

Quoted 21 lines · Seiji Aguchi
Quoted 17 lines

qemu-options.hx HXCOMM This is the last statement. Insert new options before this line! · line 3116

Quoted 13 lines
qemu-options.hx +11 -0
+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

I am confused. If the user specifies -msg then enable_timestamp_msg is on by default. If the user does not specify -msg then enable_timestmap_msg is off. Did I get that right?

Yes.

Quoted 1 line
Quoted 6 lines
Quoted 4 lines

This means that the default behavior of QEMU does not change but you can add -msg to enable timestamps.

I'm happy with this but find the documentation confusing.

I can remove "(disabled by default)" if needed.

Perhaps the simplest solution is timestamp=off by default. Then there can be no confusion and users must do -msg timestamp=on to enable timestamps.

Quoted 5 lines

If you really want to keep -msg as a shortcut for -msg timestamp=on, then please document explicitly that:
1. Without -msg timestamps are off.
1. With -msg timestamps are on.
2. -msg timestamp=off can be used to turn timestamps off again.

Quoted 8 lines

My apologies for the confusion.

The syntax, "-msg [timestamp=on|off]", was wrong.
"-msg timestamp[=on|off]" is correct.

And there is no way to make "timestamp" optional, as far as I looked into a source code. Therefore, the explanation should be as below.
(I think it is reasonable to keep "-msg timestamp" as a shortcut for -msg timestamp=on.)

Yes, I think you are correct. I thought previously that "-msg" works but it seems an option is always required.

Quoted 13 lines

<snip>

qemu-options.hx +10 -0
+DEF("msg", HAS_ARG, QEMU_OPTION_msg,
+    "-msg timestamp[=on|off]\n"
+    "                change the format of messages\n"
+    "                on|off controls leading timestamps (default:on)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -msg timestamp[=on|off]
+@findex -msg
+prepend a timestamp to each log message.(default:on)
+ETEXI
<snip>
Quoted 3 lines

To be simpler, we may be able to introduce just a single -msg-timestamp. But I think current "-msg timestamp[=on|off]" is reasonable because other options may be introduced to msg, like log_level or debug.

Yep.

Stefan