[Qemu-devel] [PATCH v4] Add timestamp to error message

[Qemu-devel] [PATCH v4] Add timestamp to error message

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

[TODO]
Add timestamp to monitor_printf() and fprintf().

Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
---
Changelog
 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)

 v1 -> v2

 - add an option, -msg timestamp={on|off}, to enable output message with timestamp
---
 include/qemu/time.h |   11 +++++++++++
 qemu-options.hx     |   12 ++++++++++++
 util/Makefile.objs  |    1 +
 util/qemu-error.c   |    8 ++++++++
 util/qemu-time.c    |   24 ++++++++++++++++++++++++
 vl.c                |   28 ++++++++++++++++++++++++++++
 6 files changed, 84 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..f70739b
--- /dev/null
+++ b/include/qemu/time.h
@@ -0,0 +1,11 @@
+#ifndef TIME_H
+#define TIME_H
+
+#include "qemu-common.h"
+
+/*  "1970-01-01T00:00:00.999999Z" + '\0' */
+#define TIMESTAMP_LEN 28
+extern void qemu_get_timestamp_str(char (*timestr)[]);
+extern bool enable_timestamp_msg;
+
+#endif /* !TIME_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index ca6fdf6..7890921 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"
+    "                output message with timestamp (default: off)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -msg timestamp=on|off
+@findex - msg
+Output message with timestamp.
+Adding timestamp to messages with @option{timestamp=on}
+(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..33fa9d3 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);
+        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..37f7b9e
--- /dev/null
+++ b/util/qemu-time.c
@@ -0,0 +1,24 @@
+/*
+ * 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)[])
+{
+    GTimeVal tv;
+    gchar *tmp_str = NULL;
+
+    g_get_current_time(&tv);
+    tmp_str = g_time_val_to_iso8601(&tv);
+    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
+    g_free(tmp_str);
+    return;
+}
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

Re: [Qemu-devel] [PATCH v4] Add timestamp to error message

[Laszlo Ersek]

comments below

On 06/27/13 04:08, 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().
> 
> [TODO]
> Add timestamp to monitor_printf() and fprintf().
> 
> Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
> ---
> Changelog
>  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().

I think this is a good choice. Based on the glib NEWS file, the latest
fix for g_time_val_to_iso8601() went into 2.19.6. Therefore the function
should be available on stable distros (eg. RHEL-6 has glib2-2.22.5-7.el6).

> 
>  - Intoroduce a common time-handling function to util/qemu-time.c.
>    (Suggested by Daniel P. Berrange)
> 
>  v1 -> v2
> 
>  - add an option, -msg timestamp={on|off}, to enable output message with timestamp
> ---
>  include/qemu/time.h |   11 +++++++++++
>  qemu-options.hx     |   12 ++++++++++++
>  util/Makefile.objs  |    1 +
>  util/qemu-error.c   |    8 ++++++++
>  util/qemu-time.c    |   24 ++++++++++++++++++++++++
>  vl.c                |   28 ++++++++++++++++++++++++++++
>  6 files changed, 84 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..f70739b
> --- /dev/null
> +++ b/include/qemu/time.h
> @@ -0,0 +1,11 @@
> +#ifndef TIME_H
> +#define TIME_H

I wonder if TIME_H is maybe a bit too nondescript and could conflict
with other guards.

The guards currently used in "include/qemu/*.h" files are inconsistent
-- some use a QEMU_ prefix, some a __QEMU_ one, and others use none.

Don't respin just because of this, but maybe it's something to consider.


> +
> +#include "qemu-common.h"
> +
> +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> +#define TIMESTAMP_LEN 28
> +extern void qemu_get_timestamp_str(char (*timestr)[]);

(a) The type of "timestr" is a valid one, it says "pointer to array of
unknown size". The array type is an incomplete type (its size is
unknown), but pointers can point to incomplete types (like to an opaque
struct, which is also an incomplete type).

It's however quite unusual to write something like this, when a simple
pointer-to-char would do. The above prototype requres any caller that
wants to format the timestamp into the middle of an array to typecasting
hackery. Compare:

{
    char buf[1024];

    /* I want the timestamp to start at the fifth element */
    qemu_get_timestamp_str((char (*)[1020])(buf + 4));
}

