diff mbox

[RFC,v2] Add timestamp to error message

Message ID 1367265445-27365-1-git-send-email-saguchi@redhat.com
State New
Headers show

Commit Message

Seiji Aguchi April 29, 2013, 7:57 p.m. UTC 
From: Seiji Aguchi <seiji.aguchi@hds.com>

[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]
This patch adds a timestamp to qemu's error message logged by
error_report().

A logic calculating a time is copied from libvirt, src/util/virtime.c.
* http://libvirt.org/git/?p=libvirt.git;a=commit;h=3ec128989606278635a7c5dfbeee959692d12e15

[TODO]
Add timestamp Messages with monitor_printf() and fprintf().

Signed-off-by: Seiji Aguchi <seiji.aguchi@hds.com>
---
Changelog v1 -> v2

 - add an option, -msg timestamp={on|off}, to enable output message with
   timestamp
---
 include/monitor/monitor.h |    2 +
 qemu-options.hx           |   12 ++++++
 util/qemu-error.c         |   93 +++++++++++++++++++++++++++++++++++++++++++++
 vl.c                      |   26 ++++++++++++
 4 files changed, 133 insertions(+), 0 deletions(-)

Comments

Stefan Hajnoczi May 1, 2013, 12:05 p.m. UTC | #1 
On Mon, Apr 29, 2013 at 03:57:25PM -0400, Seiji Aguchi wrote:
> diff --git a/util/qemu-error.c b/util/qemu-error.c
> index 08a36f4..35ef9ab 100644
> --- a/util/qemu-error.c
> +++ b/util/qemu-error.c
> @@ -196,6 +196,96 @@ void error_print_loc(void)
>      }
>  }
>  
> +
> +#define SECS_PER_HOUR   (60 * 60)
> +#define SECS_PER_DAY    (SECS_PER_HOUR * 24)
> +#define DIV(a, b) ((a) / (b) - ((a) % (b) < 0))
> +#define LEAPS_THRU_END_OF(y) (DIV(y, 4) - DIV(y, 100) + DIV(y, 400))
> +
> +const unsigned short int __mon_yday[2][13] = {
> +    /* Normal years.  */
> +    { 0, 31, 59, 90, 120, 151, 181, 212, 243, 273, 304, 334, 365 },
> +    /* Leap years.  */
> +    { 0, 31, 60, 91, 121, 152, 182, 213, 244, 274, 305, 335, 366 }
> +};
> +
> +#define is_leap_year(y) \
> +    ((y) % 4 == 0 && ((y) % 100 != 0 || (y) % 400 == 0))
> +
> +static void error_print_timestamp(void)
> +{
> +    struct timespec ts;
> +    unsigned long long now;
> +
> +    struct tm fields;
> +    long int days, rem, y;
> +    const unsigned short int *ip;
> +    unsigned long long whenSecs;
> +    unsigned int offset = 0; /* We hardcoded GMT */
> +
> +    if (clock_gettime(CLOCK_REALTIME, &ts) < 0) {
> +        return;
> +    }
> +
> +    now = (ts.tv_sec * 1000ull) + (ts.tv_nsec / (1000ull * 1000ull));
> +    /* This code is taken from GLibC under terms of LGPLv2+ */
> +
> +    whenSecs = now / 1000ull;
> +
> +    days = whenSecs / SECS_PER_DAY;
> +    rem = whenSecs % SECS_PER_DAY;
> +    rem += offset;
> +    while (rem < 0) {
> +        rem += SECS_PER_DAY;
> +        --days;
> +    }
> +    while (rem >= SECS_PER_DAY) {
> +        rem -= SECS_PER_DAY;
> +        ++days;
> +    }
> +    fields.tm_hour = rem / SECS_PER_HOUR;
> +    rem %= SECS_PER_HOUR;
> +    fields.tm_min = rem / 60;
> +    fields.tm_sec = rem % 60;
> +    /* January 1, 1970 was a Thursday.  */
> +    fields.tm_wday = (4 + days) % 7;
> +    if (fields.tm_wday < 0) {
> +        fields.tm_wday += 7;
> +    }
> +    y = 1970;
> +
> +    while (days < 0 || days >= (is_leap_year(y) ? 366 : 365)) {
> +        /* Guess a corrected year, assuming 365 days per year.  */
> +        long int yg = y + days / 365 - (days % 365 < 0);
> +
> +      /* Adjust DAYS and Y to match the guessed year.  */
> +      days -= ((yg - y) * 365
> +               + LEAPS_THRU_END_OF(yg - 1)
> +               - LEAPS_THRU_END_OF(y - 1));
> +      y = yg;
> +    }
> +    fields.tm_year = y - 1900;
> +
> +    fields.tm_yday = days;
> +    ip = __mon_yday[is_leap_year(y)];
> +    for (y = 11; days < (long int) ip[y]; --y) {
> +        continue;
> +    }
> +
> +    days -= ip[y];
> +    fields.tm_mon = y;
> +    fields.tm_mday = days + 1;
> +
> +    error_printf(
> +           "%4d-%02d-%02d %02d:%02d:%02d.%03lld+0000 ",
> +           fields.tm_year + 1900, fields.tm_mon + 1, fields.tm_mday,
> +           fields.tm_hour, fields.tm_min, fields.tm_sec,
> +           now % 1000);

Can strftime(3) be used instead of copying code from glibc?
Eric Blake May 1, 2013, 12:16 p.m. UTC | #2 
On 05/01/2013 06:05 AM, Stefan Hajnoczi wrote:

>> +    error_printf(
>> +           "%4d-%02d-%02d %02d:%02d:%02d.%03lld+0000 ",
>> +           fields.tm_year + 1900, fields.tm_mon + 1, fields.tm_mday,
>> +           fields.tm_hour, fields.tm_min, fields.tm_sec,
>> +           now % 1000);
> 
> Can strftime(3) be used instead of copying code from glibc?

No, because glibc's strftime() is not async-signal safe, and therefore
is not safe to call between fork() and exec() (libvirt hit actual
deadlocks[1] where a child was blocked on a mutex associated with
time-related functions that happened to be held by another parent
thread, but where the fork nuked that other thread so the mutex would
never clear).  This code is copied from libvirt, which copied the
no-lock-needed safe portions of glibc for a reason.

[1] https://www.redhat.com/archives/libvir-list/2011-November/msg01609.html
Daniel P. Berrangé May 1, 2013, 12:25 p.m. UTC | #3 
On Wed, May 01, 2013 at 06:16:33AM -0600, Eric Blake wrote:
> On 05/01/2013 06:05 AM, Stefan Hajnoczi wrote:
> 
> >> +    error_printf(
> >> +           "%4d-%02d-%02d %02d:%02d:%02d.%03lld+0000 ",
> >> +           fields.tm_year + 1900, fields.tm_mon + 1, fields.tm_mday,
> >> +           fields.tm_hour, fields.tm_min, fields.tm_sec,
> >> +           now % 1000);
> > 
> > Can strftime(3) be used instead of copying code from glibc?
> 
> No, because glibc's strftime() is not async-signal safe, and therefore
> is not safe to call between fork() and exec() (libvirt hit actual
> deadlocks[1] where a child was blocked on a mutex associated with
> time-related functions that happened to be held by another parent
> thread, but where the fork nuked that other thread so the mutex would
> never clear).  This code is copied from libvirt, which copied the
> no-lock-needed safe portions of glibc for a reason.
> 
> [1] https://www.redhat.com/archives/libvir-list/2011-November/msg01609.html

NB the original libvirt code had this & other related functions in
a standalone file, along with a significant test suite. I think it
is better from a maintenence POV to keep this functionality in a
file that's separate from the qemu error file, so it can be reused
elsewhere in QEMU if needed. It should also copy the test suite,
since it is bad practice to throw away tests which already exist.

Daniel
Anthony Liguori May 1, 2013, 2:26 p.m. UTC | #4 
"Daniel P. Berrange" <berrange@redhat.com> writes:

> On Wed, May 01, 2013 at 06:16:33AM -0600, Eric Blake wrote:
>> On 05/01/2013 06:05 AM, Stefan Hajnoczi wrote:
>> 
>> >> +    error_printf(
>> >> +           "%4d-%02d-%02d %02d:%02d:%02d.%03lld+0000 ",
>> >> +           fields.tm_year + 1900, fields.tm_mon + 1, fields.tm_mday,
>> >> +           fields.tm_hour, fields.tm_min, fields.tm_sec,
>> >> +           now % 1000);
>> > 
>> > Can strftime(3) be used instead of copying code from glibc?
>> 
>> No, because glibc's strftime() is not async-signal safe, and therefore
>> is not safe to call between fork() and exec() (libvirt hit actual
>> deadlocks[1] where a child was blocked on a mutex associated with
>> time-related functions that happened to be held by another parent
>> thread, but where the fork nuked that other thread so the mutex would
>> never clear).  This code is copied from libvirt, which copied the
>> no-lock-needed safe portions of glibc for a reason.
>> 
>> [1] https://www.redhat.com/archives/libvir-list/2011-November/msg01609.html
>
> NB the original libvirt code had this & other related functions in
> a standalone file, along with a significant test suite. I think it
> is better from a maintenence POV to keep this functionality in a
> file that's separate from the qemu error file, so it can be reused
> elsewhere in QEMU if needed. It should also copy the test suite,
> since it is bad practice to throw away tests which already exist.

I also don't buy that we can't use strftime.  There are very few places
where we use fork() in QEMU (it doesn't exist on Windows so it can't be
used without protection).  None of those places use the error reporting
infrastructure.

This code is also extremely naive.  It doesn't take into account leap
seconds and makes bad assumptions about leap years.

Regards,

Anthony Liguori

>
> Daniel
> -- 
> |: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
> |: http://libvirt.org              -o-             http://virt-manager.org :|
> |: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
> |: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|
Seiji Aguchi May 2, 2013, 8:39 p.m. UTC | #5 
Thank you for giving the comments.

I will separate this functionality from the qemu error file.

> I also don't buy that we can't use strftime.  There are very few places
> where we use fork() in QEMU (it doesn't exist on Windows so it can't be
> used without protection).  None of those places use the error reporting
> infrastructure.
> 
> This code is also extremely naive.  It doesn't take into account leap
> seconds and makes bad assumptions about leap years.

OK.
I will use strftime().

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 Anthony Liguori
> Sent: Wednesday, May 01, 2013 10:27 AM
> To: Daniel P. Berrange; Eric Blake
> Cc: kwolf@redhat.com; dle-develop@lists.sourceforge.net; Seiji Aguchi; stefanha@redhat.com; mst@redhat.com; Stefan Hajnoczi;
> mtosatti@redhat.com; qemu-devel@nongnu.org; armbru@redhat.com; av1474@comtv.ru; Tomoki Sekiyama; pbonzini@redhat.com;
> lcapitulino@redhat.com; Seiji Aguchi
> Subject: Re: [Qemu-devel] [RFC][PATCH v2]Add timestamp to error message
> 
> "Daniel P. Berrange" <berrange@redhat.com> writes:
> 
> > On Wed, May 01, 2013 at 06:16:33AM -0600, Eric Blake wrote:
> >> On 05/01/2013 06:05 AM, Stefan Hajnoczi wrote:
> >>
> >> >> +    error_printf(
> >> >> +           "%4d-%02d-%02d %02d:%02d:%02d.%03lld+0000 ",
> >> >> +           fields.tm_year + 1900, fields.tm_mon + 1, fields.tm_mday,
> >> >> +           fields.tm_hour, fields.tm_min, fields.tm_sec,
> >> >> +           now % 1000);
> >> >
> >> > Can strftime(3) be used instead of copying code from glibc?
> >>
> >> No, because glibc's strftime() is not async-signal safe, and therefore
> >> is not safe to call between fork() and exec() (libvirt hit actual
> >> deadlocks[1] where a child was blocked on a mutex associated with
> >> time-related functions that happened to be held by another parent
> >> thread, but where the fork nuked that other thread so the mutex would
> >> never clear).  This code is copied from libvirt, which copied the
> >> no-lock-needed safe portions of glibc for a reason.
> >>
> >> [1] https://www.redhat.com/archives/libvir-list/2011-November/msg01609.html
> >
> > NB the original libvirt code had this & other related functions in
> > a standalone file, along with a significant test suite. I think it
> > is better from a maintenence POV to keep this functionality in a
> > file that's separate from the qemu error file, so it can be reused
> > elsewhere in QEMU if needed. It should also copy the test suite,
> > since it is bad practice to throw away tests which already exist.
> 
> I also don't buy that we can't use strftime.  There are very few places
> where we use fork() in QEMU (it doesn't exist on Windows so it can't be
> used without protection).  None of those places use the error reporting
> infrastructure.
> 
> This code is also extremely naive.  It doesn't take into account leap
> seconds and makes bad assumptions about leap years.
> 
> Regards,
> 
> Anthony Liguori
> 
> >
> > Daniel
> > --
> > |: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
> > |: http://libvirt.org              -o-             http://virt-manager.org :|
> > |: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
> > |: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|
>
diff mbox

Patch

diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h
index b868760..6cbb0ff 100644
--- a/include/monitor/monitor.h
+++ b/include/monitor/monitor.h
@@ -99,4 +99,6 @@  int monitor_fdset_dup_fd_add(int64_t fdset_id, int dup_fd);
 int monitor_fdset_dup_fd_remove(int dup_fd);
 int monitor_fdset_dup_fd_find(int dup_fd);
 
+extern bool enable_timestamp_msg;
+
 #endif /* !MONITOR_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index e86cc24..a421261 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3097,3 +3097,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/qemu-error.c b/util/qemu-error.c
index 08a36f4..35ef9ab 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -196,6 +196,96 @@  void error_print_loc(void)
     }
 }
 
