[PATCH 0/2] target/arm: Improve M-profile exception logging

[PATCH 0/2] target/arm: Improve M-profile exception logging

[Peter Maydell]

Our current logging for M-profile exceptions has a couple of holes
which are particularly confusing for the case of an exception taken
immediately out of reset:
 * we don't log the initial PC/SP loaded from the vector table
 * we don't log the PC we load from the vector table when
   we take an exception
 * we don't log the address for i-side aborts

This case is quite common where the user has failed to provide a
vector table in their ELF file and QEMU thus loads garbage for the
initial PC. At the moment the logging looks like:

$ qemu-system-arm [...] -d in_asm,cpu,exec,int
Taking exception 3 [Prefetch Abort] on CPU 0
...with CFSR.IACCVIOL
...BusFault with BFSR.STKERR
...taking pending nonsecure exception 3
----------------
IN: 
0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}


After this patchset it looks like:

$ qemu-system-arm [...] -d in_asm,cpu,exec,int
Loaded reset SP 0x0 PC 0x0 from vector table
Loaded reset SP 0xd008f8df PC 0xf000bf00 from vector table
Taking exception 3 [Prefetch Abort] on CPU 0
...at fault address 0xf000bf00
...with CFSR.IACCVIOL
...BusFault with BFSR.STKERR
...taking pending nonsecure exception 3
...loading from element 3 of non-secure vector table at 0xc
...loaded new PC 0x20000558
----------------
IN: 
0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}

and I think it is somewhat clearer that we loaded a bogus
PC from the vector table at reset, faulted at that address,
loaded the HardFault entry point which was bogus but at
least readable, and started executing code from there.

The double-logging of the reset loads is the result of
the way we currently reset the CPU twice on QEMU startup.
If we ever manage to fix that silliness it'll go away.


(Patchset inspired by a stackexchange question:
https://stackoverflow.com/questions/71486314/loading-an-elf-file-into-qemu
)

thanks
-- PMM

Peter Maydell (2):
  target/arm: Log M-profile vector table accesses
  target/arm: Log fault address for M-profile faults

 target/arm/cpu.c      |  5 +++++
 target/arm/m_helper.c | 11 +++++++++++
 2 files changed, 16 insertions(+)

-- 
2.25.1

[PATCH 1/2] target/arm: Log M-profile vector table accesses

[Peter Maydell]

Currently the CPU_LOG_INT logging misses some useful information
about loads from the vector table.  Add logging where we load vector
table entries.  This is particularly helpful for cases where the user
has accidentally not put a vector table in their image at all, which
can result in confusing guest crashes at startup.

Here's an example of the new logging for a case where
the vector table contains garbage:

Loaded reset SP 0x0 PC 0x0 from vector table
Loaded reset SP 0xd008f8df PC 0xf000bf00 from vector table
Taking exception 3 [Prefetch Abort] on CPU 0
...with CFSR.IACCVIOL
...BusFault with BFSR.STKERR
...taking pending nonsecure exception 3
...loading from element 3 of non-secure vector table at 0xc
...loaded new PC 0x20000558
----------------
IN:
0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}

(The double reset logging is the result of our long-standing
"CPUs all get reset twice" weirdness; it looks a bit ugly
but it'll go away if we ever fix that :-))

Signed-off-by: Peter Maydell <peter.maydell@linaro.org>
---
 target/arm/cpu.c      | 5 +++++
 target/arm/m_helper.c | 5 +++++
 2 files changed, 10 insertions(+)

diff --git a/target/arm/cpu.c b/target/arm/cpu.c
index 185d4e774d5..498fb9f71b3 100644
--- a/target/arm/cpu.c
+++ b/target/arm/cpu.c
@@ -21,6 +21,7 @@
 #include "qemu/osdep.h"
 #include "qemu/qemu-print.h"
 #include "qemu/timer.h"
+#include "qemu/log.h"
 #include "qemu-common.h"
 #include "target/arm/idau.h"
 #include "qemu/module.h"
@@ -366,6 +367,10 @@ static void arm_cpu_reset(DeviceState *dev)
             initial_pc = ldl_phys(s->as, vecbase + 4);
         }
 
+        qemu_log_mask(CPU_LOG_INT,
+                      "Loaded reset SP 0x%x PC 0x%x from vector table\n",
+                      initial_msp, initial_pc);
+
         env->regs[13] = initial_msp & 0xFFFFFFFC;
         env->regs[15] = initial_pc & ~1;
         env->thumb = initial_pc & 1;
