| Message ID | 51CB6946.90903@hds.com |
|---|---|
| State | New |
| Headers | show |
> Signed-off-by: Seiji Aguchi <saguchi@redhat.com> I used wrong email address to Signed-off-by. Please ignore this patch. Seiji > -----Original Message----- > From: qemu-devel-bounces+seiji.aguchi=hds.com@nongnu.org [mailto:qemu-devel-bounces+seiji.aguchi=hds.com@nongnu.org] > On Behalf Of Seiji Aguchi > Sent: Wednesday, June 26, 2013 6:21 PM > To: qemu-devel@nongnu.org > Cc: kwolf@redhat.com; aliguori@us.ibm.com; Tomoki Sekiyama; mst@redhat.com; stefanha@gmail.com; mtosatti@redhat.com; > armbru@redhat.com; lcapitulino@redhat.com; dle-develop@lists.sourceforge.net; av1474@comtv.ru; stefanha@redhat.com; > pbonzini@redhat.com > 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 <saguchi@redhat.com> > --- > 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 > +@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(×tr); > + 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 >
On 06/26/2013 04:20 PM, 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. > > +#include "qemu-common.h" > + > +/* "1970-01-01T00:00:00.999999Z" + '\0' */ > +#define TIMESTAMP_LEN 28 Self-documenting constants are nicer: #define TIMESTAMP_LEN (sizeof("1970-01-01T00:00:00.999999Z")+1) > +extern void qemu_get_timestamp_str(char (*timestr)[]); Eww. I had a tough time parsing this signature. Isn't it the same as the more legible: extern void qemu_get_timestamp_str(char **timestr); Furthermore, isn't the idea that you DON'T want to return a malloc'd string, but require that the user pre-allocate storage that we write into (since malloc during a log message reporting OOM is liable to fail, but we still want the log to be best effort)? But then why do you need a pointer to an array? Wouldn't it be better as: extern void qemu_get_timestamp_str(char *timestr, size_t len) where len is the length of timestr, and where the comments document that len should be at least TIMESTAMP_LEN to avoid truncation (or even assert() if it is not)? > +++ 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) Did you test that the existing query-command-line-options QMP command will list this option (just making sure that libvirt will be able to know when to use this option).
Thank you for the review. > > +#include "qemu-common.h" > > + > > +/* "1970-01-01T00:00:00.999999Z" + '\0' */ > > +#define TIMESTAMP_LEN 28 > > Self-documenting constants are nicer: > > #define TIMESTAMP_LEN (sizeof("1970-01-01T00:00:00.999999Z")+1) I will fix it. > > extern void qemu_get_timestamp_str(char *timestr, size_t len) > > where len is the length of timestr, and where the comments document that > len should be at least TIMESTAMP_LEN to avoid truncation (or even > assert() if it is not)? I will fix as above. > > > +++ 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) > > Did you test that the existing query-command-line-options QMP command > will list this option (just making sure that libvirt will be able to > know when to use this option). I will test it in the next patch. Seiji > > -- > Eric Blake eblake redhat com +1-919-301-3266 > Libvirt virtualization library http://libvirt.org
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(×tr); + 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); }
[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 <saguchi@redhat.com> --- 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