| Message ID | 51D1D04F.3010201@hds.com |
|---|---|
| State | New |
| Headers | show |
On 07/01/13 20:54, 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 > v4 -> v5 > - Use sizeof() to define TIMESTAMP_LEN. > - 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. Reviewed-by: Laszlo Ersek <lersek@redhat.com> Since you plan to post followup patches, please at that time include a one-liner modification: the STEXI-ETEXI section in "qemu-options.hx" still says (right before ETEXI) "(disabled by default)". I think it should be fixed in a followup, not by posting v6. Thanks! Laszlo
On Mon, Jul 01, 2013 at 02:54:07PM -0400, Seiji Aguchi wrote: > diff --git a/qemu-options.hx b/qemu-options.hx > index ca6fdf6..a6dac1a 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" > + " change the format of messages\n" > + " timestamp=on|off enables leading timestamps (default:on)\n", > + QEMU_ARCH_ALL) > +STEXI > +@item -msg timestamp=on|off > +@findex -msg > +prepend a timestamp to each log message. > +(disabled by default) > +ETEXI I am confused. If the user specifies -msg then enable_timestamp_msg is on by default. If the user does not specify -msg then enable_timestmap_msg is off. Did I get that right? This means that the default behavior of QEMU does not change but you can add -msg to enable timestamps. I'm happy with this but find the documentation confusing. > diff --git a/util/qemu-time.c b/util/qemu-time.c > new file mode 100644 > index 0000000..3862788 > --- /dev/null > +++ b/util/qemu-time.c > @@ -0,0 +1,26 @@ > +/* > + * 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, size_t len) > +{ > + GTimeVal tv; > + gchar *tmp_str = NULL; > + > + /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */ > + assert(len >= TIMESTAMP_LEN); > + > + g_get_current_time(&tv); > + tmp_str = g_time_val_to_iso8601(&tv); > + g_strlcpy((gchar *)timestr, tmp_str, len); > + g_free(tmp_str); > +} Why strcpy into a fixed-size buffer when glib gives us a heap-allocated string? This patch would be simpler by dropping qemu-time.c/time.h and simply doing: if (enable_timestamp_msg) { GTimeVal tv; gchar *timestamp; g_get_current_time(&tv); timestamp = g_time_val_to_iso8601(&tv); error_printf("%s ", timestamp); g_free(timestamp); }
> > +DEF("msg", HAS_ARG, QEMU_OPTION_msg, > > + "-msg [timestamp=on|off]\n" > > + " change the format of messages\n" > > + " timestamp=on|off enables leading timestamps (default:on)\n", > > + QEMU_ARCH_ALL) > > +STEXI > > +@item -msg timestamp=on|off > > +@findex -msg > > +prepend a timestamp to each log message. > > +(disabled by default) > > +ETEXI > > I am confused. If the user specifies -msg then enable_timestamp_msg is > on by default. If the user does not specify -msg then > enable_timestmap_msg is off. Did I get that right? Yes. > > This means that the default behavior of QEMU does not change but you can > add -msg to enable timestamps. > > I'm happy with this but find the documentation confusing. I can remove "(disabled by default)" if needed. > > > diff --git a/util/qemu-time.c b/util/qemu-time.c > > new file mode 100644 > > index 0000000..3862788 > > --- /dev/null > > +++ b/util/qemu-time.c > > @@ -0,0 +1,26 @@ > > +/* > > + * 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, size_t len) > > +{ > > + GTimeVal tv; > > + gchar *tmp_str = NULL; > > + > > + /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */ > > + assert(len >= TIMESTAMP_LEN); > > + > > + g_get_current_time(&tv); > > + tmp_str = g_time_val_to_iso8601(&tv); > > + g_strlcpy((gchar *)timestr, tmp_str, len); > > + g_free(tmp_str); > > +} > > Why strcpy into a fixed-size buffer when glib gives us a heap-allocated > string? > > This patch would be simpler by dropping qemu-time.c/time.h I plan to introduce timestamp to monitor_printf() and fprintf() near future. In this case, it is better from a maintenance POV to keep time-handling functionality in a file that's separate from the qemu error file, so it can be reused elsewhere in QEMU if needed. It is suggested by Daniel. http://marc.info/?l=qemu-devel&m=136741113218944&w=2 > and simply > doing: > > if (enable_timestamp_msg) { > GTimeVal tv; > gchar *timestamp; > > g_get_current_time(&tv); > timestamp = g_time_val_to_iso8601(&tv); > error_printf("%s ", timestamp); > g_free(timestamp); I'm concerned that we may have potential memory leak If someone neglect to call the g_free(). That is why I use the fixed-size buffer. Seiji
On Tue, Jul 02, 2013 at 02:09:24PM +0000, Seiji Aguchi wrote: > > > diff --git a/util/qemu-time.c b/util/qemu-time.c > > > new file mode 100644 > > > index 0000000..3862788 > > > --- /dev/null > > > +++ b/util/qemu-time.c > > > @@ -0,0 +1,26 @@ > > > +/* > > > + * 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, size_t len) > > > +{ > > > + GTimeVal tv; > > > + gchar *tmp_str = NULL; > > > + > > > + /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */ > > > + assert(len >= TIMESTAMP_LEN); > > > + > > > + g_get_current_time(&tv); > > > + tmp_str = g_time_val_to_iso8601(&tv); > > > + g_strlcpy((gchar *)timestr, tmp_str, len); > > > + g_free(tmp_str); > > > +} > > > > Why strcpy into a fixed-size buffer when glib gives us a heap-allocated > > string? > > > > This patch would be simpler by dropping qemu-time.c/time.h > > I plan to introduce timestamp to monitor_printf() and fprintf() > near future. > > In this case, it is better from a maintenance POV to keep time-handling > functionality in a file that's separate from the qemu error file, so it can be reused > elsewhere in QEMU if needed. > > It is suggested by Daniel. > http://marc.info/?l=qemu-devel&m=136741113218944&w=2 Daniel's statement was about the code you copied from libvirt. It was not about using the glib function, which simplifies things greatly and avoids the need for a test suite. Patches need to make sense today, please do not add extra code with potential future use in mind: 1. Other developers must be able to read and modify the current codebase on its own. They do not know what potential future changes you were thinking about. 2. You may never end up submitting or getting the future stuff upstream. Then we'd be left with extra layers that are never used. Stefan
On Tue, Jul 02, 2013 at 02:09:24PM +0000, Seiji Aguchi wrote: > > > > > +DEF("msg", HAS_ARG, QEMU_OPTION_msg, > > > + "-msg [timestamp=on|off]\n" > > > + " change the format of messages\n" > > > + " timestamp=on|off enables leading timestamps (default:on)\n", > > > + QEMU_ARCH_ALL) > > > +STEXI > > > +@item -msg timestamp=on|off > > > +@findex -msg > > > +prepend a timestamp to each log message. > > > +(disabled by default) > > > +ETEXI > > > > I am confused. If the user specifies -msg then enable_timestamp_msg is > > on by default. If the user does not specify -msg then > > enable_timestmap_msg is off. Did I get that right? > > Yes. > > > > > This means that the default behavior of QEMU does not change but you can > > add -msg to enable timestamps. > > > > I'm happy with this but find the documentation confusing. > > I can remove "(disabled by default)" if needed. Perhaps the simplest solution is timestamp=off by default. Then there can be no confusion and users must do -msg timestamp=on to enable timestamps. If you really want to keep -msg as a shortcut for -msg timestamp=on, then please document explicitly that: 1. Without -msg timestamps are off. 1. With -msg timestamps are on. 2. -msg timestamp=off can be used to turn timestamps off again. Stefan
> Patches need to make sense today, please do not add extra code with > potential future use in mind: > > 1. Other developers must be able to read and modify the current codebase > on its own. They do not know what potential future changes you were > thinking about. > > 2. You may never end up submitting or getting the future stuff upstream. > Then we'd be left with extra layers that are never used. I understand what you are concerned. I will remove utils/qemu-time.c and its header file. > Daniel's statement was about the code you copied from libvirt. It was > not about using the glib function, which simplifies things greatly and > avoids the need for a test suite. Honestly, I still think it is reasonable to introduce the common time-handling functionality. You seem to say that using the glib function is simple, so we don't need to introduce the common functionality. However, "commonly useful" is not related whether it is simple or not. I'm concerned that we may duplicate same code by "focusing on today too much". But, I don't stick to my opinion on this patch. Seiji
> -----Original Message----- > From: Stefan Hajnoczi [mailto:stefanha@gmail.com] > Sent: Wednesday, July 03, 2013 5:14 AM > To: Seiji Aguchi > Cc: qemu-devel@nongnu.org; aliguori@us.ibm.com; berrange@redhat.com; kwolf@redhat.com; mtosatti@redhat.com; > armbru@redhat.com; Tomoki Sekiyama; pbonzini@redhat.com; lcapitulino@redhat.com; lersek@redhat.com; eblake@redhat.com; > dle-develop@lists.sourceforge.net > Subject: Re: [PATCH v5] Add timestamp to error_report() > > On Tue, Jul 02, 2013 at 02:09:24PM +0000, Seiji Aguchi wrote: > > > > > > > > +DEF("msg", HAS_ARG, QEMU_OPTION_msg, > > > > + "-msg [timestamp=on|off]\n" > > > > + " change the format of messages\n" > > > > + " timestamp=on|off enables leading timestamps (default:on)\n", > > > > + QEMU_ARCH_ALL) > > > > +STEXI > > > > +@item -msg timestamp=on|off > > > > +@findex -msg > > > > +prepend a timestamp to each log message. > > > > +(disabled by default) > > > > +ETEXI > > > > > > I am confused. If the user specifies -msg then enable_timestamp_msg is > > > on by default. If the user does not specify -msg then > > > enable_timestmap_msg is off. Did I get that right? > > > > Yes. > > > > > > > > This means that the default behavior of QEMU does not change but you can > > > add -msg to enable timestamps. > > > > > > I'm happy with this but find the documentation confusing. > > > > I can remove "(disabled by default)" if needed. > > Perhaps the simplest solution is timestamp=off by default. Then there > can be no confusion and users must do -msg timestamp=on to enable > timestamps. > > If you really want to keep -msg as a shortcut for -msg timestamp=on, > then please document explicitly that: > 1. Without -msg timestamps are off. > 1. With -msg timestamps are on. > 2. -msg timestamp=off can be used to turn timestamps off again. My apologies for the confusion. The syntax, "-msg [timestamp=on|off]", was wrong. "-msg timestamp[=on|off]" is correct. And there is no way to make "timestamp" optional, as far as I looked into a source code. Therefore, the explanation should be as below. (I think it is reasonable to keep "-msg timestamp" as a shortcut for -msg timestamp=on.) <snip> +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 <snip> To be simpler, we may be able to introduce just a single -msg-timestamp. But I think current "-msg timestamp[=on|off]" is reasonable because other options may be introduced to msg, like log_level or debug. Seiji
On Thu, Jul 04, 2013 at 02:57:13AM +0000, Seiji Aguchi wrote: > > > > -----Original Message----- > > From: Stefan Hajnoczi [mailto:stefanha@gmail.com] > > Sent: Wednesday, July 03, 2013 5:14 AM > > To: Seiji Aguchi > > Cc: qemu-devel@nongnu.org; aliguori@us.ibm.com; berrange@redhat.com; kwolf@redhat.com; mtosatti@redhat.com; > > armbru@redhat.com; Tomoki Sekiyama; pbonzini@redhat.com; lcapitulino@redhat.com; lersek@redhat.com; eblake@redhat.com; > > dle-develop@lists.sourceforge.net > > Subject: Re: [PATCH v5] Add timestamp to error_report() > > > > On Tue, Jul 02, 2013 at 02:09:24PM +0000, Seiji Aguchi wrote: > > > > > > > > > > > +DEF("msg", HAS_ARG, QEMU_OPTION_msg, > > > > > + "-msg [timestamp=on|off]\n" > > > > > + " change the format of messages\n" > > > > > + " timestamp=on|off enables leading timestamps (default:on)\n", > > > > > + QEMU_ARCH_ALL) > > > > > +STEXI > > > > > +@item -msg timestamp=on|off > > > > > +@findex -msg > > > > > +prepend a timestamp to each log message. > > > > > +(disabled by default) > > > > > +ETEXI > > > > > > > > I am confused. If the user specifies -msg then enable_timestamp_msg is > > > > on by default. If the user does not specify -msg then > > > > enable_timestmap_msg is off. Did I get that right? > > > > > > Yes. > > > > > > > > > > > This means that the default behavior of QEMU does not change but you can > > > > add -msg to enable timestamps. > > > > > > > > I'm happy with this but find the documentation confusing. > > > > > > I can remove "(disabled by default)" if needed. > > > > Perhaps the simplest solution is timestamp=off by default. Then there > > can be no confusion and users must do -msg timestamp=on to enable > > timestamps. > > > > If you really want to keep -msg as a shortcut for -msg timestamp=on, > > then please document explicitly that: > > 1. Without -msg timestamps are off. > > 1. With -msg timestamps are on. > > 2. -msg timestamp=off can be used to turn timestamps off again. > > My apologies for the confusion. > > The syntax, "-msg [timestamp=on|off]", was wrong. > "-msg timestamp[=on|off]" is correct. > > And there is no way to make "timestamp" optional, as far as I looked into a source code. > Therefore, the explanation should be as below. > (I think it is reasonable to keep "-msg timestamp" as a shortcut for -msg timestamp=on.) Yes, I think you are correct. I thought previously that "-msg" works but it seems an option is always required. > <snip> > +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 > <snip> > > To be simpler, we may be able to introduce just a single -msg-timestamp. > But I think current "-msg timestamp[=on|off]" is reasonable > because other options may be introduced to msg, like log_level or debug. Yep. Stefan
diff --git a/include/qemu/time.h b/include/qemu/time.h new file mode 100644 index 0000000..ce3903e --- /dev/null +++ b/include/qemu/time.h @@ -0,0 +1,10 @@ +#ifndef QEMU_TIME_H +#define QEMU_TIME_H + +#include "qemu-common.h" + +#define TIMESTAMP_LEN sizeof("1970-01-01T00:00:00.999999Z") +extern void qemu_get_timestamp_str(char *, size_t); +extern bool enable_timestamp_msg; + +#endif /* QEMU_TIME_H */ diff --git a/qemu-options.hx b/qemu-options.hx index ca6fdf6..a6dac1a 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" + " change the format of messages\n" + " timestamp=on|off enables leading timestamps (default:on)\n", + QEMU_ARCH_ALL) +STEXI +@item -msg timestamp=on|off +@findex -msg +prepend a timestamp to each log message. +(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..c65fdfd 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, sizeof(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..3862788 --- /dev/null +++ b/util/qemu-time.c @@ -0,0 +1,26 @@ +/* + * 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, size_t len) +{ + GTimeVal tv; + gchar *tmp_str = NULL; + + /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */ + assert(len >= TIMESTAMP_LEN); + + g_get_current_time(&tv); + tmp_str = g_time_val_to_iso8601(&tv); + g_strlcpy((gchar *)timestr, tmp_str, len); + g_free(tmp_str); +} 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); }
[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 v4 -> v5 - Use sizeof() to define TIMESTAMP_LEN. - 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/time.h | 10 ++++++++++ qemu-options.hx | 12 ++++++++++++ util/Makefile.objs | 1 + util/qemu-error.c | 8 ++++++++ util/qemu-time.c | 26 ++++++++++++++++++++++++++ vl.c | 28 ++++++++++++++++++++++++++++ 6 files changed, 85 insertions(+), 0 deletions(-) create mode 100644 include/qemu/time.h create mode 100644 util/qemu-time.c -- 1.7.1