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

[Luiz Capitulino <lcapitulino@redhat.com>]

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