[PATCHv2 0/2] log guest name and memory error type AO, AR for MCEs

[PATCHv2 0/2] log guest name and memory error type AO, AR for MCEs

[Mario Smarduch]

In a large VPC environment we want to log memory error occurrences
and log them with guest name and type - there are few use cases


- if VM crashes on AR mce inform the user about the reason and resolve the case
- if VM hangs notify the user to reboot and resume processing
- if VM continues to run let the user know, he/she maybe able to correlate
  to vm internal outage
- Rawhammer attacks - isolate/determine the attacker possible migrating it off
  the hypervisor
- In general track memory errors on a hyperviosr over time to determine trends

Monitoring our fleet we come across quite a few of these and been
able to take action where before there were no clues to the causes.

When memory error occurs we get a log entry in qemu log:

Guest [Droplet-12345678] 2019-08-02T05:00:11.940270Z qemu-system-x86_64:
Guest MCE Memory Error at QEMU addr 0x7f3c7622f000 and GUEST 0x78e42f000
addr of type BUS_MCEERR_AR injected

with enterprise logging environment we can to take further actions.

v1 -> v2:
- split into two patches one to get the gustname second to log MCEs 
- addressed comments for MCE logging

Mario Smarduch (2):
  util/qemu-error: add guest name helper with -msg options
  target/i386: log MCE guest and host addresses

 include/qemu/error-report.h |  1 +
 qemu-options.hx             | 10 ++++++----
 target/i386/kvm.c           | 29 ++++++++++++++++++++++++-----
 util/qemu-error.c           | 31 +++++++++++++++++++++++++++++++
 vl.c                        |  5 +++++
 5 files changed, 67 insertions(+), 9 deletions(-)

-- 
2.9.3

[PATCHv2 1/2] util/qemu-error: add guest name helper with -msg options

[Mario Smarduch]

This patch adds an option to enable/disable printing lead guest name in
logging messages.

A '-msg name=on|off' allows to turn on, off guest name logging.

If guest name is not set disabling this makes sense.

Verified with all combinations of 
  '-msg timestamp=yes|no,name=yes|no.

Signed-off-by: Mario Smarduch <msmarduch@digitalocean.com>
---
 include/qemu/error-report.h |  1 +
 qemu-options.hx             | 10 ++++++----
 util/qemu-error.c           | 31 +++++++++++++++++++++++++++++++
 vl.c                        |  5 +++++
 4 files changed, 43 insertions(+), 4 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 00d069b..9b44a06 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -74,5 +74,6 @@ void error_init(const char *argv0);
 
 const char *error_get_progname(void);
 extern bool enable_timestamp_msg;
+extern bool enable_guestname_msg;
 
 #endif
diff --git a/qemu-options.hx b/qemu-options.hx
index 2a04ca6..6066001 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -4164,14 +4164,16 @@ HXCOMM Deprecated by -accel tcg
 DEF("no-kvm", 0, QEMU_OPTION_no_kvm, "", QEMU_ARCH_I386)
 
 DEF("msg", HAS_ARG, QEMU_OPTION_msg,
-    "-msg timestamp[=on|off]\n"
+    "-msg [timestamp=on|off][name=on|off]\n"
     "                change the format of messages\n"
-    "                on|off controls leading timestamps (default:on)\n",
+    "                timestamp=on|off controls leading timestamps (default: on)\n"
+    "                name=on|off controls leading guest name (default: off)\n",
     QEMU_ARCH_ALL)
 STEXI
-@item -msg timestamp[=on|off]
+@item -msg timestamp=on|off
+@item -msg name=on|off
 @findex -msg
-prepend a timestamp to each log message.(default:on)
+Prepend additional information to each log message
 ETEXI
 
 DEF("dump-vmstate", HAS_ARG, QEMU_OPTION_dump_vmstate,
diff --git a/util/qemu-error.c b/util/qemu-error.c
index f373f3b..8ece7b2 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -11,6 +11,8 @@
  */
 
 #include "qemu/osdep.h"
+#include "qemu/option.h"
+#include "qemu/config-file.h"
 #include "monitor/monitor.h"
 #include "qemu/error-report.h"
 
@@ -192,6 +194,8 @@ static void print_loc(void)
 }
 
 bool enable_timestamp_msg;
