[PATCH] powerpc/64s: Fix irq tracing corruption in interrupt/syscall return caused by perf interrupts

Alexey reports lockdep_assert_irqs_enabled() warnings when stress testing perf, e.g.,

WARNING: CPU: 0 PID: 1556 at kernel/softirq.c:169 __local_bh_enable_ip+0x258/0x270
CPU: 0 PID: 1556 Comm: syz-executor
NIP:  c0000000001ec888 LR: c0000000001ec884 CTR: c000000000ef0610
REGS: c000000022d4f8a0 TRAP: 0700   Not tainted  (5.8.0-rc3-x)
MSR:  8000000000029033 <SF,EE,ME,IR,DR,RI,LE>  CR: 28008844  XER: 20040000
CFAR: c0000000001dc1d0 IRQMASK: 0

The interesting thing is MSR[EE] and IRQMASK shows interrupts are enabled,
suggesting the current->hardirqs_enabled irq tracing state is going out of sync
with the actual interrupt enable state.

The cause is a window in interrupt/syscall return where irq tracing state is being
adjusted for an irqs-enabled return while MSR[EE] is still enabled. A perf
interrupt hits and ends up calling trace_hardirqs_off() when restoring
interrupt flags to a disable state.

Fix this by disabling perf interrupts as well while adjusting irq tracing state.

Add a debug check that catches the condition sooner.

Fixes: 68b34588e202 ("powerpc/64/sycall: Implement syscall entry/exit logic in C")
Reported-by: Alexey Kardashevskiy <redacted>
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---

I can reproduce similar symptoms and this patch fixes my test case,
still trying to confirm Alexey's test case or whether there's another
similar bug causing it.

 arch/powerpc/kernel/syscall_64.c | 11 +++++++++--
 1 file changed, 9 insertions(+), 2 deletions(-)

diff --git a/arch/powerpc/kernel/syscall_64.c b/arch/powerpc/kernel/syscall_64.c
index 79edba3ab312..6c6f88eff915 100644
--- a/arch/powerpc/kernel/syscall_64.c
+++ b/arch/powerpc/kernel/syscall_64.c

