[PATCH for 4.5 v2 0/2] Improve "Emulation failed" error message

[PATCH for 4.5 v2 0/2] Improve "Emulation failed" error message

[Andrew Cooper]

After wanting to improve this error for a long time, I have encountered two
cases in the past 2 days where I have needed more information than it
provided, so have finally gotten around to fixing it.

Patch 1 introduces a "print hex buffer" custom %p format (compatible with the
Linux equivelent), while Patch 2 improves the error message.

Changes in v2:
 * Sort position of %*ph in document.  Introduce missing title for %pv.
 * Clip limit at 64 bytes rather than defaulting back to 0.
 * Don't emit a trailing space after the last byte of the hex buffer.
 * Reduce content of message for clarity.
 * Only identify 16/32/64 bit operating mode.  ???_guest_x86_mode() is
   currently insufficiently expressive to cover all operating modes.

Andrew Cooper (2):
  xen/vsprintf: Introduce %*ph extended format specifier for hex
    buffers
  x86/hvm: Improve "Emulation failed @" error messages

 docs/misc/printk-formats.txt      |    7 +++++++
 xen/arch/x86/hvm/emulate.c        |   34 +++++++++++++++++++++++++---------
 xen/arch/x86/hvm/io.c             |   11 +----------
 xen/arch/x86/hvm/vmx/realmode.c   |    9 +--------
 xen/common/vsprintf.c             |   27 +++++++++++++++++++++++++++
 xen/include/asm-x86/hvm/emulate.h |    3 +++
 6 files changed, 64 insertions(+), 27 deletions(-)

-- 
1.7.10.4

[PATCH for 4.5 v2 1/2] xen/vsprintf: Introduce %*ph extended format specifier for hex buffers

[Andrew Cooper]

This behaves in the same way as Linux.  The 64 byte limit is arbitrary but
long enough for practical purposes.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
Reviewed-by: Tim Deegan <tim@xen.org>
Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>

---
v2: (Suggestions from Jan and Tim)
 * Sort position of %*ph in document.  Introduce missing title for %pv.
 * Clip limit at 64 bytes rather than defaulting back to 0.
 * Don't emit a trailing space after the last byte of the hex buffer.
---
 docs/misc/printk-formats.txt |    7 +++++++
 xen/common/vsprintf.c        |   27 +++++++++++++++++++++++++++
 2 files changed, 34 insertions(+)

diff --git a/docs/misc/printk-formats.txt b/docs/misc/printk-formats.txt
index 3b4323a..dee0f3e 100644
--- a/docs/misc/printk-formats.txt
+++ b/docs/misc/printk-formats.txt
@@ -3,6 +3,11 @@ Xen custom %p format options.  A subset, borrowed from Linux.
 All parameters to a %p option should be compatible with void*.  Regular
 pointers are fine.  Numbers should make use of the _p() macro.
 
+Raw buffer as hex string:
+
+       %*ph    Up to 64 characters, printed as "00 01 02 ... ff".  Buffer length
+               expected via the field_width paramter. i.e. printk("%*ph", 8, buffer);
+
 Symbol/Function pointers:
 
        %ps     Symbol name with condition offset and size (iff offset != 0)
@@ -16,5 +21,7 @@ Symbol/Function pointers:
        In the case that an appropriate symbol name can't be found, %p[sS] will
        fall back to '%p' and print the address in hex.
 
+Domain and vCPU information:
+
        %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
                "d<domid>v<vcpuid>")
