qemu-devel
[Top][All Lists]
Advanced

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

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


From: Laszlo Ersek
Subject: Re: [Qemu-devel] [PATCH v4] Add timestamp to error message
Date: Thu, 27 Jun 2013 12:21:20 +0200
User-agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130513 Thunderbird/17.0.6

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 <address@hidden>
> ---
> 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
> address@hidden -msg timestamp=on|off
> address@hidden - 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 <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);

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



reply via email to

[Prev in Thread] Current Thread [Next in Thread]