@@ -107,8 +107,13 @@ notrace long system_call_exception(long r3, long r4, long r5,
  */
 static notrace inline bool prep_irq_for_enabled_exit(void)
 {
-	/* This must be done with RI=1 because tracing may touch vmaps */
-	trace_hardirqs_on();
+	if (IS_ENABLED(CONFIG_TRACE_IRQFLAGS)) {
+		/* Prevent perf interrupts hitting and messing up the trace_hardirqs state */
+		irq_soft_mask_set(IRQS_ALL_DISABLED);
+
+		/* This must be done with RI=1 because tracing may touch vmaps */
+		trace_hardirqs_on();
+	}
 
 	/* This pattern matches prep_irq_for_idle */
 	__hard_EE_RI_disable();

@@ -123,6 +128,8 @@ static notrace inline bool prep_irq_for_enabled_exit(void)
 	local_paca->irq_happened = 0;
 	irq_soft_mask_set(IRQS_ENABLED);
 
+	lockdep_assert_irqs_enabled();
+
 	return true;
 }
 

-- 
2.23.0

On 22/07/2020 17:34, Nicholas Piggin wrote:

Alexey reports lockdep_assert_irqs_enabled() warnings when stress testing perf, e.g.,

WARNING: CPU: 0 PID: 1556 at kernel/softirq.c:169 __local_bh_enable_ip+0x258/0x270
CPU: 0 PID: 1556 Comm: syz-executor
NIP:  c0000000001ec888 LR: c0000000001ec884 CTR: c000000000ef0610
REGS: c000000022d4f8a0 TRAP: 0700   Not tainted  (5.8.0-rc3-x)
MSR:  8000000000029033 <SF,EE,ME,IR,DR,RI,LE>  CR: 28008844  XER: 20040000
CFAR: c0000000001dc1d0 IRQMASK: 0

The interesting thing is MSR[EE] and IRQMASK shows interrupts are enabled,
suggesting the current->hardirqs_enabled irq tracing state is going out of sync
with the actual interrupt enable state.

The cause is a window in interrupt/syscall return where irq tracing state is being
adjusted for an irqs-enabled return while MSR[EE] is still enabled. A perf
interrupt hits and ends up calling trace_hardirqs_off() when restoring
interrupt flags to a disable state.

Fix this by disabling perf interrupts as well while adjusting irq tracing state.

Add a debug check that catches the condition sooner.

Fixes: 68b34588e202 ("powerpc/64/sycall: Implement syscall entry/exit logic in C")
Reported-by: Alexey Kardashevskiy <redacted>
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---

I can reproduce similar symptoms and this patch fixes my test case,
still trying to confirm Alexey's test case or whether there's another
similar bug causing it.

This does not fix my testcase. I applied this on top of 4fa640dc5230
("Merge tag 'vfio-v5.8-rc7' of git://github.com/awilliam/linux-vfio into
master")  without any of my testing code, just to be clear. Sorry...

-- 
Alexey

Excerpts from Alexey Kardashevskiy's message of July 22, 2020 8:50 pm:

On 22/07/2020 17:34, Nicholas Piggin wrote:

quoted

Alexey reports lockdep_assert_irqs_enabled() warnings when stress testing perf, e.g.,

WARNING: CPU: 0 PID: 1556 at kernel/softirq.c:169 __local_bh_enable_ip+0x258/0x270
CPU: 0 PID: 1556 Comm: syz-executor
NIP:  c0000000001ec888 LR: c0000000001ec884 CTR: c000000000ef0610
REGS: c000000022d4f8a0 TRAP: 0700   Not tainted  (5.8.0-rc3-x)
MSR:  8000000000029033 <SF,EE,ME,IR,DR,RI,LE>  CR: 28008844  XER: 20040000
CFAR: c0000000001dc1d0 IRQMASK: 0

The interesting thing is MSR[EE] and IRQMASK shows interrupts are enabled,
suggesting the current->hardirqs_enabled irq tracing state is going out of sync
with the actual interrupt enable state.

The cause is a window in interrupt/syscall return where irq tracing state is being
adjusted for an irqs-enabled return while MSR[EE] is still enabled. A perf
interrupt hits and ends up calling trace_hardirqs_off() when restoring
interrupt flags to a disable state.

Fix this by disabling perf interrupts as well while adjusting irq tracing state.

Add a debug check that catches the condition sooner.

Fixes: 68b34588e202 ("powerpc/64/sycall: Implement syscall entry/exit logic in C")
Reported-by: Alexey Kardashevskiy <redacted>
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---

I can reproduce similar symptoms and this patch fixes my test case,
still trying to confirm Alexey's test case or whether there's another
similar bug causing it.

This does not fix my testcase. I applied this on top of 4fa640dc5230
("Merge tag 'vfio-v5.8-rc7' of git://github.com/awilliam/linux-vfio into
master")  without any of my testing code, just to be clear. Sorry...

Okay it seems to be a bigger problem and not actually caused by that
patch but was possible for lockdep hardirqs_enabled state to get out 
of synch with the local_irq_disable() state before that too. Root
cause is similar -- perf interrupts hitting between updating the two
different bits of state.

Not quite sure why Alexey's test wasn't hitting it before the patch,
but possibly the way masked interrupts get replayed. But I was able
to hit the problem with a different assertion.

I think I have a fix, but it seems to be a generic irq tracing code
issue. So this patch can be dropped, and it's not an urgent issue for
the next release (it only triggers warns on rare occasions and only
when lockdep is enabled).

Thanks,
Nick

On 23/07/2020 20:29, Nicholas Piggin wrote:

Excerpts from Alexey Kardashevskiy's message of July 22, 2020 8:50 pm:

quoted

On 22/07/2020 17:34, Nicholas Piggin wrote:

quoted

Alexey reports lockdep_assert_irqs_enabled() warnings when stress testing perf, e.g.,

WARNING: CPU: 0 PID: 1556 at kernel/softirq.c:169 __local_bh_enable_ip+0x258/0x270
CPU: 0 PID: 1556 Comm: syz-executor
NIP:  c0000000001ec888 LR: c0000000001ec884 CTR: c000000000ef0610
REGS: c000000022d4f8a0 TRAP: 0700   Not tainted  (5.8.0-rc3-x)
MSR:  8000000000029033 <SF,EE,ME,IR,DR,RI,LE>  CR: 28008844  XER: 20040000
CFAR: c0000000001dc1d0 IRQMASK: 0

The interesting thing is MSR[EE] and IRQMASK shows interrupts are enabled,
suggesting the current->hardirqs_enabled irq tracing state is going out of sync
with the actual interrupt enable state.

The cause is a window in interrupt/syscall return where irq tracing state is being
adjusted for an irqs-enabled return while MSR[EE] is still enabled. A perf
interrupt hits and ends up calling trace_hardirqs_off() when restoring
interrupt flags to a disable state.

Fix this by disabling perf interrupts as well while adjusting irq tracing state.

Add a debug check that catches the condition sooner.

Fixes: 68b34588e202 ("powerpc/64/sycall: Implement syscall entry/exit logic in C")
Reported-by: Alexey Kardashevskiy <redacted>
Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---

I can reproduce similar symptoms and this patch fixes my test case,
still trying to confirm Alexey's test case or whether there's another
similar bug causing it.

This does not fix my testcase. I applied this on top of 4fa640dc5230
("Merge tag 'vfio-v5.8-rc7' of git://github.com/awilliam/linux-vfio into
master")  without any of my testing code, just to be clear. Sorry...

Okay it seems to be a bigger problem and not actually caused by that
patch but was possible for lockdep hardirqs_enabled state to get out 
of synch with the local_irq_disable() state before that too. Root
cause is similar -- perf interrupts hitting between updating the two
different bits of state.

Not quite sure why Alexey's test wasn't hitting it before the patch,
but possibly the way masked interrupts get replayed. But I was able
to hit the problem with a different assertion.

I think I have a fix, but it seems to be a generic irq tracing code
issue. So this patch can be dropped, and it's not an urgent issue for
the next release (it only triggers warns on rare occasions and only
when lockdep is enabled).

I would still like to understand how the last
curr->hardirq_disable_event misses the ftrace buffer and we end up in
the original interrupted kernel code...


-- 
Alexey