vs.

{
    char buf[1024];

    qemu_get_timestamp_str(buf + 4);
}

(b) Also, although it's correct C, we avoid the "extern" storage-class
specifier for function declarations in file scope. ("extern" is called a
storage-class specifier for syntax reasons, in fact it determines
linkage for the function of course.)

(c) Third suggestion for the prototype: since it can never fail, make it
return the "timestr" pointer just passed in. That would allow use such as:

{
    char buf[TIMESTAMP_LEN];

    printf("[%s] hello world!\n", qemu_get_timestamp_str(buf));
}

None of this is important of course :) The one call to this function is
nicely buried in practice, and the bikeshedding has been going on for
too long for this patch.


> +extern bool enable_timestamp_msg;
> +
> +#endif /* !TIME_H */
> diff --git a/qemu-options.hx b/qemu-options.hx
> index ca6fdf6..7890921 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"
> +    "                output message with timestamp (default: off)\n",
> +    QEMU_ARCH_ALL)
> +STEXI
> +@item -msg timestamp=on|off
> +@findex - msg

A space has snuck in between "-" and "msg". Perhaps this is the only
note that would warrant a respin (or rather a maintainer fixup at commit).


> +Output message with timestamp.

As a non-native speaker, I propose rewording this as "prepend a
timestamp to each log message" (in the prior occurrence as well) if you
decided to repost.


> +Adding timestamp to messages with @option{timestamp=on}
> +(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..33fa9d3 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);
> +        error_printf("%s ", timestr);
> +    }
>  
>      error_print_loc();
>      va_start(ap, fmt);

Does this print the timestamp to all kinds of monitors too? On stderr,
the timestamp is great. When printed to an "interactive monitor", it
could also help post-mortem debugging. But would it not confuse libvirt
eg.? (Apologies if this has been discussed before.)