+bool enable_guestname_msg;
+
 /*
  * Print a message to current monitor if we have one, else to stderr.
  * @report_type is the type of message: error, warning or informational.
@@ -228,6 +232,27 @@ static void vreport(report_type type, const char *fmt, va_list ap)
     error_printf("\n");
 }
 
+static const char *error_get_guestname(void)
+{
+    QemuOpts *opts = qemu_opts_find(qemu_find_opts("name"), NULL);
+    return qemu_opt_get(opts, "guest");
+}
+
+/*
+ * Also print the guest name, handy if we log to a server.
+ */
+static void error_print_guestname(void)
+{
+    const char *name;
+
+    if (enable_guestname_msg) {
+        name = error_get_guestname();
+        if (name && !cur_mon) {
+            error_printf("Guest [%s] ", name);
+        }
+    }
+}
+
 /*
  * Print an error message to current monitor if we have one, else to stderr.
  * Format arguments like vsprintf().  The resulting message should be
@@ -237,6 +262,7 @@ static void vreport(report_type type, const char *fmt, va_list ap)
  */
 void error_vreport(const char *fmt, va_list ap)
 {
+    error_print_guestname();
     vreport(REPORT_TYPE_ERROR, fmt, ap);
 }
 
@@ -248,6 +274,7 @@ void error_vreport(const char *fmt, va_list ap)
  */
 void warn_vreport(const char *fmt, va_list ap)
 {
+    error_print_guestname();
     vreport(REPORT_TYPE_WARNING, fmt, ap);
 }
 
@@ -274,6 +301,7 @@ void error_report(const char *fmt, ...)
 {
     va_list ap;
 
+    error_print_guestname();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_ERROR, fmt, ap);
     va_end(ap);
@@ -289,6 +317,7 @@ void warn_report(const char *fmt, ...)
 {
     va_list ap;
 
+    error_print_guestname();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_WARNING, fmt, ap);
     va_end(ap);
@@ -324,6 +353,7 @@ bool error_report_once_cond(bool *printed, const char *fmt, ...)
         return false;
     }
     *printed = true;
+    error_print_guestname();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_ERROR, fmt, ap);
     va_end(ap);
@@ -344,6 +374,7 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...)
         return false;
     }
     *printed = true;
+    error_print_guestname();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_WARNING, fmt, ap);
     va_end(ap);
diff --git a/vl.c b/vl.c
index 002bf49..024bdc6 100644
--- a/vl.c
+++ b/vl.c
@@ -417,6 +417,10 @@ static QemuOptsList qemu_msg_opts = {
             .name = "timestamp",
             .type = QEMU_OPT_BOOL,
         },
+        {
+            .name = "name",
+            .type = QEMU_OPT_BOOL,
+        },
         { /* end of list */ }
     },
 };
@@ -1263,6 +1267,7 @@ static void realtime_init(void)
 static void configure_msg(QemuOpts *opts)
 {
     enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
+    enable_guestname_msg = qemu_opt_get_bool(opts, "name", false);
 }
 
 
-- 
2.9.3

Re: [PATCHv2 1/2] util/qemu-error: add guest name helper with -msg options

[Paolo Bonzini]

On 09/10/19 18:44, Mario Smarduch wrote:
>  };
> @@ -1263,6 +1267,7 @@ static void realtime_init(void)
>  static void configure_msg(QemuOpts *opts)
>  {
>      enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
> +    enable_guestname_msg = qemu_opt_get_bool(opts, "name", false);
>  }

Before, the msg option certainly had a timestamp suboption, but this
might not be the case now.  So that "true" needs to become "false".
I'll fix it up when applying.

Paolo

Re: [PATCHv2 1/2] util/qemu-error: add guest name helper with -msg options

[Markus Armbruster]

Paolo Bonzini <pbonzini@redhat.com> writes:

> On 09/10/19 18:44, Mario Smarduch wrote:
>>  };
>> @@ -1263,6 +1267,7 @@ static void realtime_init(void)
>>  static void configure_msg(QemuOpts *opts)
>>  {
>>      enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
>> +    enable_guestname_msg = qemu_opt_get_bool(opts, "name", false);
>>  }
>
> Before, the msg option certainly had a timestamp suboption, but this
> might not be the case now.  So that "true" needs to become "false".
> I'll fix it up when applying.

Hold your horses.

Before this patch, -msg "" enables timestamps.  If you apply it with
your fixup, it doesn't anymore.  I don't disagree with that change, but
it needs to be its own commit, with a proper explanation.

I have more comments on this patch.

Re: [PATCHv2 1/2] util/qemu-error: add guest name helper with -msg options

[Markus Armbruster]

I don't think merging this via qemu-trivial is a good idea.  First, it's
not sufficiently trivial, as we shall see below.  Second, the code in
question has a maintainer willing to review and merge patches: me.  I
can't always review as quickly as we all would like; sorry about that.

Mario Smarduch <msmarduch@digitalocean.com> writes:

> This patch adds an option to enable/disable printing lead guest name in
> logging messages.

Why is that useful?  Remember, the commit message is how you pitch your
patch to the maintainers :)