+
+#define SECS_PER_HOUR   (60 * 60)
+#define SECS_PER_DAY    (SECS_PER_HOUR * 24)
+#define DIV(a, b) ((a) / (b) - ((a) % (b) < 0))
+#define LEAPS_THRU_END_OF(y) (DIV(y, 4) - DIV(y, 100) + DIV(y, 400))
+
+const unsigned short int __mon_yday[2][13] = {
+    /* Normal years.  */
+    { 0, 31, 59, 90, 120, 151, 181, 212, 243, 273, 304, 334, 365 },
+    /* Leap years.  */
+    { 0, 31, 60, 91, 121, 152, 182, 213, 244, 274, 305, 335, 366 }
+};
+
+#define is_leap_year(y) \
+    ((y) % 4 == 0 && ((y) % 100 != 0 || (y) % 400 == 0))
+
+static void error_print_timestamp(void)
+{
+    struct timespec ts;
+    unsigned long long now;
+
+    struct tm fields;
+    long int days, rem, y;
+    const unsigned short int *ip;
+    unsigned long long whenSecs;
+    unsigned int offset = 0; /* We hardcoded GMT */
+
+    if (clock_gettime(CLOCK_REALTIME, &ts) < 0) {
+        return;
+    }
+
+    now = (ts.tv_sec * 1000ull) + (ts.tv_nsec / (1000ull * 1000ull));
+    /* This code is taken from GLibC under terms of LGPLv2+ */
+
+    whenSecs = now / 1000ull;
+
+    days = whenSecs / SECS_PER_DAY;
+    rem = whenSecs % SECS_PER_DAY;
+    rem += offset;
+    while (rem < 0) {
+        rem += SECS_PER_DAY;
+        --days;
+    }
+    while (rem >= SECS_PER_DAY) {
+        rem -= SECS_PER_DAY;
+        ++days;
+    }
+    fields.tm_hour = rem / SECS_PER_HOUR;
+    rem %= SECS_PER_HOUR;
+    fields.tm_min = rem / 60;
+    fields.tm_sec = rem % 60;
+    /* January 1, 1970 was a Thursday.  */
+    fields.tm_wday = (4 + days) % 7;
+    if (fields.tm_wday < 0) {
+        fields.tm_wday += 7;
+    }
+    y = 1970;
+
+    while (days < 0 || days >= (is_leap_year(y) ? 366 : 365)) {
+        /* Guess a corrected year, assuming 365 days per year.  */
+        long int yg = y + days / 365 - (days % 365 < 0);
+
+      /* Adjust DAYS and Y to match the guessed year.  */
+      days -= ((yg - y) * 365
+               + LEAPS_THRU_END_OF(yg - 1)
+               - LEAPS_THRU_END_OF(y - 1));
+      y = yg;
+    }
+    fields.tm_year = y - 1900;
+
+    fields.tm_yday = days;
+    ip = __mon_yday[is_leap_year(y)];
+    for (y = 11; days < (long int) ip[y]; --y) {
+        continue;
+    }
+
+    days -= ip[y];
+    fields.tm_mon = y;
+    fields.tm_mday = days + 1;
+
+    error_printf(
+           "%4d-%02d-%02d %02d:%02d:%02d.%03lld+0000 ",
+           fields.tm_year + 1900, fields.tm_mon + 1, fields.tm_mday,
+           fields.tm_hour, fields.tm_min, fields.tm_sec,
+           now % 1000);
+
+    return;
+}
+
+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
@@ -207,6 +297,9 @@  void error_report(const char *fmt, ...)
 {
     va_list ap;
 
+    if (enable_timestamp_msg) {
+        error_print_timestamp();
+    }
     error_print_loc();
     va_start(ap, fmt);
     error_vprintf(fmt, ap);
diff --git a/vl.c b/vl.c
index 6caa5f4..f1286a3 100644
--- a/vl.c
+++ b/vl.c
@@ -533,6 +533,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;
@@ -1446,6 +1458,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 */
 
@@ -2889,6 +2907,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();
 
@@ -3869,6 +3888,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);
             }