[Qemu-devel] [PATCH v6] add timestamp to error_report()

[Qemu-devel] [PATCH v6] add timestamp to error_report()

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

Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
---
Changelog
 v5 -> v6
 - Remove include/qemu/time.h and utils/qemu-time.c.
 - Fix a syntax and indent of messages in msg option's DEF().
 - Change explanation of the msg option.

 v4 -> v5
 - 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/error-report.h |    2 ++
 qemu-options.hx             |   11 +++++++++++
 util/qemu-error.c           |   10 ++++++++++
 vl.c                        |   26 ++++++++++++++++++++++++++
 4 files changed, 49 insertions(+), 0 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 14c1719..3b098a9 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -14,6 +14,7 @@
 #define QEMU_ERROR_H
 
 #include <stdarg.h>
+#include <stdbool.h>
 #include "qemu/compiler.h"
 
 typedef struct Location {
@@ -40,5 +41,6 @@ void error_print_loc(void);
 void error_set_progname(const char *argv0);
 void error_report(const char *fmt, ...) GCC_FMT_ATTR(1, 2);
 const char *error_get_progname(void);
+extern bool enable_timestamp_msg;
 
 #endif
diff --git a/qemu-options.hx b/qemu-options.hx
index ca6fdf6..f241379 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3098,6 +3098,17 @@ property must be set.  These objects are placed in the
 '/objects' path.
 ETEXI
 
+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
+
 HXCOMM This is the last statement. Insert new options before this line!
 STEXI
 @end table
diff --git a/util/qemu-error.c b/util/qemu-error.c
index 08a36f4..fec02c6 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -196,6 +196,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 +207,15 @@ void error_print_loc(void)
 void error_report(const char *fmt, ...)
 {
     va_list ap;
+    GTimeVal tv;
+    gchar *timestr;
+
+    if (enable_timestamp_msg) {
+        g_get_current_time(&tv);
+        timestr = g_time_val_to_iso8601(&tv);
+        error_printf("%s ", timestr);
+        g_free(timestr);
+    }
 
     error_print_loc();
     va_start(ap, fmt);
diff --git a/vl.c b/vl.c
index 0a8f056..589d264 100644
--- a/vl.c
+++ b/vl.c
@@ -516,6 +516,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 +1471,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 +2919,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 +3827,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

Re: [Qemu-devel] [PATCH v6] add timestamp to error_report()

[Stefan Hajnoczi]

On Wed, Jul 03, 2013 at 11:02:46PM -0400, Seiji Aguchi wrote:
> [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
>  v5 -> v6
>  - Remove include/qemu/time.h and utils/qemu-time.c.
>  - Fix a syntax and indent of messages in msg option's DEF().
>  - Change explanation of the msg option.
> 
>  v4 -> v5
>  - 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/error-report.h |    2 ++
>  qemu-options.hx             |   11 +++++++++++
>  util/qemu-error.c           |   10 ++++++++++
>  vl.c                        |   26 ++++++++++++++++++++++++++
>  4 files changed, 49 insertions(+), 0 deletions(-)

Reviewed-by: Stefan Hajnoczi <stefanha@redhat.com>

Re: [Qemu-devel] [PATCH v6] add timestamp to error_report()

[Luiz Capitulino]

On Wed, 03 Jul 2013 23:02:46 -0400
Seiji Aguchi <seiji.aguchi@hds.com> wrote:

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

I can take this through the QMP tree, but I have two review
comments below.

> Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
> ---
> Changelog
>  v5 -> v6
>  - Remove include/qemu/time.h and utils/qemu-time.c.
>  - Fix a syntax and indent of messages in msg option's DEF().
>  - Change explanation of the msg option.
> 
>  v4 -> v5
>  - 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/error-report.h |    2 ++
>  qemu-options.hx             |   11 +++++++++++
>  util/qemu-error.c           |   10 ++++++++++
>  vl.c                        |   26 ++++++++++++++++++++++++++
>  4 files changed, 49 insertions(+), 0 deletions(-)
> 
> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
> index 14c1719..3b098a9 100644
> --- a/include/qemu/error-report.h
> +++ b/include/qemu/error-report.h
> @@ -14,6 +14,7 @@
>  #define QEMU_ERROR_H
>  
>  #include <stdarg.h>
> +#include <stdbool.h>
>  #include "qemu/compiler.h"
>  
>  typedef struct Location {
> @@ -40,5 +41,6 @@ void error_print_loc(void);
>  void error_set_progname(const char *argv0);
>  void error_report(const char *fmt, ...) GCC_FMT_ATTR(1, 2);
>  const char *error_get_progname(void);
> +extern bool enable_timestamp_msg;
>  
>  #endif
> diff --git a/qemu-options.hx b/qemu-options.hx
> index ca6fdf6..f241379 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -3098,6 +3098,17 @@ property must be set.  These objects are placed in the
>  '/objects' path.
>  ETEXI
>  
> +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",

Did you really intend to say it's on by default? Because it's actually
disabled by default. I prefer having this disabled btw, and I can fix it
myself before applying if that's what you intended.

> +    QEMU_ARCH_ALL)
> +STEXI
> +@item -msg timestamp[=on|off]
> +@findex -msg
> +prepend a timestamp to each log message.(default:on)
> +ETEXI
> +
>  HXCOMM This is the last statement. Insert new options before this line!
>  STEXI
>  @end table
> diff --git a/util/qemu-error.c b/util/qemu-error.c
> index 08a36f4..fec02c6 100644
> --- a/util/qemu-error.c
> +++ b/util/qemu-error.c
> @@ -196,6 +196,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 +207,15 @@ void error_print_loc(void)
>  void error_report(const char *fmt, ...)
>  {

There are some errors being printed to stderr that call error_get_pretty(),
you might want to convert them to error_report() to increase coverage. But
you can do this as a follow up patch.

>      va_list ap;
> +    GTimeVal tv;
> +    gchar *timestr;
> +
> +    if (enable_timestamp_msg) {
> +        g_get_current_time(&tv);
> +        timestr = g_time_val_to_iso8601(&tv);
> +        error_printf("%s ", timestr);
> +        g_free(timestr);
> +    }
>  
>      error_print_loc();
>      va_start(ap, fmt);
> diff --git a/vl.c b/vl.c
> index 0a8f056..589d264 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -516,6 +516,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 +1471,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 +2919,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 +3827,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);
>              }

Re: [Qemu-devel] [PATCH v6] add timestamp to error_report()

[Seiji Aguchi]

> > +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",
> 
> Did you really intend to say it's on by default? Because it's actually
> disabled by default. I prefer having this disabled btw, and I can fix it
> myself before applying if that's what you intended.


My default  is "-msg timestamp".
Why do you think it is actually disabled by default?


> >  /*
> >   * 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 +207,15 @@ void error_print_loc(void)
> >  void error_report(const char *fmt, ...)
> >  {
> 
> There are some errors being printed to stderr that call error_get_pretty(),
> you might want to convert them to error_report() to increase coverage. But
> you can do this as a follow up patch.

I will make a follow up patch after this patch is merged to your tree.

Seiji

Re: [Qemu-devel] [PATCH v6] add timestamp to error_report()

[Luiz Capitulino]

On Mon, 8 Jul 2013 18:47:24 +0000
Seiji Aguchi <seiji.aguchi@hds.com> wrote:

> > > +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",
> > 
> > Did you really intend to say it's on by default? Because it's actually
> > disabled by default. I prefer having this disabled btw, and I can fix it
> > myself before applying if that's what you intended.
> 
> 
> My default  is "-msg timestamp".
> Why do you think it is actually disabled by default?

Oh, for some reason I assumed you wanted the timestamps to show up
even when -msg is not passed. But now I see that it's on by default
only if -msg timestamp is passed. Seems reasonable.

Applied to the qmp branch, thanks.

Re: [Qemu-devel] [PATCH v6] add timestamp to error_report()

[Laszlo Ersek]

On 07/08/13 21:00, Luiz Capitulino wrote:
> On Mon, 8 Jul 2013 18:47:24 +0000
> Seiji Aguchi <seiji.aguchi@hds.com> wrote:
> 
>>>> +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",
>>>
>>> Did you really intend to say it's on by default? Because it's actually
>>> disabled by default. I prefer having this disabled btw, and I can fix it
>>> myself before applying if that's what you intended.
>>
>>
>> My default  is "-msg timestamp".
>> Why do you think it is actually disabled by default?
> 
> Oh, for some reason I assumed you wanted the timestamps to show up
> even when -msg is not passed. But now I see that it's on by default
> only if -msg timestamp is passed. Seems reasonable.

Yeah the "(default: XXX)" statements in "qemu-options.hx" keep confusing
me too. They don't document the default qemu behavior (ie. with the
option absent) but the default behavior of the specific option, if given
on the command line :)

> Applied to the qmp branch, thanks.

Great, thanks!

In case you're willing to reword the commit message:

Reviewed-by: Laszlo Ersek <lersek@redhat.com>

Laszlo