> A '-msg name=on|off' allows to turn on, off guest name logging.
>
> If guest name is not set disabling this makes sense.
>
> Verified with all combinations of 
>   '-msg timestamp=yes|no,name=yes|no.

Information on how you tested are welcome.  I'd put that ...

> Signed-off-by: Mario Smarduch <msmarduch@digitalocean.com>
> ---

... below the --- line, since there's no need to record it for
posterity.

>  include/qemu/error-report.h |  1 +
>  qemu-options.hx             | 10 ++++++----
>  util/qemu-error.c           | 31 +++++++++++++++++++++++++++++++
>  vl.c                        |  5 +++++
>  4 files changed, 43 insertions(+), 4 deletions(-)
>
> diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
> index 00d069b..9b44a06 100644
> --- a/include/qemu/error-report.h
> +++ b/include/qemu/error-report.h
> @@ -74,5 +74,6 @@ void error_init(const char *argv0);
>  
>  const char *error_get_progname(void);
>  extern bool enable_timestamp_msg;
> +extern bool enable_guestname_msg;
>  
>  #endif
> diff --git a/qemu-options.hx b/qemu-options.hx
> index 2a04ca6..6066001 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -4164,14 +4164,16 @@ HXCOMM Deprecated by -accel tcg
>  DEF("no-kvm", 0, QEMU_OPTION_no_kvm, "", QEMU_ARCH_I386)
>  
>  DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> -    "-msg timestamp[=on|off]\n"
> +    "-msg [timestamp=on|off][name=on|off]\n"

Name of what?  Let's call it "guest-name".

>      "                change the format of messages\n"
> -    "                on|off controls leading timestamps (default:on)\n",
> +    "                timestamp=on|off controls leading timestamps (default: on)\n"
> +    "                name=on|off controls leading guest name (default: off)\n",
>      QEMU_ARCH_ALL)
>  STEXI
> -@item -msg timestamp[=on|off]
> +@item -msg timestamp=on|off
> +@item -msg name=on|off
>  @findex -msg
> -prepend a timestamp to each log message.(default:on)
> +Prepend additional information to each log message
>  ETEXI

Preexisting: "log message" isn't quite right.  This isn't about logging,
it's about error messages.  Related to logging only because the software
layer above QEMU typically captures and logs them.

Your patch loses the explanation of what timestamp=on does, and its
default value.  Remember, this is the manual, and the text in DEF() is
*not* visible here.

It also incorrectly suggests you can have either timestamp or name, but
not both.

Better:

   STEXI
   @item -msg [guest-name[=on|off]][,timestamp[=on|off]]
   @findex -msg
   Control error message format.
   @table @option
   @item guest-name=on|off
   Prefix messages with the guest name.  Default is off.
   @item timestamp=on|off
   Prefix messages with a timestamp.  Default is off.
   @end table
   ETEXI

