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

[PATCH for-4.5 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.

Konrad: I am requesting a release ack for this as it is a non-feature change
for the purpose of improving error messages.  Neither of the patches are
complicated (low risk of bugs/regressions), and if the worse comes to the
worst, they can safely be reverted.

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      |    6 ++++++
 xen/arch/x86/hvm/emulate.c        |   41 +++++++++++++++++++++++++++++--------
 xen/arch/x86/hvm/io.c             |   11 +---------
 xen/arch/x86/hvm/vmx/realmode.c   |    9 +-------
 xen/common/vsprintf.c             |   25 ++++++++++++++++++++++
 xen/include/asm-x86/hvm/emulate.h |    3 +++
 6 files changed, 68 insertions(+), 27 deletions(-)

[PATCH for-4.5 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>
CC: Keir Fraser <keir@xen.org>
CC: Jan Beulich <JBeulich@suse.com>
CC: Tim Deegan <tim@xen.org>
CC: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
---
 docs/misc/printk-formats.txt |    6 ++++++
 xen/common/vsprintf.c        |   25 +++++++++++++++++++++++++
 2 files changed, 31 insertions(+)

diff --git a/docs/misc/printk-formats.txt b/docs/misc/printk-formats.txt
index 3b4323a..81b3651 100644
--- a/docs/misc/printk-formats.txt
+++ b/docs/misc/printk-formats.txt
@@ -18,3 +18,9 @@ Symbol/Function pointers:
 
        %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
                "d<domid>v<vcpuid>")
+
+
+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);
diff --git a/xen/common/vsprintf.c b/xen/common/vsprintf.c
index e68886a..4a7da1c 100644
--- a/xen/common/vsprintf.c
+++ b/xen/common/vsprintf.c
@@ -272,6 +272,31 @@ 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. */
+    {
+        /*
+         * User expected to provide an explicit count using %*.  Bound between
+         * 0 and 64 bytes, defaulting to 0.
+         */
+        unsigned i, nr_bytes =
+            ((field_width < 1) || (field_width > 64)) ? 0 : 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);
+            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

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

[Jan Beulich]

>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
> --- a/docs/misc/printk-formats.txt
> +++ b/docs/misc/printk-formats.txt
> @@ -18,3 +18,9 @@ Symbol/Function pointers:
>  
>         %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
>                 "d<domid>v<vcpuid>")
> +
> +
> +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);

Let's keep this list sorted alphabetically please.

Also Linux supports an optional suffix (any of C, D, or N).

> --- a/xen/common/vsprintf.c
> +++ b/xen/common/vsprintf.c
> @@ -272,6 +272,31 @@ 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. */
> +    {
> +        /*
> +         * User expected to provide an explicit count using %*.  Bound between
> +         * 0 and 64 bytes, defaulting to 0.
> +         */
> +        unsigned i, nr_bytes =
> +            ((field_width < 1) || (field_width > 64)) ? 0 : field_width;

Producing no output for too small a field width makes sense, but why
not print 64 bytes if more were requested?

> +        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);
> +            if ( str < end )
> +                *str = ' ';
> +            ++str;

Could you suppress the trailing blank this produces, just like Linux
does?

Jan

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

[Andrew Cooper]

On 26/09/14 12:32, Jan Beulich wrote:
>>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
>> --- a/docs/misc/printk-formats.txt
>> +++ b/docs/misc/printk-formats.txt
>> @@ -18,3 +18,9 @@ Symbol/Function pointers:
>>  
>>         %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
>>                 "d<domid>v<vcpuid>")
>> +
>> +
>> +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);
> Let's keep this list sorted alphabetically please.

Ok, but then the "Symbol/Function pointers:" paragraph marker should be
dropped.

I am happy with doing either.

>
> Also Linux supports an optional suffix (any of C, D, or N).

None of those looked particularly useful IMO.  They would be trivial to
add should a need arise.