diff --git a/xen/common/vsprintf.c b/xen/common/vsprintf.c
index e68886a..599d52a 100644
--- a/xen/common/vsprintf.c
+++ b/xen/common/vsprintf.c
@@ -272,6 +272,33 @@ static char *pointer(char *str, char *end, const char **fmt_ptr,
     /* Custom %p suffixes. See XEN_ROOT/docs/misc/printk-formats.txt */
     switch ( fmt[1] )
     {
+    case 'h': /* Raw buffer as hex string. */
+    {
+        /* Bound user count from %* to between 0 and 64 bytes. */
+        unsigned i, nr_bytes =
+            (field_width < 0) ? 0 : (field_width > 64) ? 64 : field_width;
+        const uint8_t *hex_buffer = arg;
+
+        /* Consumed 'h' from the format string. */
+        ++*fmt_ptr;
+
+        for ( i = 0; i < nr_bytes; ++i )
+        {
+            /* Each byte: 2 chars, 0-padded, base 16, no hex prefix. */
+            str = number(str, end, hex_buffer[i], 16, 2, -1, ZEROPAD);
+
+            /* Skip trailing space after final byte. */
+            if ( i == (nr_bytes - 1) )
+                break;
+
+            if ( str < end )
+                *str = ' ';
+            ++str;
+        }
+
+        return str;
+    }
+
     case 's': /* Symbol name with offset and size (iff offset != 0) */
     case 'S': /* Symbol name unconditionally with offset and size */
     {
-- 
1.7.10.4

[PATCH v3 1/2] vsprintf: introduce %*ph extended format specifier for hex buffers

[Jan Beulich]

[-- Attachment #1: Type: text/plain, Size: 2385 bytes --]

This behaves in the same way as Linux.  The 64 byte limit is arbitrary but
long enough for practical purposes.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

Re-structured code.

Signed-off-by: Jan Beulich <jbeulich@suse.com>

--- a/docs/misc/printk-formats.txt
+++ b/docs/misc/printk-formats.txt
@@ -3,6 +3,11 @@ Xen custom %p format options.  A subset,
 All parameters to a %p option should be compatible with void*.  Regular
 pointers are fine.  Numbers should make use of the _p() macro.
 
+Raw buffer as hex string:
+
+       %*ph    Up to 64 characters, printed as "00 01 02 ... ff".  Buffer length
+               expected via the field_width paramter. i.e. printk("%*ph", 8, buffer);
+
 Symbol/Function pointers:
 
        %ps     Symbol name with condition offset and size (iff offset != 0)
@@ -16,5 +21,7 @@ Symbol/Function pointers:
        In the case that an appropriate symbol name can't be found, %p[sS] will
        fall back to '%p' and print the address in hex.
 
+Domain and vCPU information:
+
        %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
                "d<domid>v<vcpuid>")
--- a/xen/common/vsprintf.c
+++ b/xen/common/vsprintf.c
@@ -272,6 +272,34 @@ static char *pointer(char *str, char *en
     /* Custom %p suffixes. See XEN_ROOT/docs/misc/printk-formats.txt */
     switch ( fmt[1] )
     {
+    case 'h': /* Raw buffer as hex string. */
+    {
+        const uint8_t *hex_buffer = arg;
+        unsigned int i;
+
+        /* Consumed 'h' from the format string. */
+        ++*fmt_ptr;
+
+        /* Bound user count from %* to between 0 and 64 bytes. */
+        if ( field_width <= 0 )
+            return str;
+        if ( field_width > 64 )
+            field_width = 64;
+
+        for ( i = 0; ; )
+        {
+            /* Each byte: 2 chars, 0-padded, base 16, no hex prefix. */
+            str = number(str, end, hex_buffer[i], 16, 2, -1, ZEROPAD);
+
+            if ( ++i == field_width )
+                return str;
+
+            if ( str < end )
+                *str = ' ';
+            ++str;
+        }
+    }
+
     case 's': /* Symbol name with offset and size (iff offset != 0) */
     case 'S': /* Symbol name unconditionally with offset and size */
     {




[-- Attachment #2: vsnprintf-%ph.patch --]
[-- Type: text/plain, Size: 2449 bytes --]

vsprintf: introduce %*ph extended format specifier for hex buffers

This behaves in the same way as Linux.  The 64 byte limit is arbitrary but
long enough for practical purposes.

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>

Re-structured code.

Signed-off-by: Jan Beulich <jbeulich@suse.com>

--- a/docs/misc/printk-formats.txt
+++ b/docs/misc/printk-formats.txt
@@ -3,6 +3,11 @@ Xen custom %p format options.  A subset,
 All parameters to a %p option should be compatible with void*.  Regular
 pointers are fine.  Numbers should make use of the _p() macro.
 
+Raw buffer as hex string:
+
+       %*ph    Up to 64 characters, printed as "00 01 02 ... ff".  Buffer length
+               expected via the field_width paramter. i.e. printk("%*ph", 8, buffer);
+
 Symbol/Function pointers:
 
        %ps     Symbol name with condition offset and size (iff offset != 0)
@@ -16,5 +21,7 @@ Symbol/Function pointers:
        In the case that an appropriate symbol name can't be found, %p[sS] will
        fall back to '%p' and print the address in hex.
 
+Domain and vCPU information:
+
        %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
                "d<domid>v<vcpuid>")
--- a/xen/common/vsprintf.c
+++ b/xen/common/vsprintf.c
@@ -272,6 +272,34 @@ static char *pointer(char *str, char *en
     /* Custom %p suffixes. See XEN_ROOT/docs/misc/printk-formats.txt */
     switch ( fmt[1] )
     {
+    case 'h': /* Raw buffer as hex string. */
+    {
+        const uint8_t *hex_buffer = arg;
+        unsigned int i;
+
+        /* Consumed 'h' from the format string. */
+        ++*fmt_ptr;
+
+        /* Bound user count from %* to between 0 and 64 bytes. */
+        if ( field_width <= 0 )
+            return str;
+        if ( field_width > 64 )
+            field_width = 64;
+
+        for ( i = 0; ; )
+        {
+            /* Each byte: 2 chars, 0-padded, base 16, no hex prefix. */
+            str = number(str, end, hex_buffer[i], 16, 2, -1, ZEROPAD);
+
+            if ( ++i == field_width )
+                return str;
+
+            if ( str < end )
+                *str = ' ';
+            ++str;
+        }
+    }
+
     case 's': /* Symbol name with offset and size (iff offset != 0) */
     case 'S': /* Symbol name unconditionally with offset and size */
     {

[-- Attachment #3: Type: text/plain, Size: 126 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xen.org
http://lists.xen.org/xen-devel

Re: [PATCH v3 1/2] vsprintf: introduce %*ph extended format specifier for hex buffers

[Andrew Cooper]

On 01/10/14 08:21, Jan Beulich wrote:
> This behaves in the same way as Linux.  The 64 byte limit is arbitrary but
> long enough for practical purposes.
>
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
> Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
>
> Re-structured code.
>
> Signed-off-by: Jan Beulich <jbeulich@suse.com>

As this is a modification to my patch, I am not sure whether Reviewed-by
or Ack-ed by is more appropriate.

Either way, I am happy with the change.

~Andrew

>
> --- a/docs/misc/printk-formats.txt
> +++ b/docs/misc/printk-formats.txt
> @@ -3,6 +3,11 @@ Xen custom %p format options.  A subset,
>  All parameters to a %p option should be compatible with void*.  Regular
>  pointers are fine.  Numbers should make use of the _p() macro.
>  
> +Raw buffer as hex string:
> +
> +       %*ph    Up to 64 characters, printed as "00 01 02 ... ff".  Buffer length
> +               expected via the field_width paramter. i.e. printk("%*ph", 8, buffer);
> +
>  Symbol/Function pointers:
>  
>         %ps     Symbol name with condition offset and size (iff offset != 0)
> @@ -16,5 +21,7 @@ Symbol/Function pointers:
>         In the case that an appropriate symbol name can't be found, %p[sS] will
>         fall back to '%p' and print the address in hex.
>  
> +Domain and vCPU information:
> +
>         %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
>                 "d<domid>v<vcpuid>")
> --- a/xen/common/vsprintf.c
> +++ b/xen/common/vsprintf.c
> @@ -272,6 +272,34 @@ static char *pointer(char *str, char *en
>      /* Custom %p suffixes. See XEN_ROOT/docs/misc/printk-formats.txt */
>      switch ( fmt[1] )
>      {
> +    case 'h': /* Raw buffer as hex string. */
> +    {
> +        const uint8_t *hex_buffer = arg;
> +        unsigned int i;
> +
> +        /* Consumed 'h' from the format string. */
> +        ++*fmt_ptr;
> +
> +        /* Bound user count from %* to between 0 and 64 bytes. */
> +        if ( field_width <= 0 )
> +            return str;
> +        if ( field_width > 64 )
> +            field_width = 64;
> +
> +        for ( i = 0; ; )
> +        {
> +            /* Each byte: 2 chars, 0-padded, base 16, no hex prefix. */
> +            str = number(str, end, hex_buffer[i], 16, 2, -1, ZEROPAD);
> +
> +            if ( ++i == field_width )
> +                return str;
> +
> +            if ( str < end )
> +                *str = ' ';
> +            ++str;
> +        }
> +    }
> +
>      case 's': /* Symbol name with offset and size (iff offset != 0) */
>      case 'S': /* Symbol name unconditionally with offset and size */
>      {
>
>
>

[PATCH for 4.5 v2 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Andrew Cooper]

* Introduce hvm_dump_emulation_state() to be a common implementation rather
  than having the printk() open-coded slightly differently in 3 separate
  places.
* Identify the vcpu operating mode to allow for unambiguous decoding of the
  instruction bytes.
* A valid instruction can be up to 15 bytes long, but may also be shorter than
  the current arbitrary 10 bytes.  Print only the fetched bytes, which could
  include nothing if the emulation failed due to an inability to fetch the
  instruction.

A sample new error message looks like:

(d1) MMIO emulation failed: d1v0 64bit @ 0008:ffff82d0802c4f20 -> 48 8b b8 e8 7f 00 00

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
Reviewed-by: Tim Deegan <tim@xen.org>
Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Jun Nakajima <jun.nakajima@intel.com>
CC: Eddie Dong <eddie.dong@intel.com>
CC: Kevin Tian <kevin.tian@intel.com>

---

v2: (Suggestions from Jan and Tim)
 * Reduce content of message for clarity.
 * Only identify 16/32/64 bit operating mode.  ???_guest_x86_mode() is
   currently insufficiently expressive to cover all operating modes.

Ideally, hvm_dump_emulation_state() would have a const context pointer, but
hvmemul_get_seg_reg() currently needs to set an accessed bit.  We should
probably differencitate between get_seg_reg() for the purposes of emulating,
and get_seg_reg() for the purpose of debug printing.
---
 xen/arch/x86/hvm/emulate.c        |   34 +++++++++++++++++++++++++---------
 xen/arch/x86/hvm/io.c             |   11 +----------
 xen/arch/x86/hvm/vmx/realmode.c   |    9 +--------
 xen/include/asm-x86/hvm/emulate.h |    3 +++
 4 files changed, 30 insertions(+), 27 deletions(-)

diff --git a/xen/arch/x86/hvm/emulate.c b/xen/arch/x86/hvm/emulate.c
index 6ab06e0..85e0934 100644
--- a/xen/arch/x86/hvm/emulate.c
+++ b/xen/arch/x86/hvm/emulate.c
@@ -1390,15 +1390,7 @@ void hvm_mem_event_emulate_one(bool_t nowrite, unsigned int trapnr,
          */
         return;
     case X86EMUL_UNHANDLEABLE:
-        gdprintk(XENLOG_DEBUG, "Emulation failed @ %04x:%lx: "
-               "%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
-               hvmemul_get_seg_reg(x86_seg_cs, &ctx)->sel,
-               ctx.insn_buf_eip,
-               ctx.insn_buf[0], ctx.insn_buf[1],
-               ctx.insn_buf[2], ctx.insn_buf[3],
-               ctx.insn_buf[4], ctx.insn_buf[5],
-               ctx.insn_buf[6], ctx.insn_buf[7],
-               ctx.insn_buf[8], ctx.insn_buf[9]);
+        hvm_dump_emulation_state(XENLOG_G_DEBUG "Mem event", &ctx);
         hvm_inject_hw_exception(trapnr, errcode);
         break;
     case X86EMUL_EXCEPTION:
@@ -1449,6 +1441,30 @@ struct segment_register *hvmemul_get_seg_reg(
     return &hvmemul_ctxt->seg_reg[seg];
 }
 
+static const char *guest_x86_mode_to_str(int mode)
+{
+    switch ( mode )
+    {
+    case 0 ... 2: return "16bit";
+    case 4:       return "32bit";
+    case 8:       return "64bit";
+    default:      return "Unknown";
+    }
+}
+
+void hvm_dump_emulation_state(const char *prefix,
+                              struct hvm_emulate_ctxt *hvmemul_ctxt)
+{
+    struct vcpu *curr = current;
+    const char *mode_str = guest_x86_mode_to_str(hvm_guest_x86_mode(curr));
+    const struct segment_register *cs =
+        hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt);
+
+    printk("%s emulation failed: %pv %s @ %04x:%08lx -> %*ph\n",
+           prefix, curr, mode_str, cs->sel, hvmemul_ctxt->insn_buf_eip,
+           hvmemul_ctxt->insn_buf_bytes, hvmemul_ctxt->insn_buf);
+}
+
 /*
  * Local variables:
  * mode: C
diff --git a/xen/arch/x86/hvm/io.c b/xen/arch/x86/hvm/io.c
index 9f565d6..acbb69b 100644
--- a/xen/arch/x86/hvm/io.c
+++ b/xen/arch/x86/hvm/io.c
@@ -100,16 +100,7 @@ int handle_mmio(void)
     switch ( rc )
     {
     case X86EMUL_UNHANDLEABLE:
-        gdprintk(XENLOG_WARNING,
-                 "MMIO emulation failed @ %04x:%lx: "
-                 "%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
-                 hvmemul_get_seg_reg(x86_seg_cs, &ctxt)->sel,
-                 ctxt.insn_buf_eip,
-                 ctxt.insn_buf[0], ctxt.insn_buf[1],
-                 ctxt.insn_buf[2], ctxt.insn_buf[3],
-                 ctxt.insn_buf[4], ctxt.insn_buf[5],
-                 ctxt.insn_buf[6], ctxt.insn_buf[7],
-                 ctxt.insn_buf[8], ctxt.insn_buf[9]);
+        hvm_dump_emulation_state(XENLOG_G_WARNING "MMIO", &ctxt);
         return 0;
     case X86EMUL_EXCEPTION:
         if ( ctxt.exn_pending )
diff --git a/xen/arch/x86/hvm/vmx/realmode.c b/xen/arch/x86/hvm/vmx/realmode.c
index 45066b2..80d1543 100644
--- a/xen/arch/x86/hvm/vmx/realmode.c
+++ b/xen/arch/x86/hvm/vmx/realmode.c
@@ -157,14 +157,7 @@ static void realmode_emulate_one(struct hvm_emulate_ctxt *hvmemul_ctxt)
     return;
 
  fail:
-    gdprintk(XENLOG_ERR,
-             "Real-mode emulation failed @ %04x:%08lx: "
-             "%02x %02x %02x %02x %02x %02x\n",
-             hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt)->sel,
-             hvmemul_ctxt->insn_buf_eip,
-             hvmemul_ctxt->insn_buf[0], hvmemul_ctxt->insn_buf[1],
-             hvmemul_ctxt->insn_buf[2], hvmemul_ctxt->insn_buf[3],
-             hvmemul_ctxt->insn_buf[4], hvmemul_ctxt->insn_buf[5]);
+    hvm_dump_emulation_state(XENLOG_G_ERR "Real-mode", hvmemul_ctxt);
     domain_crash(curr->domain);
 }
 
diff --git a/xen/include/asm-x86/hvm/emulate.h b/xen/include/asm-x86/hvm/emulate.h
index efff97e..a510123 100644
--- a/xen/include/asm-x86/hvm/emulate.h
+++ b/xen/include/asm-x86/hvm/emulate.h
@@ -55,4 +55,7 @@ int hvmemul_do_pio(
     unsigned long port, unsigned long *reps, int size,
     paddr_t ram_gpa, int dir, int df, void *p_data);
 
+void hvm_dump_emulation_state(const char *situation,
+                              struct hvm_emulate_ctxt *hvmemul_ctxt);
+
 #endif /* __ASM_X86_HVM_EMULATE_H__ */
-- 
1.7.10.4

Re: [PATCH for 4.5 v2 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Jan Beulich]

>>> On 26.09.14 at 18:24, <andrew.cooper3@citrix.com> wrote:
> @@ -1449,6 +1441,30 @@ struct segment_register *hvmemul_get_seg_reg(
>      return &hvmemul_ctxt->seg_reg[seg];
>  }
>  
> +static const char *guest_x86_mode_to_str(int mode)
> +{
> +    switch ( mode )
> +    {
> +    case 0 ... 2: return "16bit";

I don't really follow why you dropped the real and vm86 mode
special casing here (nor do I think ???_guest_x86_mode() is
producing insufficient detail for the purposes here or elsewhere).

Jan

Re: [PATCH for 4.5 v2 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Andrew Cooper]

On 29/09/14 09:34, Jan Beulich wrote:
>>>> On 26.09.14 at 18:24, <andrew.cooper3@citrix.com> wrote:
>> @@ -1449,6 +1441,30 @@ struct segment_register *hvmemul_get_seg_reg(
>>      return &hvmemul_ctxt->seg_reg[seg];
>>  }
>>  
>> +static const char *guest_x86_mode_to_str(int mode)
>> +{
>> +    switch ( mode )
>> +    {
>> +    case 0 ... 2: return "16bit";
> I don't really follow why you dropped the real and vm86 mode
> special casing here (nor do I think ???_guest_x86_mode() is
> producing insufficient detail for the purposes here or elsewhere).
>
> Jan
>

I specifically want to avoid having specifics like "Real" and "v86"
along side more generic terms such as "16bit", because I can see even
myself as the author getting confused in the future.

One option would be to borrow the terminology from
http://sandpile.org/x86/mode.htm which is unambiguous, and provides
rather more information than just how to decode the instructions. 
Unfortunately, ???_guest_x86_mode() is insufficiently expressive to
express this complete set.

Therefore, I opted for the other extreme to avoid having a mix of
information returned from guest_x86_mode_to_str().

~Andrew

Re: [PATCH for 4.5 v2 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Jan Beulich]

>>> On 29.09.14 at 11:23, <andrew.cooper3@citrix.com> wrote:
> On 29/09/14 09:34, Jan Beulich wrote:
>>>>> On 26.09.14 at 18:24, <andrew.cooper3@citrix.com> wrote:
>>> @@ -1449,6 +1441,30 @@ struct segment_register *hvmemul_get_seg_reg(
>>>      return &hvmemul_ctxt->seg_reg[seg];
>>>  }
>>>  
>>> +static const char *guest_x86_mode_to_str(int mode)
>>> +{
>>> +    switch ( mode )
>>> +    {
>>> +    case 0 ... 2: return "16bit";
>> I don't really follow why you dropped the real and vm86 mode
>> special casing here (nor do I think ???_guest_x86_mode() is
>> producing insufficient detail for the purposes here or elsewhere).
> 
> I specifically want to avoid having specifics like "Real" and "v86"
> along side more generic terms such as "16bit", because I can see even
> myself as the author getting confused in the future.
> 
> One option would be to borrow the terminology from
> http://sandpile.org/x86/mode.htm which is unambiguous, and provides
> rather more information than just how to decode the instructions. 
> Unfortunately, ???_guest_x86_mode() is insufficiently expressive to
> express this complete set.

The distinction there clearly goes too far for the purposes here.
Knowing whether the code was executing in protected or real/vm86
modes may be useful though for assigning proper meaning to the
printed code selector value. And implying protected mode from
"NNbit" being printed isn't that hard a task.

Jan

[PATCH for 4.5 v3 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Andrew Cooper]

* Introduce hvm_dump_emulation_state() to be a common implementation rather
  than having the printk() open-coded slightly differently in 3 separate
  places.
* Identify the vcpu operating mode to allow for unambiguous decoding of the
  instruction bytes.
* A valid instruction can be up to 15 bytes long, but may also be shorter than
  the current arbitrary 10 bytes.  Print only the fetched bytes, which could
  include nothing if the emulation failed due to an inability to fetch the
  instruction.

A sample new error message looks like:

(d1) MMIO emulation failed: d1v0 64bit @ 0008:ffff82d0802c4f20 -> 48 8b b8 e8 7f 00 00

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
Reviewed-by: Tim Deegan <tim@xen.org>
Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Jun Nakajima <jun.nakajima@intel.com>
CC: Eddie Dong <eddie.dong@intel.com>
CC: Kevin Tian <kevin.tian@intel.com>

---
v3:
 * Include real/v86 distinction to help identify the meaning of %cs
 * Fix parameter mistake between the declaration and definition of
   hvm_dump_emulation_state()
v2: (Suggestions from Jan and Tim)
 * Reduce content of message for clarity.
 * Only identify 16/32/64 bit operating mode.  ???_guest_x86_mode() is
   currently insufficiently expressive to cover all operating modes.

Ideally, hvm_dump_emulation_state() would have a const context pointer, but
hvmemul_get_seg_reg() currently needs to set an accessed bit.  We should
probably differencitate between get_seg_reg() for the purposes of emulating,
and get_seg_reg() for the purpose of debug printing.
---
 xen/arch/x86/hvm/emulate.c        |   36 +++++++++++++++++++++++++++---------
 xen/arch/x86/hvm/io.c             |   11 +----------
 xen/arch/x86/hvm/vmx/realmode.c   |    9 +--------
 xen/include/asm-x86/hvm/emulate.h |    3 +++
 4 files changed, 32 insertions(+), 27 deletions(-)

diff --git a/xen/arch/x86/hvm/emulate.c b/xen/arch/x86/hvm/emulate.c
index 463ccfb..c0f47d2 100644
--- a/xen/arch/x86/hvm/emulate.c
+++ b/xen/arch/x86/hvm/emulate.c
@@ -1420,15 +1420,7 @@ void hvm_mem_event_emulate_one(bool_t nowrite, unsigned int trapnr,
          */
         return;
     case X86EMUL_UNHANDLEABLE:
-        gdprintk(XENLOG_DEBUG, "Emulation failed @ %04x:%lx: "
-               "%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
-               hvmemul_get_seg_reg(x86_seg_cs, &ctx)->sel,
-               ctx.insn_buf_eip,
-               ctx.insn_buf[0], ctx.insn_buf[1],
-               ctx.insn_buf[2], ctx.insn_buf[3],
-               ctx.insn_buf[4], ctx.insn_buf[5],
-               ctx.insn_buf[6], ctx.insn_buf[7],
-               ctx.insn_buf[8], ctx.insn_buf[9]);
+        hvm_dump_emulation_state(XENLOG_G_DEBUG "Mem event", &ctx);
         hvm_inject_hw_exception(trapnr, errcode);
         break;
     case X86EMUL_EXCEPTION:
@@ -1479,6 +1471,32 @@ struct segment_register *hvmemul_get_seg_reg(
     return &hvmemul_ctxt->seg_reg[seg];
 }
 
+static const char *guest_x86_mode_to_str(int mode)
+{
+    switch ( mode )
+    {
+    case 0:  return "Real";
+    case 1:  return "v86";
+    case 2:  return "16bit";
+    case 4:  return "32bit";
+    case 8:  return "64bit";
+    default: return "Unknown";
+    }
+}
+
+void hvm_dump_emulation_state(const char *prefix,
+                              struct hvm_emulate_ctxt *hvmemul_ctxt)
+{
+    struct vcpu *curr = current;
+    const char *mode_str = guest_x86_mode_to_str(hvm_guest_x86_mode(curr));
+    const struct segment_register *cs =
+        hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt);
+
+    printk("%s emulation failed: %pv %s @ %04x:%08lx -> %*ph\n",
+           prefix, curr, mode_str, cs->sel, hvmemul_ctxt->insn_buf_eip,
+           hvmemul_ctxt->insn_buf_bytes, hvmemul_ctxt->insn_buf);
+}
+
 /*
  * Local variables:
  * mode: C
diff --git a/xen/arch/x86/hvm/io.c b/xen/arch/x86/hvm/io.c
index e5d5e79..68fb890 100644
--- a/xen/arch/x86/hvm/io.c
+++ b/xen/arch/x86/hvm/io.c
@@ -100,16 +100,7 @@ int handle_mmio(void)
     switch ( rc )
     {
     case X86EMUL_UNHANDLEABLE:
-        gdprintk(XENLOG_WARNING,
-                 "MMIO emulation failed @ %04x:%lx: "
-                 "%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
-                 hvmemul_get_seg_reg(x86_seg_cs, &ctxt)->sel,
-                 ctxt.insn_buf_eip,
-                 ctxt.insn_buf[0], ctxt.insn_buf[1],
-                 ctxt.insn_buf[2], ctxt.insn_buf[3],
-                 ctxt.insn_buf[4], ctxt.insn_buf[5],
-                 ctxt.insn_buf[6], ctxt.insn_buf[7],
-                 ctxt.insn_buf[8], ctxt.insn_buf[9]);
+        hvm_dump_emulation_state(XENLOG_G_WARNING "MMIO", &ctxt);
         return 0;
     case X86EMUL_EXCEPTION:
         if ( ctxt.exn_pending )
diff --git a/xen/arch/x86/hvm/vmx/realmode.c b/xen/arch/x86/hvm/vmx/realmode.c
index 9a6de6c..fe8b4a0 100644
--- a/xen/arch/x86/hvm/vmx/realmode.c
+++ b/xen/arch/x86/hvm/vmx/realmode.c
@@ -157,14 +157,7 @@ static void realmode_emulate_one(struct hvm_emulate_ctxt *hvmemul_ctxt)
     return;
 
  fail:
-    gdprintk(XENLOG_ERR,
-             "Real-mode emulation failed @ %04x:%08lx: "
-             "%02x %02x %02x %02x %02x %02x\n",
-             hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt)->sel,
-             hvmemul_ctxt->insn_buf_eip,
-             hvmemul_ctxt->insn_buf[0], hvmemul_ctxt->insn_buf[1],
-             hvmemul_ctxt->insn_buf[2], hvmemul_ctxt->insn_buf[3],
-             hvmemul_ctxt->insn_buf[4], hvmemul_ctxt->insn_buf[5]);
+    hvm_dump_emulation_state(XENLOG_G_ERR "Real-mode", hvmemul_ctxt);
     domain_crash(curr->domain);
 }
 
diff --git a/xen/include/asm-x86/hvm/emulate.h b/xen/include/asm-x86/hvm/emulate.h
index 6cdc57b..5411302 100644
--- a/xen/include/asm-x86/hvm/emulate.h
+++ b/xen/include/asm-x86/hvm/emulate.h
@@ -54,4 +54,7 @@ int hvmemul_do_pio(
     unsigned long port, unsigned long *reps, int size,
     paddr_t ram_gpa, int dir, int df, void *p_data);
 
+void hvm_dump_emulation_state(const char *prefix,
+                              struct hvm_emulate_ctxt *hvmemul_ctxt);
+
 #endif /* __ASM_X86_HVM_EMULATE_H__ */
-- 
1.7.10.4

Re: [PATCH for 4.5 v3 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Tian, Kevin]

> From: Andrew Cooper [mailto:andrew.cooper3@citrix.com]
> Sent: Monday, September 29, 2014 2:46 AM
> 
> * Introduce hvm_dump_emulation_state() to be a common implementation
> rather
>   than having the printk() open-coded slightly differently in 3 separate
>   places.
> * Identify the vcpu operating mode to allow for unambiguous decoding of the
>   instruction bytes.
> * A valid instruction can be up to 15 bytes long, but may also be shorter than
>   the current arbitrary 10 bytes.  Print only the fetched bytes, which could
>   include nothing if the emulation failed due to an inability to fetch the
>   instruction.
> 
> A sample new error message looks like:
> 
> (d1) MMIO emulation failed: d1v0 64bit @ 0008:ffff82d0802c4f20 -> 48 8b b8
> e8 7f 00 00
> 
> Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
> Reviewed-by: Tim Deegan <tim@xen.org>
> Release-acked-by: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> CC: Keir Fraser <keir@xen.org>
> CC: Jan Beulich <JBeulich@suse.com>
> CC: Jun Nakajima <jun.nakajima@intel.com>
> CC: Eddie Dong <eddie.dong@intel.com>
> CC: Kevin Tian <kevin.tian@intel.com>

Acked-by: Kevin Tian <kevin.tian@intel.com>

> 
> ---
> v3:
>  * Include real/v86 distinction to help identify the meaning of %cs
>  * Fix parameter mistake between the declaration and definition of
>    hvm_dump_emulation_state()
> v2: (Suggestions from Jan and Tim)
>  * Reduce content of message for clarity.
>  * Only identify 16/32/64 bit operating mode.  ???_guest_x86_mode() is
>    currently insufficiently expressive to cover all operating modes.
> 
> Ideally, hvm_dump_emulation_state() would have a const context pointer, but
> hvmemul_get_seg_reg() currently needs to set an accessed bit.  We should
> probably differencitate between get_seg_reg() for the purposes of emulating,
> and get_seg_reg() for the purpose of debug printing.
> ---
>  xen/arch/x86/hvm/emulate.c        |   36
> +++++++++++++++++++++++++++---------
>  xen/arch/x86/hvm/io.c             |   11 +----------
>  xen/arch/x86/hvm/vmx/realmode.c   |    9 +--------
>  xen/include/asm-x86/hvm/emulate.h |    3 +++
>  4 files changed, 32 insertions(+), 27 deletions(-)
> 
> diff --git a/xen/arch/x86/hvm/emulate.c b/xen/arch/x86/hvm/emulate.c
> index 463ccfb..c0f47d2 100644
> --- a/xen/arch/x86/hvm/emulate.c
> +++ b/xen/arch/x86/hvm/emulate.c
> @@ -1420,15 +1420,7 @@ void hvm_mem_event_emulate_one(bool_t
> nowrite, unsigned int trapnr,
>           */
>          return;
>      case X86EMUL_UNHANDLEABLE:
> -        gdprintk(XENLOG_DEBUG, "Emulation failed @ %04x:%lx: "
> -
> "%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
> -               hvmemul_get_seg_reg(x86_seg_cs, &ctx)->sel,
> -               ctx.insn_buf_eip,
> -               ctx.insn_buf[0], ctx.insn_buf[1],
> -               ctx.insn_buf[2], ctx.insn_buf[3],
> -               ctx.insn_buf[4], ctx.insn_buf[5],
> -               ctx.insn_buf[6], ctx.insn_buf[7],
> -               ctx.insn_buf[8], ctx.insn_buf[9]);
> +        hvm_dump_emulation_state(XENLOG_G_DEBUG "Mem event",
> &ctx);
>          hvm_inject_hw_exception(trapnr, errcode);
>          break;
>      case X86EMUL_EXCEPTION:
> @@ -1479,6 +1471,32 @@ struct segment_register *hvmemul_get_seg_reg(
>      return &hvmemul_ctxt->seg_reg[seg];
>  }
> 
> +static const char *guest_x86_mode_to_str(int mode)
> +{
> +    switch ( mode )
> +    {
> +    case 0:  return "Real";
> +    case 1:  return "v86";
> +    case 2:  return "16bit";
> +    case 4:  return "32bit";
> +    case 8:  return "64bit";
> +    default: return "Unknown";
> +    }
> +}
> +
> +void hvm_dump_emulation_state(const char *prefix,
> +                              struct hvm_emulate_ctxt
> *hvmemul_ctxt)
> +{
> +    struct vcpu *curr = current;
> +    const char *mode_str =
> guest_x86_mode_to_str(hvm_guest_x86_mode(curr));
> +    const struct segment_register *cs =
> +        hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt);
> +
> +    printk("%s emulation failed: %pv %s @ %04x:%08lx -> %*ph\n",
> +           prefix, curr, mode_str, cs->sel, hvmemul_ctxt->insn_buf_eip,
> +           hvmemul_ctxt->insn_buf_bytes, hvmemul_ctxt->insn_buf);
> +}
> +
>  /*
>   * Local variables:
>   * mode: C
> diff --git a/xen/arch/x86/hvm/io.c b/xen/arch/x86/hvm/io.c
> index e5d5e79..68fb890 100644
> --- a/xen/arch/x86/hvm/io.c
> +++ b/xen/arch/x86/hvm/io.c
> @@ -100,16 +100,7 @@ int handle_mmio(void)
>      switch ( rc )
>      {
>      case X86EMUL_UNHANDLEABLE:
> -        gdprintk(XENLOG_WARNING,
> -                 "MMIO emulation failed @ %04x:%lx: "
> -
> "%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x\n",
> -                 hvmemul_get_seg_reg(x86_seg_cs, &ctxt)->sel,
> -                 ctxt.insn_buf_eip,
> -                 ctxt.insn_buf[0], ctxt.insn_buf[1],
> -                 ctxt.insn_buf[2], ctxt.insn_buf[3],
> -                 ctxt.insn_buf[4], ctxt.insn_buf[5],
> -                 ctxt.insn_buf[6], ctxt.insn_buf[7],
> -                 ctxt.insn_buf[8], ctxt.insn_buf[9]);
> +        hvm_dump_emulation_state(XENLOG_G_WARNING "MMIO",
> &ctxt);
>          return 0;
>      case X86EMUL_EXCEPTION:
>          if ( ctxt.exn_pending )
> diff --git a/xen/arch/x86/hvm/vmx/realmode.c
> b/xen/arch/x86/hvm/vmx/realmode.c
> index 9a6de6c..fe8b4a0 100644
> --- a/xen/arch/x86/hvm/vmx/realmode.c
> +++ b/xen/arch/x86/hvm/vmx/realmode.c
> @@ -157,14 +157,7 @@ static void realmode_emulate_one(struct
> hvm_emulate_ctxt *hvmemul_ctxt)
>      return;
> 
>   fail:
> -    gdprintk(XENLOG_ERR,
> -             "Real-mode emulation failed @ %04x:%08lx: "
> -             "%02x %02x %02x %02x %02x %02x\n",
> -             hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt)->sel,
> -             hvmemul_ctxt->insn_buf_eip,
> -             hvmemul_ctxt->insn_buf[0], hvmemul_ctxt->insn_buf[1],
> -             hvmemul_ctxt->insn_buf[2], hvmemul_ctxt->insn_buf[3],
> -             hvmemul_ctxt->insn_buf[4], hvmemul_ctxt->insn_buf[5]);
> +    hvm_dump_emulation_state(XENLOG_G_ERR "Real-mode",
> hvmemul_ctxt);
>      domain_crash(curr->domain);
>  }
> 
> diff --git a/xen/include/asm-x86/hvm/emulate.h
> b/xen/include/asm-x86/hvm/emulate.h
> index 6cdc57b..5411302 100644
> --- a/xen/include/asm-x86/hvm/emulate.h
> +++ b/xen/include/asm-x86/hvm/emulate.h
> @@ -54,4 +54,7 @@ int hvmemul_do_pio(
>      unsigned long port, unsigned long *reps, int size,
>      paddr_t ram_gpa, int dir, int df, void *p_data);
> 
> +void hvm_dump_emulation_state(const char *prefix,
> +                              struct hvm_emulate_ctxt
> *hvmemul_ctxt);
> +
>  #endif /* __ASM_X86_HVM_EMULATE_H__ */
> --
> 1.7.10.4