>  
>  DEF("dump-vmstate", HAS_ARG, QEMU_OPTION_dump_vmstate,
> diff --git a/util/qemu-error.c b/util/qemu-error.c
> index f373f3b..8ece7b2 100644
> --- a/util/qemu-error.c
> +++ b/util/qemu-error.c
> @@ -11,6 +11,8 @@
>   */
>  
>  #include "qemu/osdep.h"
> +#include "qemu/option.h"
> +#include "qemu/config-file.h"
>  #include "monitor/monitor.h"
>  #include "qemu/error-report.h"
>  
> @@ -192,6 +194,8 @@ static void print_loc(void)
>  }
>  
>  bool enable_timestamp_msg;
> +bool enable_guestname_msg;
> +
>  /*
>   * Print a message to current monitor if we have one, else to stderr.
>   * @report_type is the type of message: error, warning or informational.
> @@ -228,6 +232,27 @@ static void vreport(report_type type, const char *fmt, va_list ap)
>      error_printf("\n");
>  }
>  
> +static const char *error_get_guestname(void)
> +{
> +    QemuOpts *opts = qemu_opts_find(qemu_find_opts("name"), NULL);
> +    return qemu_opt_get(opts, "guest");
> +}
> +
> +/*
> + * Also print the guest name, handy if we log to a server.
> + */
> +static void error_print_guestname(void)
> +{
> +    const char *name;
> +
> +    if (enable_guestname_msg) {
> +        name = error_get_guestname();
> +        if (name && !cur_mon) {
> +            error_printf("Guest [%s] ", name);

Looks a bit ornate.  For instance:

    $ qemu-system-x86_64 -name frob --msg timestamp,name bad.img
    Guest [frob] 2019-10-10T07:13:15.135641Z qemu-system-x86_64: bad.img: Could not open 'bad.img': No such file or directory

Any particular reason for "Guest [%s] " instead of plain "%s "?

If the guest name is not set, -msg name=on gets silently ignored.
Shouldn't we reject it instead?

> +        }
> +    }
> +}
> +
>  /*
>   * Print an error message to current monitor if we have one, else to stderr.
>   * Format arguments like vsprintf().  The resulting message should be
> @@ -237,6 +262,7 @@ static void vreport(report_type type, const char *fmt, va_list ap)
>   */
>  void error_vreport(const char *fmt, va_list ap)
>  {
> +    error_print_guestname();
>      vreport(REPORT_TYPE_ERROR, fmt, ap);
>  }
>  
> @@ -248,6 +274,7 @@ void error_vreport(const char *fmt, va_list ap)
>   */
>  void warn_vreport(const char *fmt, va_list ap)
>  {
> +    error_print_guestname();
>      vreport(REPORT_TYPE_WARNING, fmt, ap);
>  }
>  
> @@ -274,6 +301,7 @@ void error_report(const char *fmt, ...)
>  {
>      va_list ap;
>  
> +    error_print_guestname();
>      va_start(ap, fmt);
>      vreport(REPORT_TYPE_ERROR, fmt, ap);
>      va_end(ap);
> @@ -289,6 +317,7 @@ void warn_report(const char *fmt, ...)
>  {
>      va_list ap;
>  
> +    error_print_guestname();
>      va_start(ap, fmt);
>      vreport(REPORT_TYPE_WARNING, fmt, ap);
>      va_end(ap);
> @@ -324,6 +353,7 @@ bool error_report_once_cond(bool *printed, const char *fmt, ...)
>          return false;
>      }
>      *printed = true;
> +    error_print_guestname();
>      va_start(ap, fmt);
>      vreport(REPORT_TYPE_ERROR, fmt, ap);
>      va_end(ap);
> @@ -344,6 +374,7 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...)
>          return false;
>      }
>      *printed = true;
> +    error_print_guestname();
>      va_start(ap, fmt);
>      vreport(REPORT_TYPE_WARNING, fmt, ap);
>      va_end(ap);

This doesn't look right.  What's wrong with printing the name right
where we already print the timestamp, in vreport()?

> diff --git a/vl.c b/vl.c
> index 002bf49..024bdc6 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -417,6 +417,10 @@ static QemuOptsList qemu_msg_opts = {
>              .name = "timestamp",
>              .type = QEMU_OPT_BOOL,
>          },
> +        {
> +            .name = "name",
> +            .type = QEMU_OPT_BOOL,
> +        },
>          { /* end of list */ }
>      },
>  };
> @@ -1263,6 +1267,7 @@ static void realtime_init(void)
>  static void configure_msg(QemuOpts *opts)
>  {
>      enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
> +    enable_guestname_msg = qemu_opt_get_bool(opts, "name", false);
>  }

We store -msg parameter "timestamp" in enable_timestamp_msg so vreport()
doesn't have to retrieve it all the time.

You do the same for parameter "name", but you still retrieve -name
parameter "guest" all the time.  Misses the point, I'm afraid :)

I append a revised patch to illustrate what I mean.


From 487d50757336125560a06141c4af2f565bdc3c16 Mon Sep 17 00:00:00 2001
From: Mario Smarduch <msmarduch@digitalocean.com>
Date: Wed, 9 Oct 2019 09:44:58 -0700
Subject: [RFC PATCH] error: New -msg guest-name to include guest name in
 messages

TODO why is that useful?

Looks like this:

    $ qemu-system-x86_64 --msg name=on,timestamp=on bad.img
    2019-10-10T08:02:45.905913Z qemu-system-x86_64: bad.img: Could not open 'bad.img': No such file or directory

Signed-off-by: Mario Smarduch <msmarduch@digitalocean.com>
Signed-off-by: Markus Armbruster <armbru@redhat.com>
---
 include/qemu/error-report.h |  1 +
 util/qemu-error.c           |  7 +++++++
 vl.c                        | 10 ++++++++++
 qemu-options.hx             |  7 +++++--
 4 files changed, 23 insertions(+), 2 deletions(-)

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 87532d8596..50b3587a05 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -74,6 +74,7 @@ void error_init(const char *argv0);
 
 const char *error_get_progname(void);
 
+extern const char *error_guest_name;
 extern bool error_with_timestamp;
 
 #endif
diff --git a/util/qemu-error.c b/util/qemu-error.c
index dac7c7dc50..c5d00d57d5 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -24,6 +24,9 @@ typedef enum {
     REPORT_TYPE_INFO,
 } report_type;
 
+/* Prepend guest name to messages */
+const char *error_guest_name;
+
 /* Prepend timestamp to messages */
 bool error_with_timestamp;
 