> diff --git a/util/qemu-time.c b/util/qemu-time.c
> new file mode 100644
> index 0000000..37f7b9e
> --- /dev/null
> +++ b/util/qemu-time.c
> @@ -0,0 +1,24 @@
> +/*
> + * 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)[])
> +{
> +    GTimeVal tv;
> +    gchar *tmp_str = NULL;
> +
> +    g_get_current_time(&tv);

Hm. There's also g_get_monotonic_time(), but (a) that's less portable
(available since 2.28), (b) this is simply good enough IMO, in practice. OK.


> +    tmp_str = g_time_val_to_iso8601(&tv);
> +    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
> +    g_free(tmp_str);
> +    return;

You're not returning a value so the last statement is superfluous.

> +}
> 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);
> +}

I think the default value doesn't match the docs, which say "deafult:
off". As far as I recall (from Tomoki's "-realtime [mlock=on|off]"
patch), statements about defaults in the option docs don't describe how
qemu works by default (ie. when you omit the option altogether), they
describe what happens if you specify the option but omit its arguments
(ie. with "-msg" only.)

In that case, the docs should state something like:

DEF("msg", HAS_ARG, QEMU_OPTION_msg,
    "-msg [timestamp=on|off]\n"
    "     change the format of error messages\n"
    "     timestamp=on|off enables leading timestamps (default: on)\n",
    QEMU_ARCH_ALL)

> +
>  /***********************************************************/
>  /* 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);
>              }
> 

I hope you don't mind my review.

Thanks,
Laszlo

Re: [Qemu-devel] [PATCH v4] Add timestamp to error message

[Eric Blake]

[-- Attachment #1: Type: text/plain, Size: 2178 bytes --]

On 06/27/2013 04:21 AM, Laszlo Ersek wrote:
> comments below
> 
> On 06/27/13 04:08, 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.
>>

>> +extern void qemu_get_timestamp_str(char (*timestr)[]);
> 
> (a) The type of "timestr" is a valid one, it says "pointer to array of
> unknown size". The array type is an incomplete type (its size is
> unknown), but pointers can point to incomplete types (like to an opaque
> struct, which is also an incomplete type).
> 
> It's however quite unusual to write something like this, when a simple
> pointer-to-char would do.

Agreed; I made a similar comment against v3.

>>      error_print_loc();
>>      va_start(ap, fmt);
> 
> Does this print the timestamp to all kinds of monitors too? On stderr,
> the timestamp is great. When printed to an "interactive monitor", it
> could also help post-mortem debugging. But would it not confuse libvirt
> eg.? (Apologies if this has been discussed before.)

Libvirt would love to unconditionally enable timestamps in log output;
having coordination of any qemu log dumped alongside other libvirt log
output will indeed benefit from having a common timestamp synchronization.

Regarding monitor output, libvirt uses the QMP monitor, not the HMP
monitor, and this had better not prepend text to QMP output (since that
would result in non-JSON output).  It could be added as an additional
dictionary member within each QMP command, which would not impact
libvirt (which ignores dictionary elements it is not expecting, or
future libvirt could see if a timestamp was passed back).  HMP
passthrough commands called via QMP's 'human-monitor-command' might then
have the timestamp included, but that's not an issue since HMP output is
already not guaranteed stable.  But if you DO want to add it to QMP
return values, then it needs a followup patch.

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 621 bytes --]

Re: [Qemu-devel] [PATCH v4] Add timestamp to error message

[Seiji Aguchi]

> > diff --git a/include/qemu/time.h b/include/qemu/time.h
> > new file mode 100644
> > index 0000000..f70739b
> > --- /dev/null
> > +++ b/include/qemu/time.h
> > @@ -0,0 +1,11 @@
> > +#ifndef TIME_H
> > +#define TIME_H
> 
> I wonder if TIME_H is maybe a bit too nondescript and could conflict
> with other guards.
> 
> The guards currently used in "include/qemu/*.h" files are inconsistent
> -- some use a QEMU_ prefix, some a __QEMU_ one, and others use none.
> 
> Don't respin just because of this, but maybe it's something to consider.

This should be discussed in other thread...

> 
> 
> > +
> > +#include "qemu-common.h"
> > +
> > +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> > +#define TIMESTAMP_LEN 28
> > +extern void qemu_get_timestamp_str(char (*timestr)[]);

I will change to "extern void qemu_get_timestamp_str(char *timestr, size_t len)"
as Eric pointed out.

> 
> 
> > +extern bool enable_timestamp_msg;
> > +
> > +#endif /* !TIME_H */
> > diff --git a/qemu-options.hx b/qemu-options.hx
> > index ca6fdf6..7890921 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"
> > +    "                output message with timestamp (default: off)\n",
> > +    QEMU_ARCH_ALL)
> > +STEXI
> > +@item -msg timestamp=on|off
> > +@findex - msg
> 
> A space has snuck in between "-" and "msg". Perhaps this is the only
> note that would warrant a respin (or rather a maintainer fixup at commit).

I will fix it.

> 
> 
> > +Output message with timestamp.
> 
> As a non-native speaker, I propose rewording this as "prepend a
> timestamp to each log message" (in the prior occurrence as well) if you
> decided to repost.

Will fix as well.

> >  void error_report(const char *fmt, ...)
> >  {
> >      va_list ap;
> > +    char timestr[TIMESTAMP_LEN];
> > +
> > +    if (enable_timestamp_msg) {
> > +        qemu_get_timestamp_str(&timestr);
> > +        error_printf("%s ", timestr);
> > +    }
> >
> >      error_print_loc();
> >      va_start(ap, fmt);
> 
> Does this print the timestamp to all kinds of monitors too? On stderr,
> the timestamp is great. When printed to an "interactive monitor", it
> could also help post-mortem debugging. But would it not confuse libvirt
> eg.? (Apologies if this has been discussed before.)

I will try to add timestamp to monitor_printf().
(In the long term, I would like to add it to all fprintf() in qemu.)

> 
> 
> > diff --git a/util/qemu-time.c b/util/qemu-time.c
> > new file mode 100644
> > index 0000000..37f7b9e
> > --- /dev/null
> > +++ b/util/qemu-time.c
> > @@ -0,0 +1,24 @@
> > +/*
> > + * 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)[])
> > +{
> > +    GTimeVal tv;
> > +    gchar *tmp_str = NULL;
> > +
> > +    g_get_current_time(&tv);
> 
> Hm. There's also g_get_monotonic_time(), but (a) that's less portable
> (available since 2.28), (b) this is simply good enough IMO, in practice. OK.
> 
> 
> > +    tmp_str = g_time_val_to_iso8601(&tv);
> > +    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
> > +    g_free(tmp_str);
> > +    return;
> 
> You're not returning a value so the last statement is superfluous.

I will remove the unnecessary "return".

> > +
> > +static void configure_msg(QemuOpts *opts)
> > +{
> > +    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
> > +}
> 
> I think the default value doesn't match the docs, which say "deafult:
> off". As far as I recall (from Tomoki's "-realtime [mlock=on|off]"
> patch), statements about defaults in the option docs don't describe how
> qemu works by default (ie. when you omit the option altogether), they
> describe what happens if you specify the option but omit its arguments
> (ie. with "-msg" only.)
> 
> In that case, the docs should state something like:
> 
> DEF("msg", HAS_ARG, QEMU_OPTION_msg,
>     "-msg [timestamp=on|off]\n"
>     "     change the format of error messages\n"
>     "     timestamp=on|off enables leading timestamps (default: on)\n",
>     QEMU_ARCH_ALL)

Currently, this patch add timestamp to just error_report().
But, we may need it for both error and normal messages.
So, I will change the sentence "change the format of error messages"
to "change the format of messages".

I appreciate your review.

Seiji

Re: [Qemu-devel] [PATCH v4] Add timestamp to error message

[Laszlo Ersek]

On 06/28/13 20:54, Seiji Aguchi wrote:
> 
>>> diff --git a/include/qemu/time.h b/include/qemu/time.h
>>> new file mode 100644
>>> index 0000000..f70739b
>>> --- /dev/null
>>> +++ b/include/qemu/time.h
>>> @@ -0,0 +1,11 @@
>>> +#ifndef TIME_H
>>> +#define TIME_H
>>
>> I wonder if TIME_H is maybe a bit too nondescript and could conflict
>> with other guards.
>>
>> The guards currently used in "include/qemu/*.h" files are inconsistent
>> -- some use a QEMU_ prefix, some a __QEMU_ one, and others use none.
>>
>> Don't respin just because of this, but maybe it's something to consider.
> 
> This should be discussed in other thread...

Ah, right, apologies for the ambiguity. I just meant that either
QEMU_TIME_H or __QEMU_TIME_H would have a lower chance to clash with
another guard than plain TIME_H -- "some" prefix would be nice, but I
couldn't point out a specific one, because the current practice varies.
I didn't mean to suggest that you should unify the prefixes across all
guards!

Anyway, even my QEMU_TIME_H / __QEMU_TIME_H suggestion is tangential;
feel free to ignore it.

Thanks
Laszlo

Re: [Qemu-devel] [PATCH v4] Add timestamp to error message

[Seiji Aguchi]

> >>
> >> I wonder if TIME_H is maybe a bit too nondescript and could conflict
> >> with other guards.

OK.
I will use QEMU_TIME_H.
Apologies for my curt reply.

Seiji

Re: [Qemu-devel] [PATCH v4] Add timestamp to error message

[Seiji Aguchi]

> > >  void error_report(const char *fmt, ...)
> > >  {
> > >      va_list ap;
> > > +    char timestr[TIMESTAMP_LEN];
> > > +
> > > +    if (enable_timestamp_msg) {
> > > +        qemu_get_timestamp_str(&timestr);
> > > +        error_printf("%s ", timestr);
> > > +    }
> > >
> > >      error_print_loc();
> > >      va_start(ap, fmt);
> >
> > Does this print the timestamp to all kinds of monitors too? On stderr,
> > the timestamp is great. When printed to an "interactive monitor", it
> > could also help post-mortem debugging. But would it not confuse libvirt
> > eg.? (Apologies if this has been discussed before.)
> 
> I will try to add timestamp to monitor_printf().
> (In the long term, I would like to add it to all fprintf() in qemu.)

I tried to add timestamp to monitor_printf().
But, it wasn't easier than I expected.
(At least, we should not add it to monitor_printf() in readline.c.)
We need to discuss which message of monitor_printf() has to be
added timestamp.

Therefore, I would like to forcus on error_report() in this thread.
(I posted patch v5 just now.)

Seiji