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

[Seiji Aguchi]

> Signed-off-by: Seiji Aguchi <address@hidden>

I used wrong email address to Signed-off-by.
Please ignore this patch.

Seiji

> -----Original Message-----
> From: address@hidden [mailto:address@hidden
> On Behalf Of Seiji Aguchi
> Sent: Wednesday, June 26, 2013 6:21 PM
> To: address@hidden
> Cc: address@hidden; address@hidden; Tomoki Sekiyama; address@hidden; 
> address@hidden; address@hidden;
> address@hidden; address@hidden; address@hidden; address@hidden; 
> address@hidden;
> address@hidden
> Subject: [Qemu-devel] [PATCH v3] Add timestamp to error message
> 
> [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 <address@hidden>
> ---
> Changelog
>  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
> address@hidden -msg timestamp=on|off
> address@hidden - 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 <address@hidden>
> + *
> + * 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
>