@@ -206,6 +209,10 @@ static void vreport(report_type type, const char *fmt, va_list ap)
     GTimeVal tv;
     gchar *timestr;
 
+    if (error_guest_name && !cur_mon) {
+        error_printf("%s ", error_guest_name);
+    }
+
     if (error_with_timestamp && !cur_mon) {
         g_get_current_time(&tv);
         timestr = g_time_val_to_iso8601(&tv);
diff --git a/vl.c b/vl.c
index b8e4c11f02..26974e2b79 100644
--- a/vl.c
+++ b/vl.c
@@ -417,6 +417,10 @@ static QemuOptsList qemu_msg_opts = {
             .name = "timestamp",
             .type = QEMU_OPT_BOOL,
         },
+        {
+            .name = "guest-name",
+            .type = QEMU_OPT_BOOL,
+        },
         { /* end of list */ }
     },
 };
@@ -1262,6 +1266,12 @@ static void realtime_init(void)
 
 static void configure_msg(QemuOpts *opts)
 {
+    if (qemu_opt_get_bool(opts, "guest-name", false)) {
+        error_guest_name = qemu_opt_get(qemu_opts_find(qemu_find_opts("name"),
+                                                       NULL),
+                                        "guest");
+    }
+
     error_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
 }
 
diff --git a/qemu-options.hx b/qemu-options.hx
index 158244da0f..6cd402db74 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -4164,15 +4164,18 @@ HXCOMM Deprecated by -accel tcg
 DEF("no-kvm", 0, QEMU_OPTION_no_kvm, "", QEMU_ARCH_I386)
 
 DEF("msg", HAS_ARG, QEMU_OPTION_msg,
-    "-msg timestamp[=on|off]\n"
+    "-msg [guest-name[=on|off]][,timestamp[=on|off]]\n"
     "                control error message format\n"
+    "                guest-name=on includes the guest name (default: off)\n"
     "                timestamp=on enables timestamps (default: off)\n",
     QEMU_ARCH_ALL)
 STEXI
-@item -msg timestamp[=on|off]
+@item -msg [guest-name[=on|off]][,timestamp[=on|off]]
 @findex -msg
 Control error message format.
 @table @option
+@item guest-name=on|off
+Prefix messages with the guest name.  Default is off.
 @item timestamp=on|off
 Prefix messages with a timestamp.  Default is off.
 @end table
-- 
2.21.0

Re: [PATCHv2 1/2] util/qemu-error: add guest name helper with -msg options

[Paolo Bonzini]

[Sorry Markus, I missed this message before]

On 10/10/19 10:16, Markus Armbruster wrote:
> I don't think merging this via qemu-trivial is a good idea.  First, it's
> not sufficiently trivial, as we shall see below.  Second, the code in
> question has a maintainer willing to review and merge patches: me.  I
> can't always review as quickly as we all would like; sorry about that.

Yes, it's not trivial indeed.

I think I can pick up v2 2/2 separately.  Since I had already started 
working on resolving conflicts before seeing your reply, I will leave
here my resulting patch, for Mario to pick up.

diff --git a/include/qemu/error-report.h b/include/qemu/error-report.h
index 87532d8596..4d3ee6f00c 100644
--- a/include/qemu/error-report.h
+++ b/include/qemu/error-report.h
@@ -75,5 +75,6 @@ void error_init(const char *argv0);
 const char *error_get_progname(void);
 
 extern bool error_with_timestamp;
+extern bool error_with_guest_name;
 
 #endif
diff --git a/qemu-options.hx b/qemu-options.hx
index 158244da0f..70a76069a6 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -4164,17 +4164,20 @@ HXCOMM Deprecated by -accel tcg
 DEF("no-kvm", 0, QEMU_OPTION_no_kvm, "", QEMU_ARCH_I386)
 
 DEF("msg", HAS_ARG, QEMU_OPTION_msg,
-    "-msg timestamp[=on|off]\n"
-    "                control error message format\n"
-    "                timestamp=on enables timestamps (default: off)\n",
+    "-msg [timestamp=on|off][,name=on|off]\n"
+    "                change the format of messages\n"
+    "                timestamp=on|off prepend timestamps (default: off)\n"
+    "                name=on|off prepend guest name (default: off)\n",
     QEMU_ARCH_ALL)
 STEXI
-@item -msg timestamp[=on|off]
+@item -msg
 @findex -msg
 Control error message format.
 @table @option
 @item timestamp=on|off
 Prefix messages with a timestamp.  Default is off.
+@item name=on|off
+Prefix messages with the name of the guest.  Default is off.
 @end table
 ETEXI
 