>
>> --- a/xen/common/vsprintf.c
>> +++ b/xen/common/vsprintf.c
>> @@ -272,6 +272,31 @@ 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. */
>> +    {
>> +        /*
>> +         * User expected to provide an explicit count using %*.  Bound between
>> +         * 0 and 64 bytes, defaulting to 0.
>> +         */
>> +        unsigned i, nr_bytes =
>> +            ((field_width < 1) || (field_width > 64)) ? 0 : field_width;
> Producing no output for too small a field width makes sense, but why
> not print 64 bytes if more were requested?

64 is arbitrary (taken from the Linux statement to the same effect). 
Even with an upper bound of 64, the caller should be using something
shorter and putting in newlines.

>
>> +        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);
>> +            if ( str < end )
>> +                *str = ' ';
>> +            ++str;
> Could you suppress the trailing blank this produces, just like Linux
> does?

I will see what I can do.

~Andrew

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

[Jan Beulich]

>>> On 26.09.14 at 14:16, <andrew.cooper3@citrix.com> wrote:
> On 26/09/14 12:32, Jan Beulich wrote:
>>>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
>>> --- a/docs/misc/printk-formats.txt
>>> +++ b/docs/misc/printk-formats.txt
>>> @@ -18,3 +18,9 @@ Symbol/Function pointers:
>>>  
>>>         %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
>>>                 "d<domid>v<vcpuid>")
>>> +
>>> +
>>> +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);
>> Let's keep this list sorted alphabetically please.
> 
> Ok, but then the "Symbol/Function pointers:" paragraph marker should be
> dropped.
> 
> I am happy with doing either.

Actually it looks like I should have added a header when adding %pv,
so maybe that's what wants to be corrected? Sorting by formatting
character still would see desirable to me, as would keeping the
headings.

>>> --- a/xen/common/vsprintf.c
>>> +++ b/xen/common/vsprintf.c
>>> @@ -272,6 +272,31 @@ 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. */
>>> +    {
>>> +        /*
>>> +         * User expected to provide an explicit count using %*.  Bound between
>>> +         * 0 and 64 bytes, defaulting to 0.
>>> +         */
>>> +        unsigned i, nr_bytes =
>>> +            ((field_width < 1) || (field_width > 64)) ? 0 : field_width;
>> Producing no output for too small a field width makes sense, but why
>> not print 64 bytes if more were requested?
> 
> 64 is arbitrary (taken from the Linux statement to the same effect). 
> Even with an upper bound of 64, the caller should be using something
> shorter and putting in newlines.

I'd be fine with you limiting it to a lower value; I just find it odd to
zap a value exceeding the boundary to zero rather than to the
upper bound.

Jan

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

[Andrew Cooper]

On 26/09/14 13:31, Jan Beulich wrote:
>>>> On 26.09.14 at 14:16, <andrew.cooper3@citrix.com> wrote:
>> On 26/09/14 12:32, Jan Beulich wrote:
>>>>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
>>>> --- a/docs/misc/printk-formats.txt
>>>> +++ b/docs/misc/printk-formats.txt
>>>> @@ -18,3 +18,9 @@ Symbol/Function pointers:
>>>>  
>>>>         %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
>>>>                 "d<domid>v<vcpuid>")
>>>> +
>>>> +
>>>> +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);
>>> Let's keep this list sorted alphabetically please.
>> Ok, but then the "Symbol/Function pointers:" paragraph marker should be
>> dropped.
>>
>> I am happy with doing either.
> Actually it looks like I should have added a header when adding %pv,
> so maybe that's what wants to be corrected? Sorting by formatting
> character still would see desirable to me, as would keeping the
> headings.

I will introduce the heading for %pv

