[PATCH] x86/traps: Misc tweaks to several printk()s

[PATCH] x86/traps: Misc tweaks to several printk()s

[Andrew Cooper]

* Reword the printk() in do_guest_trap() to avoid
    "Unhandled general protection fault fault/trap"
* Drop irrelevant file/line references.
* Make some of the text more concise.
* A trap with an extable entry does not warrant an error level message.
* Use %ps for extable sources to provide extra context.
* Always log emulated rdmsr failures, like wrmsr failures

Sample new messages are:

(XEN) d0v0 attempted WRMSR 0x00000174: 0x000000000000e008 -> 0x0000000000000010

(XEN) Exception [#0, ec=0000] (divide error): do_extreme_debug+0x36/0x51 ffff82d08018ca67 -> ffff82d08023cc4c

(XEN) #GP[0000]: do_general_protection+0x2fbf/0x34e0 ffff82d080193407 -> ffff82d08023cd8f
(XEN) d1v0 attempted RDMSR 0xdead0000
(XEN) d1v0 Unhandled exception [#13, ec=0000] general protection fault

Signed-off-by: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Jan Beulich <JBeulich@suse.com>
---
 xen/arch/x86/traps.c |   24 +++++++++++++-----------
 1 file changed, 13 insertions(+), 11 deletions(-)

diff --git a/xen/arch/x86/traps.c b/xen/arch/x86/traps.c
index 556c5be..2fef93d 100644
--- a/xen/arch/x86/traps.c
+++ b/xen/arch/x86/traps.c
@@ -521,8 +521,8 @@ static void do_guest_trap(
 
     if ( unlikely(null_trap_bounce(v, tb)) )
         gprintk(XENLOG_WARNING,
-                "Unhandled %s fault/trap [#%d, ec=%04x]\n",
-                trapstr(trapnr), trapnr, regs->error_code);
+                "Unhandled exception [#%d, ec=%04x] %s\n",
+                trapnr, regs->error_code, trapstr(trapnr));
 }
 
 static void instruction_done(
@@ -626,8 +626,9 @@ static void do_trap(struct cpu_user_regs *regs, int use_error_code)
 
     if ( likely((fixup = search_exception_table(regs->eip)) != 0) )
     {
-        dprintk(XENLOG_ERR, "Trap %d: %p -> %p\n",
-                trapnr, _p(regs->eip), _p(fixup));
+        printk(XENLOG_INFO "Exception [#%d, ec=%04x] (%s): %ps %p -> %p\n",
+               trapnr, use_error_code ? regs->error_code : 0, trapstr(trapnr),
+               _p(regs->eip), _p(regs->eip), _p(fixup));
         this_cpu(last_extable_addr) = regs->eip;
         regs->eip = fixup;
         return;
@@ -2677,9 +2678,9 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
 
             if ( (rdmsr_safe(regs->ecx, val) != 0) || (msr_content != val) )
         invalid:
-                gdprintk(XENLOG_WARNING, "Domain attempted WRMSR %p from "
-                        "0x%016"PRIx64" to 0x%016"PRIx64".\n",
-                        _p(regs->ecx), val, msr_content);
+                gprintk(XENLOG_WARNING,
+                        "attempted WRMSR 0x%08x: 0x%016"PRIx64" -> 0x%016"PRIx64"\n",
+                        regs->_ecx, val, msr_content);
             break;
         }
         break;
@@ -2813,10 +2814,11 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
         case MSR_EFER:
  rdmsr_normal:
             /* Everyone can read the MSR space. */
-            /* gdprintk(XENLOG_WARNING,"Domain attempted RDMSR %p.\n",
-                        _p(regs->ecx));*/
             if ( rdmsr_safe(regs->ecx, val) )
+            {
+                gprintk(XENLOG_WARNING, "attempted RDMSR 0x%08x\n", regs->_ecx);
                 goto fail;
+            }
  rdmsr_writeback:
             regs->eax = (uint32_t)val;
             regs->edx = (uint32_t)(val >> 32);
@@ -3283,8 +3285,8 @@ void do_general_protection(struct cpu_user_regs *regs)
 
     if ( likely((fixup = search_exception_table(regs->eip)) != 0) )
     {
-        dprintk(XENLOG_INFO, "GPF (%04x): %p -> %p\n",
-                regs->error_code, _p(regs->eip), _p(fixup));
+        printk(XENLOG_INFO "#GP[%04x]: %ps %p -> %p\n",
+               regs->error_code, _p(regs->eip), _p(regs->eip) , _p(fixup));
         this_cpu(last_extable_addr) = regs->eip;
         regs->eip = fixup;
         return;
-- 
1.7.10.4

Re: [PATCH] x86/traps: Misc tweaks to several printk()s

[Jan Beulich]

>>> On 14.07.15 at 19:54, <andrew.cooper3@citrix.com> wrote:
> @@ -626,8 +626,9 @@ static void do_trap(struct cpu_user_regs *regs, int use_error_code)
>  
>      if ( likely((fixup = search_exception_table(regs->eip)) != 0) )
>      {
> -        dprintk(XENLOG_ERR, "Trap %d: %p -> %p\n",
> -                trapnr, _p(regs->eip), _p(fixup));
> +        printk(XENLOG_INFO "Exception [#%d, ec=%04x] (%s): %ps %p -> %p\n",
> +               trapnr, use_error_code ? regs->error_code : 0, trapstr(trapnr),
> +               _p(regs->eip), _p(regs->eip), _p(fixup));

But why the transition dprintk() -> printk()?

> @@ -2677,9 +2678,9 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
>  
>              if ( (rdmsr_safe(regs->ecx, val) != 0) || (msr_content != val) )
>          invalid:
> -                gdprintk(XENLOG_WARNING, "Domain attempted WRMSR %p from "
> -                        "0x%016"PRIx64" to 0x%016"PRIx64".\n",
> -                        _p(regs->ecx), val, msr_content);
> +                gprintk(XENLOG_WARNING,
> +                        "attempted WRMSR 0x%08x: 0x%016"PRIx64" -> 0x%016"PRIx64"\n",
> +                        regs->_ecx, val, msr_content);

In cases where the values can't usefully be taken to be decimal I'd
prefer the 0x prefixes to be omitted.

> @@ -2813,10 +2814,11 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
>          case MSR_EFER:
>   rdmsr_normal:
>              /* Everyone can read the MSR space. */
> -            /* gdprintk(XENLOG_WARNING,"Domain attempted RDMSR %p.\n",
> -                        _p(regs->ecx));*/
>              if ( rdmsr_safe(regs->ecx, val) )
> +            {
> +                gprintk(XENLOG_WARNING, "attempted RDMSR 0x%08x\n", regs->_ecx);
>                  goto fail;
> +            }

Do you really see this to be useful in production builds?

Jan

Re: [PATCH] x86/traps: Misc tweaks to several printk()s

[Andrew Cooper]

On 15/07/15 10:03, Jan Beulich wrote:
>>>> On 14.07.15 at 19:54, <andrew.cooper3@citrix.com> wrote:
>> @@ -626,8 +626,9 @@ static void do_trap(struct cpu_user_regs *regs, int use_error_code)
>>  
>>      if ( likely((fixup = search_exception_table(regs->eip)) != 0) )
>>      {
>> -        dprintk(XENLOG_ERR, "Trap %d: %p -> %p\n",
>> -                trapnr, _p(regs->eip), _p(fixup));
>> +        printk(XENLOG_INFO "Exception [#%d, ec=%04x] (%s): %ps %p -> %p\n",
>> +               trapnr, use_error_code ? regs->error_code : 0, trapstr(trapnr),
>> +               _p(regs->eip), _p(regs->eip), _p(fixup));
> But why the transition dprintk() -> printk()?

The file/line reference here is not useful, but now that you point it
out I had forgotten to consider that dprintk() now only exists in debug
builds.

It would be nice to have a variant on printk() which is restricted to
debug builds, but doesn't have a file/line reference.

>
>> @@ -2677,9 +2678,9 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
>>  
>>              if ( (rdmsr_safe(regs->ecx, val) != 0) || (msr_content != val) )
>>          invalid:
>> -                gdprintk(XENLOG_WARNING, "Domain attempted WRMSR %p from "
>> -                        "0x%016"PRIx64" to 0x%016"PRIx64".\n",
>> -                        _p(regs->ecx), val, msr_content);
>> +                gprintk(XENLOG_WARNING,
>> +                        "attempted WRMSR 0x%08x: 0x%016"PRIx64" -> 0x%016"PRIx64"\n",
>> +                        regs->_ecx, val, msr_content);
> In cases where the values can't usefully be taken to be decimal I'd
> prefer the 0x prefixes to be omitted.
>
>> @@ -2813,10 +2814,11 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
>>          case MSR_EFER:
>>   rdmsr_normal:
>>              /* Everyone can read the MSR space. */
>> -            /* gdprintk(XENLOG_WARNING,"Domain attempted RDMSR %p.\n",
>> -                        _p(regs->ecx));*/
>>              if ( rdmsr_safe(regs->ecx, val) )
>> +            {
>> +                gprintk(XENLOG_WARNING, "attempted RDMSR 0x%08x\n", regs->_ecx);
>>                  goto fail;
>> +            }
> Do you really see this to be useful in production builds?

There is currently an asymmetry between the WRMSR and RDMSR paths, which
shouldn't exist IMO.

Guest warning is rate limited by default, and anecdotally, this path
doesn't trigger by default on any of my test boxes with a 3.10 pvops kernel.

~Andrew

Re: [PATCH] x86/traps: Misc tweaks to several printk()s

[Jan Beulich]

>>> On 15.07.15 at 11:48, <andrew.cooper3@citrix.com> wrote:
> On 15/07/15 10:03, Jan Beulich wrote:
>>>>> On 14.07.15 at 19:54, <andrew.cooper3@citrix.com> wrote:
>>> @@ -626,8 +626,9 @@ static void do_trap(struct cpu_user_regs *regs, int 
> use_error_code)
>>>  
>>>      if ( likely((fixup = search_exception_table(regs->eip)) != 0) )
>>>      {
>>> -        dprintk(XENLOG_ERR, "Trap %d: %p -> %p\n",
>>> -                trapnr, _p(regs->eip), _p(fixup));
>>> +        printk(XENLOG_INFO "Exception [#%d, ec=%04x] (%s): %ps %p -> %p\n",
>>> +               trapnr, use_error_code ? regs->error_code : 0, 
> trapstr(trapnr),
>>> +               _p(regs->eip), _p(regs->eip), _p(fixup));
>> But why the transition dprintk() -> printk()?
> 
> The file/line reference here is not useful, but now that you point it
> out I had forgotten to consider that dprintk() now only exists in debug
> builds.
> 
> It would be nice to have a variant on printk() which is restricted to
> debug builds, but doesn't have a file/line reference.

But otoh the file/line pair shouldn't cause a lot of confusion - debug
build users can certainly be expected to cope with that. Which isn't
to say that I'd even consider making dprintk() by default not print
file/line, and instead have a dprintk_at() or DPRINTK() doing so for
those who really can't write distinguishable messages.

>>> @@ -2813,10 +2814,11 @@ static int emulate_privileged_op(struct cpu_user_regs *regs)
>>>          case MSR_EFER:
>>>   rdmsr_normal:
>>>              /* Everyone can read the MSR space. */
>>> -            /* gdprintk(XENLOG_WARNING,"Domain attempted RDMSR %p.\n",
>>> -                        _p(regs->ecx));*/
>>>              if ( rdmsr_safe(regs->ecx, val) )
>>> +            {
>>> +                gprintk(XENLOG_WARNING, "attempted RDMSR 0x%08x\n", regs->_ecx);
>>>                  goto fail;
>>> +            }
>> Do you really see this to be useful in production builds?
> 
> There is currently an asymmetry between the WRMSR and RDMSR paths, which
> shouldn't exist IMO.

I'm of the opposite opinion: Knowing that (just like we do) guest
kernels may access MSRs being prepared to get a #GP, and this
(naturally) being more likely on RDMSR (why would one try to write
an MSR one can't read?), the asymmetry has a reason.

> Guest warning is rate limited by default, and anecdotally, this path
> doesn't trigger by default on any of my test boxes with a 3.10 pvops kernel.

Which is nice to know, but not nearly enough to assume we won't get
flooded (ignoring the rate limiting) by these for other guest kernels.

Jan