diff --git a/util/qemu-error.c b/util/qemu-error.c
index dac7c7dc50..497217298f 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -11,6 +11,8 @@
  */
 
 #include "qemu/osdep.h"
+#include "qemu/option.h"
+#include "qemu/config-file.h"
 #include "monitor/monitor.h"
 #include "qemu/error-report.h"
 
@@ -27,6 +29,9 @@ typedef enum {
 /* Prepend timestamp to messages */
 bool error_with_timestamp;
 
+/* Prepend guest name to messages */
+bool error_with_guest_name;
+
 int error_printf(const char *fmt, ...)
 {
     va_list ap;
@@ -230,6 +235,27 @@ static void vreport(report_type type, const char *fmt, va_list ap)
     error_printf("\n");
 }
 
+static const char *error_get_guest_name(void)
+{
+    QemuOpts *opts = qemu_opts_find(qemu_find_opts("name"), NULL);
+    return qemu_opt_get(opts, "guest");
+}
+
+/*
+ * Also print the guest name, handy if we log to a server.
+ */
+static void error_print_guest_name(void)
+{
+    const char *name;
+
+    if (error_with_guest_name) {
+        name = error_get_guest_name();
+        if (name && !cur_mon) {
+            error_printf("Guest [%s] ", name);
+        }
+    }
+}
+
 /*
  * Print an error message to current monitor if we have one, else to stderr.
  * Format arguments like vsprintf().  The resulting message should be
@@ -239,6 +265,7 @@ static void vreport(report_type type, const char *fmt, va_list ap)
  */
 void error_vreport(const char *fmt, va_list ap)
 {
+    error_print_guest_name();
     vreport(REPORT_TYPE_ERROR, fmt, ap);
 }
 
@@ -250,6 +277,7 @@ void error_vreport(const char *fmt, va_list ap)
  */
 void warn_vreport(const char *fmt, va_list ap)
 {
+    error_print_guest_name();
     vreport(REPORT_TYPE_WARNING, fmt, ap);
 }
 
@@ -276,6 +304,7 @@ void error_report(const char *fmt, ...)
 {
     va_list ap;
 
+    error_print_guest_name();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_ERROR, fmt, ap);
     va_end(ap);
@@ -291,6 +320,7 @@ void warn_report(const char *fmt, ...)
 {
     va_list ap;
 
+    error_print_guest_name();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_WARNING, fmt, ap);
     va_end(ap);
@@ -326,6 +356,7 @@ bool error_report_once_cond(bool *printed, const char *fmt, ...)
         return false;
     }
     *printed = true;
+    error_print_guest_name();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_ERROR, fmt, ap);
     va_end(ap);
@@ -346,6 +377,7 @@ bool warn_report_once_cond(bool *printed, const char *fmt, ...)
         return false;
     }
     *printed = true;
+    error_print_guest_name();
     va_start(ap, fmt);
     vreport(REPORT_TYPE_WARNING, fmt, ap);
     va_end(ap);
diff --git a/vl.c b/vl.c
index b8e4c11f02..b6f870f079 100644
--- a/vl.c
+++ b/vl.c
@@ -417,6 +417,10 @@ static QemuOptsList qemu_msg_opts = {
             .name = "timestamp",
             .type = QEMU_OPT_BOOL,
         },
+        {
+            .name = "name",
+            .type = QEMU_OPT_BOOL,
+        },
         { /* end of list */ }
     },
 };
@@ -1263,6 +1267,7 @@ static void realtime_init(void)
 static void configure_msg(QemuOpts *opts)
 {
     error_with_timestamp = qemu_opt_get_bool(opts, "timestamp", false);
+    error_with_guest_name = qemu_opt_get_bool(opts, "name", false);
 }
 
 
Paolo

[PATCHv2 2/2] target/i386: log MCE guest and host addresses

[Mario Smarduch]

Patch logs MCE AO, AR messages injected to guest or taken by QEMU itself.
We print the QEMU address for guest MCEs, helps on hypervisors that have
another source of MCE logging like mce log, and when they go missing.

For example we found these QEMU logs:

September 26th 2019, 17:36:02.309        Droplet-153258224: Guest MCE Memory Error at qemu addr 0x7f8ce14f5000 and guest 3d6f5000 addr of type BUS_MCEERR_AR injected   qemu-system-x86_64      amsN    ams3nodeNNNN

September 27th 2019, 06:25:03.234        Droplet-153258224: Guest MCE Memory Error at qemu addr 0x7f8ce14f5000 and guest 3d6f5000 addr of type BUS_MCEERR_AR injected   qemu-system-x86_64      amsN    ams3nodeNNNN

The first log had a corresponding mce log entry, the second didnt (logging
thresholds) we can infer from second entry same PA and mce type.