>
>>>> --- a/xen/common/vsprintf.c
>>>> +++ b/xen/common/vsprintf.c
>>>> @@ -272,6 +272,31 @@ 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. */
>>>> +    {
>>>> +        /*
>>>> +         * User expected to provide an explicit count using %*.  Bound between
>>>> +         * 0 and 64 bytes, defaulting to 0.
>>>> +         */
>>>> +        unsigned i, nr_bytes =
>>>> +            ((field_width < 1) || (field_width > 64)) ? 0 : field_width;
>>> Producing no output for too small a field width makes sense, but why
>>> not print 64 bytes if more were requested?
>> 64 is arbitrary (taken from the Linux statement to the same effect). 
>> Even with an upper bound of 64, the caller should be using something
>> shorter and putting in newlines.
> I'd be fine with you limiting it to a lower value; I just find it odd to
> zap a value exceeding the boundary to zero rather than to the
> upper bound.
>
> Jan
>

Ok

~Andrew

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

[Tim Deegan]

At 11:10 +0100 on 26 Sep (1411726206), Andrew Cooper 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>
> CC: Keir Fraser <keir@xen.org>
> CC: Jan Beulich <JBeulich@suse.com>
> CC: Tim Deegan <tim@xen.org>
> CC: Konrad Rzeszutek Wilk <konrad.wilk@oracle.com>
> ---
>  docs/misc/printk-formats.txt |    6 ++++++
>  xen/common/vsprintf.c        |   25 +++++++++++++++++++++++++
>  2 files changed, 31 insertions(+)
> 
> diff --git a/docs/misc/printk-formats.txt b/docs/misc/printk-formats.txt
> index 3b4323a..81b3651 100644
> --- a/docs/misc/printk-formats.txt
> +++ b/docs/misc/printk-formats.txt
> @@ -18,3 +18,9 @@ Symbol/Function pointers:
>  
>         %pv     Domain and vCPU ID from a 'struct vcpu *' (printed as
>                 "d<domid>v<vcpuid>")
> +
> +
> +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);
> diff --git a/xen/common/vsprintf.c b/xen/common/vsprintf.c
> index e68886a..4a7da1c 100644
> --- a/xen/common/vsprintf.c
> +++ b/xen/common/vsprintf.c
> @@ -272,6 +272,31 @@ 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. */
> +    {
> +        /*
> +         * User expected to provide an explicit count using %*.  Bound between
> +         * 0 and 64 bytes, defaulting to 0.
> +         */
> +        unsigned i, nr_bytes =
> +            ((field_width < 1) || (field_width > 64)) ? 0 : 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);
> +            if ( str < end )

(str < end && i + 1 < nr_bytes) to avoid a trailing space?

Otherwise, Reviewed-by: Tim Deegan <tim@xen.org>

Tim.

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

[Jan Beulich]

>>> On 26.09.14 at 13:49, <tim@xen.org> wrote:
> At 11:10 +0100 on 26 Sep (1411726206), Andrew Cooper wrote:
>> +        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);
>> +            if ( str < end )
> 
> (str < end && i + 1 < nr_bytes) to avoid a trailing space?

Not exactly, as the increment of str must then also be suppressed.

Jan

[PATCH for-4.5 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.
* Identify the actual number of bytes in the instruction buffer, and print
  exactly the number of bytes fetched.  A valid instruction can be up to 15
  bytes long, but may also be shorter than the current arbitrary 10 bytes.

A sample new error message looks like:

(d1) MMIO emulation failed: d1v0 64bit mode, 7 bytes @ 0008:ffff82d080102fea: 48 63 8d 40 ff ff ff

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

---

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        |   41 +++++++++++++++++++++++++++++--------
 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, 37 insertions(+), 27 deletions(-)

diff --git a/xen/arch/x86/hvm/emulate.c b/xen/arch/x86/hvm/emulate.c
index 6ab06e0..d42d251 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,37 @@ 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 "v8086";
+    case 2:
+    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));
+    struct segment_register *cs = hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt);
+
+    printk("%s emulation failed: %pv %s mode, %u bytes @ %04x:%lx: %*ph\n",
+           prefix, curr, mode_str, hvmemul_ctxt->insn_buf_bytes,
+           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 2/2] x86/hvm: Improve "Emulation failed @" error messages

[Jan Beulich]

>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
> @@ -1449,6 +1441,37 @@ 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 "v8086";
> +    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));
> +    struct segment_register *cs = hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt);

Long line. And perhaps add "const"?

> +
> +    printk("%s emulation failed: %pv %s mode, %u bytes @ %04x:%lx: %*ph\n",
> +           prefix, curr, mode_str, hvmemul_ctxt->insn_buf_bytes,

Do you really need to print the byte count as a number when the
new formatting will suitably limit output anyway?

Jan

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

[Andrew Cooper]

On 26/09/14 12:39, Jan Beulich wrote:
>>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
>> @@ -1449,6 +1441,37 @@ 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 "v8086";
>> +    case 2:
> return "16bit";

case 2 is 32bit mode code in a 16bit segment.  Therefore, 32bit is still
the correct text when aiding decode of the instruction.

What I want to avoid is the confusing statement of "16bit mode" which is
easily confused as "Real mode" and a set of bytes which should be
decoded as 32bit instructions.

>
>> +    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));
>> +    struct segment_register *cs = hvmemul_get_seg_reg(x86_seg_cs, hvmemul_ctxt);
> Long line. And perhaps add "const"?