diff --git a/target/arm/m_helper.c b/target/arm/m_helper.c
index 648a3b3fc16..3bd16c0c465 100644
--- a/target/arm/m_helper.c
+++ b/target/arm/m_helper.c
@@ -679,6 +679,10 @@ static bool arm_v7m_load_vector(ARMCPU *cpu, int exc, bool targets_secure,
     ARMMMUIdx mmu_idx;
     bool exc_secure;
 
+    qemu_log_mask(CPU_LOG_INT,
+                  "...loading from element %d of %s vector table at 0x%x\n",
+                  exc, targets_secure ? "secure" : "non-secure", addr);
+
     mmu_idx = arm_v7m_mmu_idx_for_secstate_and_priv(env, targets_secure, true);
 
     /*
@@ -719,6 +723,7 @@ static bool arm_v7m_load_vector(ARMCPU *cpu, int exc, bool targets_secure,
         goto load_fail;
     }
     *pvec = vector_entry;
+    qemu_log_mask(CPU_LOG_INT, "...loaded new PC 0x%x\n", *pvec);
     return true;
 
 load_fail:
-- 
2.25.1

Re: [PATCH 1/2] target/arm: Log M-profile vector table accesses

[Richard Henderson]

On 3/15/22 13:43, Peter Maydell wrote:
> Currently the CPU_LOG_INT logging misses some useful information
> about loads from the vector table.  Add logging where we load vector
> table entries.  This is particularly helpful for cases where the user
> has accidentally not put a vector table in their image at all, which
> can result in confusing guest crashes at startup.
> 
> Here's an example of the new logging for a case where
> the vector table contains garbage:
> 
> Loaded reset SP 0x0 PC 0x0 from vector table
> Loaded reset SP 0xd008f8df PC 0xf000bf00 from vector table
> Taking exception 3 [Prefetch Abort] on CPU 0
> ...with CFSR.IACCVIOL
> ...BusFault with BFSR.STKERR
> ...taking pending nonsecure exception 3
> ...loading from element 3 of non-secure vector table at 0xc
> ...loaded new PC 0x20000558
> ----------------
> IN:
> 0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}
> 
> (The double reset logging is the result of our long-standing
> "CPUs all get reset twice" weirdness; it looks a bit ugly
> but it'll go away if we ever fix that :-))
> 
> Signed-off-by: Peter Maydell<peter.maydell@linaro.org>
> ---
>   target/arm/cpu.c      | 5 +++++
>   target/arm/m_helper.c | 5 +++++
>   2 files changed, 10 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

Re: [PATCH 1/2] target/arm: Log M-profile vector table accesses

[Alex Bennée]

Peter Maydell <peter.maydell@linaro.org> writes:

> Currently the CPU_LOG_INT logging misses some useful information
> about loads from the vector table.  Add logging where we load vector
> table entries.  This is particularly helpful for cases where the user
> has accidentally not put a vector table in their image at all, which
> can result in confusing guest crashes at startup.
>
> Here's an example of the new logging for a case where
> the vector table contains garbage:
>
> Loaded reset SP 0x0 PC 0x0 from vector table
> Loaded reset SP 0xd008f8df PC 0xf000bf00 from vector table
> Taking exception 3 [Prefetch Abort] on CPU 0
> ...with CFSR.IACCVIOL
> ...BusFault with BFSR.STKERR
> ...taking pending nonsecure exception 3
> ...loading from element 3 of non-secure vector table at 0xc
> ...loaded new PC 0x20000558
> ----------------
> IN:
> 0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}
>
> (The double reset logging is the result of our long-standing
> "CPUs all get reset twice" weirdness; it looks a bit ugly
> but it'll go away if we ever fix that :-))
>
> Signed-off-by: Peter Maydell <peter.maydell@linaro.org>

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

-- 
Alex Bennée

[PATCH 2/2] target/arm: Log fault address for M-profile faults

[Peter Maydell]

For M-profile, the fault address is not always exposed to the guest
in a fault register (for instance the BFAR bus fault address register
is only updated for bus faults on data accesses, not instruction
accesses).  Currently we log the address only if we're putting it
into a particular guest-visible register.  Since we always have it,
log it generically, to make logs of i-side faults a bit clearer.

Signed-off-by: Peter Maydell <peter.maydell@linaro.org>
---
 target/arm/m_helper.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/target/arm/m_helper.c b/target/arm/m_helper.c
index 3bd16c0c465..b7a0fe01141 100644
--- a/target/arm/m_helper.c
+++ b/target/arm/m_helper.c
@@ -2272,7 +2272,13 @@ void arm_v7m_cpu_do_interrupt(CPUState *cs)
          * Note that for M profile we don't have a guest facing FSR, but
          * the env->exception.fsr will be populated by the code that
          * raises the fault, in the A profile short-descriptor format.
+         *
+         * Log the exception.vaddress now regardless of subtype, because
+         * logging below only logs it when it goes into a guest visible
+         * register.
          */
+        qemu_log_mask(CPU_LOG_INT, "...at fault address 0x%x\n",
+                      (uint32_t)env->exception.vaddress);
         switch (env->exception.fsr & 0xf) {
         case M_FAKE_FSR_NSC_EXEC:
             /*
-- 
2.25.1

Re: [PATCH 2/2] target/arm: Log fault address for M-profile faults

[Richard Henderson]

On 3/15/22 13:43, Peter Maydell wrote:
> For M-profile, the fault address is not always exposed to the guest
> in a fault register (for instance the BFAR bus fault address register
> is only updated for bus faults on data accesses, not instruction
> accesses).  Currently we log the address only if we're putting it
> into a particular guest-visible register.  Since we always have it,
> log it generically, to make logs of i-side faults a bit clearer.
> 
> Signed-off-by: Peter Maydell<peter.maydell@linaro.org>
> ---
>   target/arm/m_helper.c | 6 ++++++
>   1 file changed, 6 insertions(+)

Reviewed-by: Richard Henderson <richard.henderson@linaro.org>

r~

Re: [PATCH 2/2] target/arm: Log fault address for M-profile faults

[Alex Bennée]

Peter Maydell <peter.maydell@linaro.org> writes:

> For M-profile, the fault address is not always exposed to the guest
> in a fault register (for instance the BFAR bus fault address register
> is only updated for bus faults on data accesses, not instruction
> accesses).  Currently we log the address only if we're putting it
> into a particular guest-visible register.  Since we always have it,
> log it generically, to make logs of i-side faults a bit clearer.
>
> Signed-off-by: Peter Maydell <peter.maydell@linaro.org>

Reviewed-by: Alex Bennée <alex.bennee@linaro.org>

-- 
Alex Bennée

Re: [PATCH 0/2] target/arm: Improve M-profile exception logging

[Philippe Mathieu-Daudé]

On 15/3/22 21:43, Peter Maydell wrote:
> Our current logging for M-profile exceptions has a couple of holes
> which are particularly confusing for the case of an exception taken
> immediately out of reset:
>   * we don't log the initial PC/SP loaded from the vector table
>   * we don't log the PC we load from the vector table when
>     we take an exception
>   * we don't log the address for i-side aborts
> 
> This case is quite common where the user has failed to provide a
> vector table in their ELF file and QEMU thus loads garbage for the
> initial PC. At the moment the logging looks like:
> 
> $ qemu-system-arm [...] -d in_asm,cpu,exec,int
> Taking exception 3 [Prefetch Abort] on CPU 0
> ...with CFSR.IACCVIOL
> ...BusFault with BFSR.STKERR
> ...taking pending nonsecure exception 3
> ----------------
> IN:
> 0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}
> 
> 
> After this patchset it looks like:
> 
> $ qemu-system-arm [...] -d in_asm,cpu,exec,int
> Loaded reset SP 0x0 PC 0x0 from vector table
> Loaded reset SP 0xd008f8df PC 0xf000bf00 from vector table
> Taking exception 3 [Prefetch Abort] on CPU 0
> ...at fault address 0xf000bf00
> ...with CFSR.IACCVIOL
> ...BusFault with BFSR.STKERR
> ...taking pending nonsecure exception 3
> ...loading from element 3 of non-secure vector table at 0xc
> ...loaded new PC 0x20000558
> ----------------
> IN:
> 0x20000558:  08000079  stmdaeq  r0, {r0, r3, r4, r5, r6}
> 
> and I think it is somewhat clearer that we loaded a bogus
> PC from the vector table at reset, faulted at that address,
> loaded the HardFault entry point which was bogus but at
> least readable, and started executing code from there.
> 
> The double-logging of the reset loads is the result of
> the way we currently reset the CPU twice on QEMU startup.
> If we ever manage to fix that silliness it'll go away.
> 
> 
> (Patchset inspired by a stackexchange question:
> https://stackoverflow.com/questions/71486314/loading-an-elf-file-into-qemu
> )
> 
> thanks
> -- PMM
> 
> Peter Maydell (2):
>    target/arm: Log M-profile vector table accesses
>    target/arm: Log fault address for M-profile faults

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>