Signed-off-by: Mario Smarduch <msmarduch@digitalocean.com>
---
 target/i386/kvm.c | 29 ++++++++++++++++++++++++-----
 1 file changed, 24 insertions(+), 5 deletions(-)

diff --git a/target/i386/kvm.c b/target/i386/kvm.c
index 11b9c85..7eeefac 100644
--- a/target/i386/kvm.c
+++ b/target/i386/kvm.c
@@ -592,9 +592,9 @@ static void kvm_mce_inject(X86CPU *cpu, hwaddr paddr, int code)
                        (MCM_ADDR_PHYS << 6) | 0xc, flags);
 }
 
-static void hardware_memory_error(void)
+static void hardware_memory_error(void *host_addr)
 {
-    fprintf(stderr, "Hardware memory error!\n");
+    error_report("QEMU got Hardware memory error at addr %p", host_addr);
     exit(1);
 }
 
@@ -618,15 +618,34 @@ void kvm_arch_on_sigbus_vcpu(CPUState *c, int code, void *addr)
             kvm_physical_memory_addr_from_host(c->kvm_state, addr, &paddr)) {
             kvm_hwpoison_page_add(ram_addr);
             kvm_mce_inject(cpu, paddr, code);
+
+            /*
+             * Use different logging severity based on error type.
+             * If there is additional MCE reporting on the hypervisor, QEMU VA
+             * could be another source to identify the PA and MCE details.
+             */
+            if (code == BUS_MCEERR_AR) {
+                error_report("Guest MCE Memory Error at QEMU addr %p and "
+                    "GUEST addr 0x%" HWADDR_PRIx " of type %s injected",
+                    addr, paddr, "BUS_MCEERR_AR");
+            } else {
+                 warn_report("Guest MCE Memory Error at QEMU addr %p and "
+                     "GUEST addr 0x%" HWADDR_PRIx " of type %s injected",
+                     addr, paddr, "BUS_MCEERR_AO");
+            }
+
             return;
         }
 
-        fprintf(stderr, "Hardware memory error for memory used by "
-                "QEMU itself instead of guest system!\n");
+        if (code == BUS_MCEERR_AO) {
+            warn_report("Hardware memory error at addr %p of type %s "
+                "for memory used by QEMU itself instead of guest system!",
+                 addr, "BUS_MCEERR_AO");
+        }
     }
 
     if (code == BUS_MCEERR_AR) {
-        hardware_memory_error();
+        hardware_memory_error(addr);
     }
 
     /* Hope we are lucky for AO MCE */
-- 
2.9.3

Re: [PATCHv2 0/2] log guest name and memory error type AO, AR for MCEs

[Paolo Bonzini]

On 09/10/19 18:44, Mario Smarduch wrote:
> In a large VPC environment we want to log memory error occurrences
> and log them with guest name and type - there are few use cases
> 
> 
> - if VM crashes on AR mce inform the user about the reason and resolve the case
> - if VM hangs notify the user to reboot and resume processing
> - if VM continues to run let the user know, he/she maybe able to correlate
>   to vm internal outage
> - Rawhammer attacks - isolate/determine the attacker possible migrating it off
>   the hypervisor
> - In general track memory errors on a hyperviosr over time to determine trends
> 
> Monitoring our fleet we come across quite a few of these and been
> able to take action where before there were no clues to the causes.
> 
> When memory error occurs we get a log entry in qemu log:
> 
> Guest [Droplet-12345678] 2019-08-02T05:00:11.940270Z qemu-system-x86_64:
> Guest MCE Memory Error at QEMU addr 0x7f3c7622f000 and GUEST 0x78e42f000
> addr of type BUS_MCEERR_AR injected
> 
> with enterprise logging environment we can to take further actions.
> 
> v1 -> v2:
> - split into two patches one to get the gustname second to log MCEs 
> - addressed comments for MCE logging
> 
> Mario Smarduch (2):
>   util/qemu-error: add guest name helper with -msg options
>   target/i386: log MCE guest and host addresses
> 
>  include/qemu/error-report.h |  1 +
>  qemu-options.hx             | 10 ++++++----
>  target/i386/kvm.c           | 29 ++++++++++++++++++++++++-----
>  util/qemu-error.c           | 31 +++++++++++++++++++++++++++++++
>  vl.c                        |  5 +++++
>  5 files changed, 67 insertions(+), 9 deletions(-)
> 

Queued, thanks.

Paolo

Re: [PATCHv2 0/2] log guest name and memory error type AO, AR for MCEs

[Mario Smarduch]