Ok

>
>> +
>> +    printk("%s emulation failed: %pv %s mode, %u bytes @ %04x:%lx: %*ph\n",
>> +           prefix, curr, mode_str, hvmemul_ctxt->insn_buf_bytes,
> Do you really need to print the byte count as a number when the
> new formatting will suitably limit output anyway?

I considered that, but thought that "@ xxxx:xxxx:\n" might be a little
obscure.  On the other hand, it might be ok.  I am happy dropping the
"%u bytes" if that is considered ok.

~Andrew

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

[Jan Beulich]

>>> On 26.09.14 at 14:04, <andrew.cooper3@citrix.com> wrote:
> On 26/09/14 12:39, Jan Beulich wrote:
>>>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
>>> @@ -1449,6 +1441,37 @@ 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 "v8086";
>>> +    case 2:
>> return "16bit";
> 
> case 2 is 32bit mode code in a 16bit segment.  Therefore, 32bit is still
> the correct text when aiding decode of the instruction.

It's specifically not: Operand and address size (and respective
prefixes) have different meaning. You really don't care about
the mode the CPU as a whole is in, but the kind of instructions
it executes.

> What I want to avoid is the confusing statement of "16bit mode" which is
> easily confused as "Real mode" and a set of bytes which should be
> decoded as 32bit instructions.

But instructions in a 16-bit segment should be decoded as 16-bit
instructions, not 32-bit ones. Yes, OS/2 and 16-bit Windows are
long gone, but this hasn't changed.

>>> +    printk("%s emulation failed: %pv %s mode, %u bytes @ %04x:%lx: %*ph\n",
>>> +           prefix, curr, mode_str, hvmemul_ctxt->insn_buf_bytes,
>> Do you really need to print the byte count as a number when the
>> new formatting will suitably limit output anyway?
> 
> I considered that, but thought that "@ xxxx:xxxx:\n" might be a little
> obscure.  On the other hand, it might be ok.  I am happy dropping the
> "%u bytes" if that is considered ok.

Just make it "%04x:%08lx -> %*ph"? (Intentionally not using %lx
as you did - I'd really dislike seeing addresses like 0000:12, while I'd
be much less concerned for digit counts between 8 and 16 to vary.)

Jan

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

[Andrew Cooper]

On 26/09/14 13:36, Jan Beulich wrote:
>>>> On 26.09.14 at 14:04, <andrew.cooper3@citrix.com> wrote:
>> On 26/09/14 12:39, Jan Beulich wrote:
>>>>>> On 26.09.14 at 12:10, <andrew.cooper3@citrix.com> wrote:
>>>> @@ -1449,6 +1441,37 @@ 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 "v8086";
>>>> +    case 2:
>>> return "16bit";
>> case 2 is 32bit mode code in a 16bit segment.  Therefore, 32bit is still
>> the correct text when aiding decode of the instruction.
> It's specifically not: Operand and address size (and respective
> prefixes) have different meaning. You really don't care about
> the mode the CPU as a whole is in, but the kind of instructions
> it executes.
>
>> What I want to avoid is the confusing statement of "16bit mode" which is
>> easily confused as "Real mode" and a set of bytes which should be
>> decoded as 32bit instructions.
> But instructions in a 16-bit segment should be decoded as 16-bit
> instructions, not 32-bit ones. Yes, OS/2 and 16-bit Windows are
> long gone, but this hasn't changed.

I am indeed getting confused.