On 10/09/2019 02:19 PM, Paolo Bonzini wrote:
> On 09/10/19 18:44, Mario Smarduch wrote:
>> In a large VPC environment we want to log memory error occurrences
>> and log them with guest name and type - there are few use cases
>>
>>
>> - if VM crashes on AR mce inform the user about the reason and resolve the case
>> - if VM hangs notify the user to reboot and resume processing
>> - if VM continues to run let the user know, he/she maybe able to correlate
>>   to vm internal outage
>> - Rawhammer attacks - isolate/determine the attacker possible migrating it off
>>   the hypervisor
>> - In general track memory errors on a hyperviosr over time to determine trends
>>
>> Monitoring our fleet we come across quite a few of these and been
>> able to take action where before there were no clues to the causes.
>>
>> When memory error occurs we get a log entry in qemu log:
>>
>> Guest [Droplet-12345678] 2019-08-02T05:00:11.940270Z qemu-system-x86_64:
>> Guest MCE Memory Error at QEMU addr 0x7f3c7622f000 and GUEST 0x78e42f000
>> addr of type BUS_MCEERR_AR injected
>>
>> with enterprise logging environment we can to take further actions.
>>
>> v1 -> v2:
>> - split into two patches one to get the gustname second to log MCEs 
>> - addressed comments for MCE logging
>>
>> Mario Smarduch (2):
>>   util/qemu-error: add guest name helper with -msg options
>>   target/i386: log MCE guest and host addresses
>>
>>  include/qemu/error-report.h |  1 +
>>  qemu-options.hx             | 10 ++++++----
>>  target/i386/kvm.c           | 29 ++++++++++++++++++++++++-----
>>  util/qemu-error.c           | 31 +++++++++++++++++++++++++++++++
>>  vl.c                        |  5 +++++
>>  5 files changed, 67 insertions(+), 9 deletions(-)
>>
> 
> Queued, thanks.
> 
> Paolo
> 

Great, thanks for the fixup and y'all time.

- Mario

Re: [PATCHv2 0/2] log guest name and memory error type AO, AR for MCEs

[no-reply]

Patchew URL: https://patchew.org/QEMU/20191009164459.8209-1-msmarduch@digitalocean.com/



Hi,

This series failed the docker-mingw@fedora build test. Please find the testing commands and
their output below. If you have Docker installed, you can probably reproduce it
locally.

=== TEST SCRIPT BEGIN ===
#! /bin/bash
export ARCH=x86_64
make docker-image-fedora V=1 NETWORK=1
time make docker-test-mingw@fedora J=14 NETWORK=1
=== TEST SCRIPT END ===

  CC      util/hbitmap.o
  CC      util/fifo8.o

Encoding error:
'utf-8' codec can't decode byte 0x95 in position 799: invalid start byte
The full traceback has been saved in /tmp/sphinx-err-qsfcd92y.log, if you want to report the issue to the developers.
  CC      util/cacheinfo.o
---
  CC      util/id.o
  CC      util/iov.o
  CC      util/qemu-config.o
make: *** [Makefile:994: docs/interop/index.html] Error 2
make: *** Waiting for unfinished jobs....
Traceback (most recent call last):
  File "./tests/docker/docker.py", line 662, in <module>
---
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['sudo', '-n', 'docker', 'run', '--label', 'com.qemu.instance.uuid=c8274a8a922d4d2c81b14b6b5c0902ca', '-u', '1003', '--security-opt', 'seccomp=unconfined', '--rm', '-e', 'TARGET_LIST=', '-e', 'EXTRA_CONFIGURE_OPTS=', '-e', 'V=', '-e', 'J=14', '-e', 'DEBUG=', '-e', 'SHOW_ENV=', '-e', 'CCACHE_DIR=/var/tmp/ccache', '-v', '/home/patchew2/.cache/qemu-docker-ccache:/var/tmp/ccache:z', '-v', '/var/tmp/patchew-tester-tmp-vdk7fez9/src/docker-src.2019-10-09-18.53.09.17540:/var/tmp/qemu:z,ro', 'qemu:fedora', '/var/tmp/qemu/run', 'test-mingw']' returned non-zero exit status 2.
filter=--filter=label=com.qemu.instance.uuid=c8274a8a922d4d2c81b14b6b5c0902ca
make[1]: *** [docker-run] Error 1
make[1]: Leaving directory `/var/tmp/patchew-tester-tmp-vdk7fez9/src'
make: *** [docker-run-test-mingw@fedora] Error 2

real    2m36.643s
user    0m7.259s


The full log is available at
http://patchew.org/logs/20191009164459.8209-1-msmarduch@digitalocean.com/testing.docker-mingw@fedora/?type=message.
---
Email generated automatically by Patchew [https://patchew.org/].
Please send your feedback to patchew-devel@redhat.com