>
>>>> +    printk("%s emulation failed: %pv %s mode, %u bytes @ %04x:%lx: %*ph\n",
>>>> +           prefix, curr, mode_str, hvmemul_ctxt->insn_buf_bytes,
>>> Do you really need to print the byte count as a number when the
>>> new formatting will suitably limit output anyway?
>> I considered that, but thought that "@ xxxx:xxxx:\n" might be a little
>> obscure.  On the other hand, it might be ok.  I am happy dropping the
>> "%u bytes" if that is considered ok.
> Just make it "%04x:%08lx -> %*ph"? (Intentionally not using %lx
> as you did - I'd really dislike seeing addresses like 0000:12, while I'd
> be much less concerned for digit counts between 8 and 16 to vary.)

Looks better - I shall go with that.

~Andrew

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

[Tim Deegan]

At 11:10 +0100 on 26 Sep (1411726207), Andrew Cooper wrote:
> +static const char *guest_x86_mode_to_str(int mode)
> +{
> +    switch ( mode )
> +    {
> +    case 0:
> +        return "Real";
> +    case 1:
> +        return "v8086";
> +    case 2:

return "16bit"?  

Otherwise, Reviewed-by: Tim Deegan <tim@xen.org>

While you're respinning, could you also shorten all of these strings
(e.g. to real/vm86/16b/32b/64b), and trim the rest of the line,
something like:

(d1) MMIO emulation failed: d1v0 64b @ 0008:ffff82d080102fea: 48 63 8d 40 ff ff ff

You can keep the reviewed-by regardless of whatever cosmetic changes.

Cheers,

Tim.

> +    case 4:
> +        return "32bit";
> +    case 8:
> +        return "64bit";
> +    default:
> +        return "Unknown";

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

[Andrew Cooper]

On 26/09/14 13:05, Tim Deegan wrote:
> At 11:10 +0100 on 26 Sep (1411726207), Andrew Cooper wrote:
>> +static const char *guest_x86_mode_to_str(int mode)
>> +{
>> +    switch ( mode )
>> +    {
>> +    case 0:
>> +        return "Real";
>> +    case 1:
>> +        return "v8086";
>> +    case 2:
> return "16bit"?  
>
> Otherwise, Reviewed-by: Tim Deegan <tim@xen.org>
>
> While you're respinning, could you also shorten all of these strings
> (e.g. to real/vm86/16b/32b/64b), and trim the rest of the line,
> something like:
>
> (d1) MMIO emulation failed: d1v0 64b @ 0008:ffff82d080102fea: 48 63 8d 40 ff ff ff
>
> You can keep the reviewed-by regardless of whatever cosmetic changes.
>
> Cheers,
>
> Tim.

As identified in the other thread, "16bit" is misleading as the
instruction bytes are actually 32bit code in a 16bit segment.

I am not sure what the best solution here is.  Perhaps we can trust
anyone capable of interpreting this error to know that "16b" != "Real"
or "v86" when it comes to decoding the instruction.

~Andrew

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

[Tim Deegan]

At 13:09 +0100 on 26 Sep (1411733364), Andrew Cooper wrote:
> On 26/09/14 13:05, Tim Deegan wrote:
> > At 11:10 +0100 on 26 Sep (1411726207), Andrew Cooper wrote:
> >> +static const char *guest_x86_mode_to_str(int mode)
> >> +{
> >> +    switch ( mode )
> >> +    {
> >> +    case 0:
> >> +        return "Real";
> >> +    case 1:
> >> +        return "v8086";
> >> +    case 2:
> > return "16bit"?  
> >
> > Otherwise, Reviewed-by: Tim Deegan <tim@xen.org>
> >
> > While you're respinning, could you also shorten all of these strings
> > (e.g. to real/vm86/16b/32b/64b), and trim the rest of the line,
> > something like:
> >
> > (d1) MMIO emulation failed: d1v0 64b @ 0008:ffff82d080102fea: 48 63 8d 40 ff ff ff
> >
> > You can keep the reviewed-by regardless of whatever cosmetic changes.
> >
> > Cheers,
> >
> > Tim.
> 
> As identified in the other thread, "16bit" is misleading as the
> instruction bytes are actually 32bit code in a 16bit segment.
> 
> I am not sure what the best solution here is.  Perhaps we can trust
> anyone capable of interpreting this error to know that "16b" != "Real"
> or "v86" when it comes to decoding the instruction.

Hmm.  I can see that 16bit is a bit misleading if you don't
know/remember that vm86 and real mode would be reported as such.  OTOH
that is infomration that's needed for decoding -- the instruction will
have 16bit operands and addresses even though it uses 32bit registers
and protected segments.

Maybe we should report it as '16bit protected' or similar?

Tim.

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

[Andrew Cooper]

On 26/09/14 13:41, Tim Deegan wrote:
> At 13:09 +0100 on 26 Sep (1411733364), Andrew Cooper wrote:
>> On 26/09/14 13:05, Tim Deegan wrote:
>>> At 11:10 +0100 on 26 Sep (1411726207), Andrew Cooper wrote:
>>>> +static const char *guest_x86_mode_to_str(int mode)
>>>> +{
>>>> +    switch ( mode )
>>>> +    {
>>>> +    case 0:
>>>> +        return "Real";
>>>> +    case 1:
>>>> +        return "v8086";
>>>> +    case 2:
>>> return "16bit"?  
>>>
>>> Otherwise, Reviewed-by: Tim Deegan <tim@xen.org>
>>>
>>> While you're respinning, could you also shorten all of these strings
>>> (e.g. to real/vm86/16b/32b/64b), and trim the rest of the line,
>>> something like:
>>>
>>> (d1) MMIO emulation failed: d1v0 64b @ 0008:ffff82d080102fea: 48 63 8d 40 ff ff ff
>>>
>>> You can keep the reviewed-by regardless of whatever cosmetic changes.
>>>
>>> Cheers,
>>>
>>> Tim.
>> As identified in the other thread, "16bit" is misleading as the
>> instruction bytes are actually 32bit code in a 16bit segment.
>>
>> I am not sure what the best solution here is.  Perhaps we can trust
>> anyone capable of interpreting this error to know that "16b" != "Real"
>> or "v86" when it comes to decoding the instruction.
> Hmm.  I can see that 16bit is a bit misleading if you don't
> know/remember that vm86 and real mode would be reported as such.  OTOH
> that is infomration that's needed for decoding -- the instruction will
> have 16bit operands and addresses even though it uses 32bit registers
> and protected segments.
>
> Maybe we should report it as '16bit protected' or similar?

How about following the convention at http://sandpile.org/x86/mode.htm ?

Currently, we can distinguish between RM16, VM16, (P/C)M{16,32} and
PM64, which is good enough for decoding the bytes correctly.

Alternatively, we could extend {vmx,svm}_guest_x86_mode() to provide a
rather more complete enum of processor modes and cover the other cases?

~Andrew

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

[Jan Beulich]

>>> On 26.09.14 at 14:57, <andrew.cooper3@citrix.com> wrote:
> On 26/09/14 13:41, Tim Deegan wrote:
>> At 13:09 +0100 on 26 Sep (1411733364), Andrew Cooper wrote:
>>> As identified in the other thread, "16bit" is misleading as the
>>> instruction bytes are actually 32bit code in a 16bit segment.
>>>
>>> I am not sure what the best solution here is.  Perhaps we can trust
>>> anyone capable of interpreting this error to know that "16b" != "Real"
>>> or "v86" when it comes to decoding the instruction.
>> Hmm.  I can see that 16bit is a bit misleading if you don't
>> know/remember that vm86 and real mode would be reported as such.  OTOH
>> that is infomration that's needed for decoding -- the instruction will
>> have 16bit operands and addresses even though it uses 32bit registers
>> and protected segments.
>>
>> Maybe we should report it as '16bit protected' or similar?
> 
> How about following the convention at http://sandpile.org/x86/mode.htm ?
> 
> Currently, we can distinguish between RM16, VM16, (P/C)M{16,32} and
> PM64, which is good enough for decoding the bytes correctly.
> 
> Alternatively, we could extend {vmx,svm}_guest_x86_mode() to provide a
> rather more complete enum of processor modes and cover the other cases?

None of this is relevant for instruction decoding. Even the 16-bit
protected / real / vm86 mode distinction is relevant there, that's
only useful as additional context.

Jan

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

[Andrew Cooper]

On 26/09/14 14:06, Jan Beulich wrote:
>>>> On 26.09.14 at 14:57, <andrew.cooper3@citrix.com> wrote:
>> On 26/09/14 13:41, Tim Deegan wrote:
>>> At 13:09 +0100 on 26 Sep (1411733364), Andrew Cooper wrote:
>>>> As identified in the other thread, "16bit" is misleading as the
>>>> instruction bytes are actually 32bit code in a 16bit segment.
>>>>
>>>> I am not sure what the best solution here is.  Perhaps we can trust
>>>> anyone capable of interpreting this error to know that "16b" != "Real"
>>>> or "v86" when it comes to decoding the instruction.
>>> Hmm.  I can see that 16bit is a bit misleading if you don't
>>> know/remember that vm86 and real mode would be reported as such.  OTOH
>>> that is infomration that's needed for decoding -- the instruction will
>>> have 16bit operands and addresses even though it uses 32bit registers
>>> and protected segments.
>>>
>>> Maybe we should report it as '16bit protected' or similar?
>> How about following the convention at http://sandpile.org/x86/mode.htm ?
>>
>> Currently, we can distinguish between RM16, VM16, (P/C)M{16,32} and
>> PM64, which is good enough for decoding the bytes correctly.
>>
>> Alternatively, we could extend {vmx,svm}_guest_x86_mode() to provide a
>> rather more complete enum of processor modes and cover the other cases?
> None of this is relevant for instruction decoding. Even the 16-bit
> protected / real / vm86 mode distinction is relevant there, that's
> only useful as additional context.

I presume you mean "is irrelevant there" ?

The question is whether we want to provide more or less context.

For now, I will move to just 16/32/64bit as it is the simpler course of
action.  More context can easily be added in the future, as extending
???_guest_x86_mode() will be quite invasive and we are currently in a
code freeze.

~Andrew

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

[Jan Beulich]

>>> On 26.09.14 at 15:16, <andrew.cooper3@citrix.com> wrote:
> On 26/09/14 14:06, Jan Beulich wrote:
>>>>> On 26.09.14 at 14:57, <andrew.cooper3@citrix.com> wrote:
>>> On 26/09/14 13:41, Tim Deegan wrote:
>>>> At 13:09 +0100 on 26 Sep (1411733364), Andrew Cooper wrote:
>>>>> As identified in the other thread, "16bit" is misleading as the
>>>>> instruction bytes are actually 32bit code in a 16bit segment.
>>>>>
>>>>> I am not sure what the best solution here is.  Perhaps we can trust
>>>>> anyone capable of interpreting this error to know that "16b" != "Real"
>>>>> or "v86" when it comes to decoding the instruction.
>>>> Hmm.  I can see that 16bit is a bit misleading if you don't
>>>> know/remember that vm86 and real mode would be reported as such.  OTOH
>>>> that is infomration that's needed for decoding -- the instruction will
>>>> have 16bit operands and addresses even though it uses 32bit registers
>>>> and protected segments.
>>>>
>>>> Maybe we should report it as '16bit protected' or similar?
>>> How about following the convention at http://sandpile.org/x86/mode.htm ?
>>>
>>> Currently, we can distinguish between RM16, VM16, (P/C)M{16,32} and
>>> PM64, which is good enough for decoding the bytes correctly.
>>>
>>> Alternatively, we could extend {vmx,svm}_guest_x86_mode() to provide a
>>> rather more complete enum of processor modes and cover the other cases?
>> None of this is relevant for instruction decoding. Even the 16-bit
>> protected / real / vm86 mode distinction is relevant there, that's
>> only useful as additional context.
> 
> I presume you mean "is irrelevant there" ?

Oops, yes, of course.

Jan

Re: [PATCH for-4.5 0/2] Improve "Emulation failed" error message

[Konrad Rzeszutek Wilk]

On Fri, Sep 26, 2014 at 11:10:05AM +0100, Andrew Cooper wrote:
> 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.
> 
> Konrad: I am requesting a release ack for this as it is a non-feature change
> for the purpose of improving error messages.  Neither of the patches are
> complicated (low risk of bugs/regressions), and if the worse comes to the
> worst, they can safely be reverted.

Yes. I think these can go in, even if they are not considered bug-fixes
but rather features to help developers/users in the field.

And conveniently I have an excellent test-case so I can test this
and make sure it does not cause regressions.

> 
> 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      |    6 ++++++
>  xen/arch/x86/hvm/emulate.c        |   41 +++++++++++++++++++++++++++++--------
>  xen/arch/x86/hvm/io.c             |   11 +---------
>  xen/arch/x86/hvm/vmx/realmode.c   |    9 +-------
>  xen/common/vsprintf.c             |   25 ++++++++++++++++++++++
>  xen/include/asm-x86/hvm/emulate.h |    3 +++
>  6 files changed, 68 insertions(+), 27 deletions(-)
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel