[PATCH] usbhid: Fix lockdep unannotated irqs-off warning

When compiling Linux v4.2+ and v4.3-rc2+ with a llvmlinux patchset
and CLANG v3.7 I see a BUG line like this:

[   24.705463] BUG: sleeping function called from invalid context at kernel/workqueue.c:2680
[   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid

After some vital help from workqueue and hid folks it turned out to be
a problem in the hid area.

Jiri encouraged me to look into del_timer-sync()/cancel_work_sync().
So, I disassembled kernel/time/timer.o.
This looked good.

Both functions are called in hid_cancel_delayed_stuff().
Adding a might_sleep() on top of it showed hints towards lockdep and
unannotated irqs-off.

[   23.723807] WARNING: CPU: 0 PID: 1451 at kernel/locking/lockdep.c:3519 check_flags+0x6c/0x1b0()
[   23.723866] DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled)
...
[   23.774719] possible reason: unannotated irqs-off.

Dealing with irqflags-tracing I enabled some helpful kernel-options:

CONFIG_LOCKDEP=y
CONFIG_DEBUG_LOCKDEP=y
CONFIG_TRACING=y
CONFIG_TRACE_IRQFLAGS=y
CONFIG_IRQSOFF_TRACER=y

The file irqflags-tracing.txt was helpful.
Steven Rostedt pointed me to the irqsoff section in ftrace.txt documentation.

Then, I tried to force to turn off the tracing of hardirqs in usbhid_close()
via trace_hardirqs_off() - line by line.
Finally, the spin_unlock_irq() within the if-statement looked like the culprit.

Looking through commits having a similiar issue, I replaced spin_{un}lock_irq()
with spin_{un}lock_bh() as this doesn't need interrupts disabled.

This fixed the issue for me.

Tested against Linux v4.3-rc3.

Still unsure why the same kernel built with GCC v4.9 does not show this.

Thanks to all involved people.

[1] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/irqflags-tracing.txt
[2] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/trace/ftrace.txt#n906

CC: Jiri Kosina <jikos@kernel.org>
CC: linux-input@vger.kernel.org
CC: Tejun Heo <tj@kernel.org>
CC: Lai Jiangshan <jiangshanlai@gmail.com>
CC: Steven Rostedt <rostedt@goodmis.org>
CC: Paul McKenney <redacted>

---
 drivers/hid/usbhid/hid-core.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 36712e9f56c2..188f59348ec5 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c

@@ -729,16 +729,16 @@ void usbhid_close(struct hid_device *hid)
 	 * data acquistion due to a resumption we no longer
 	 * care about
 	 */
-	spin_lock_irq(&usbhid->lock);
+	spin_lock_bh(&usbhid->lock);
 	if (!--hid->open) {
-		spin_unlock_irq(&usbhid->lock);
+		spin_unlock_bh(&usbhid->lock);
 		hid_cancel_delayed_stuff(usbhid);
 		if (!(hid->quirks & HID_QUIRK_ALWAYS_POLL)) {
 			usb_kill_urb(usbhid->urbin);
 			usbhid->intf->needs_remote_wakeup = 0;
 		}
 	} else {
-		spin_unlock_irq(&usbhid->lock);
+		spin_unlock_bh(&usbhid->lock);
 	}
 	mutex_unlock(&hid_open_mut);
 }

-- 
2.5.3

On Mon, 28 Sep 2015, Sedat Dilek wrote:

When compiling Linux v4.2+ and v4.3-rc2+ with a llvmlinux patchset
and CLANG v3.7 I see a BUG line like this:

[   24.705463] BUG: sleeping function called from invalid context at kernel/workqueue.c:2680
[   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid

After some vital help from workqueue and hid folks it turned out to be
a problem in the hid area.

Jiri encouraged me to look into del_timer-sync()/cancel_work_sync().
So, I disassembled kernel/time/timer.o.
This looked good.

Both functions are called in hid_cancel_delayed_stuff().

Yeah, but we're enabling IRQs before calling hid_cancel_delayed_stuff() 
(or, to be more precise, we're restoring original flags, and I don't see 
usbhid_close() being called with IRQs off).

Therefore ...

[ ... snip ... ]

I still don't understand how this should be improving anything. I believe 
spin_unlock_irq() should just re-enable interrupts, because we've been 
called with them enabled as well.

Now if you are able to see how usbhid_close() can be called with IRQs 
off, that would be a completely different story. But if that's not the 
case, the warning is bogus, and gcc-compiled kernels are right about not 
issuing it.

But without that, I so far fail to see how this is a correct thing to do.

Thanks,

-- 
Jiri Kosina
SUSE Labs

On Mon, Sep 28, 2015 at 1:33 PM, Jiri Kosina [off-list ref] wrote:

On Mon, 28 Sep 2015, Sedat Dilek wrote:

quoted

When compiling Linux v4.2+ and v4.3-rc2+ with a llvmlinux patchset
and CLANG v3.7 I see a BUG line like this:

[   24.705463] BUG: sleeping function called from invalid context at kernel/workqueue.c:2680
[   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid

After some vital help from workqueue and hid folks it turned out to be
a problem in the hid area.

Jiri encouraged me to look into del_timer-sync()/cancel_work_sync().
So, I disassembled kernel/time/timer.o.
This looked good.

Both functions are called in hid_cancel_delayed_stuff().

Hi Jiri,

first of all thanky ou for your fast and informative reply.

I am not a LOCKING expert or compiler guru, so a lot of stuff is new
to me and I try to understand things by testing.

Yeah, but we're enabling IRQs before calling hid_cancel_delayed_stuff()
(or, to be more precise, we're restoring original flags, and I don't see
usbhid_close() being called with IRQs off).

2nd this issue is really serious for me.
When doing a cut and paste in Firefox, my Xorg restarts and I am
confronted with my LightDM login-manager.
So... not really a working environment.

Did you look at the step-by-step moving of trace_hardirqs_off() and
the corresponding dmesg-logs?
What helps is a trace_hardirqs_off() before spin_unlock_irq() in the
if-statement.
So, yes "IRQs are enabled" but tracing does not like it.

Therefore ...

[ ... snip ... ]

quoted

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 36712e9f56c2..188f59348ec5 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c

@@ -729,16 +729,16 @@ void usbhid_close(struct hid_device *hid)
       * data acquistion due to a resumption we no longer
       * care about
       */
-     spin_lock_irq(&usbhid->lock);
+     spin_lock_bh(&usbhid->lock);
      if (!--hid->open) {
-             spin_unlock_irq(&usbhid->lock);
+             spin_unlock_bh(&usbhid->lock);
              hid_cancel_delayed_stuff(usbhid);

I still don't understand how this should be improving anything. I believe
spin_unlock_irq() should just re-enable interrupts, because we've been
called with them enabled as well.

Is spin_lock_bh() not an appropriate replacement?
Does it change code beaviour?
Is it important to re-enable IRQs here - before hid_cancel_delayed_stuff()?
Turning hardirqs off seems to make the bug-line go away.

Now if you are able to see how usbhid_close() can be called with IRQs
off, that would be a completely different story. But if that's not the
case, the warning is bogus, and gcc-compiled kernels are right about not
issuing it.

Again, I am new to tracing.
Steven encouraged me to look at the lockdep hints in dmesg - not ftrace [1].

"Actually, if you are looking for where interrupts were disabled last
before triggering the "sleeping function called from invalid context",
lockdep, not ftrace, would be your better bet.

Enable lockdep with CONFIG_PROVE_LOCKING. It will give you better
information about where the last irq was disabled."

Here, I have CONFIG_PROVE_LOCKING=y.

I am doing a new kernel-build with the might_sleep() on top of
hid_cancel_delayed_stuff() which showed some lockdep/irqsoff hints in
dmesg-log.

But without that, I so far fail to see how this is a correct thing to do.

Again, I dunno why two compiler behave different here.
Unsure if it is a compiler or linux-kernel issue or whatever.

Still fighting...

- Sedat -

[1] http://marc.info/?l=linux-kernel&m=144337272915104&w=2

On Tue, 29 Sep 2015, Sedat Dilek wrote:

Did you look at the step-by-step moving of trace_hardirqs_off() and
the corresponding dmesg-logs?
What helps is a trace_hardirqs_off() before spin_unlock_irq() in the
if-statement.
So, yes "IRQs are enabled" but tracing does not like it.

I so far fail to make any sense out of this behavior.

quoted

Therefore ...

[ ... snip ... ]

quoted

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 36712e9f56c2..188f59348ec5 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c

@@ -729,16 +729,16 @@ void usbhid_close(struct hid_device *hid)
       * data acquistion due to a resumption we no longer
       * care about
       */
-     spin_lock_irq(&usbhid->lock);
+     spin_lock_bh(&usbhid->lock);
      if (!--hid->open) {
-             spin_unlock_irq(&usbhid->lock);
+             spin_unlock_bh(&usbhid->lock);
              hid_cancel_delayed_stuff(usbhid);

I still don't understand how this should be improving anything. I believe
spin_unlock_irq() should just re-enable interrupts, because we've been
called with them enabled as well.

Is spin_lock_bh() not an appropriate replacement?

No, it's not. Plus, before we gain understanding why exactly is the 
warning being issued, I am not making any random changes to the code.

quoted

Now if you are able to see how usbhid_close() can be called with IRQs
off, that would be a completely different story. But if that's not the
case, the warning is bogus, and gcc-compiled kernels are right about not
issuing it.

Again, I am new to tracing.
Steven encouraged me to look at the lockdep hints in dmesg - not ftrace [1].

"Actually, if you are looking for where interrupts were disabled last
before triggering the "sleeping function called from invalid context",
lockdep, not ftrace, would be your better bet.

Enable lockdep with CONFIG_PROVE_LOCKING. It will give you better
information about where the last irq was disabled."

Here, I have CONFIG_PROVE_LOCKING=y.

I am doing a new kernel-build with the might_sleep() on top of
hid_cancel_delayed_stuff() which showed some lockdep/irqsoff hints in
dmesg-log.

Yes. That dmesg doesn't still make any sense. It tells us that IRQs got 
enabled during spin_unlock_irq() (I believe it's the very one in 
usbhid_close(), but we'll see), and then it bugs because it thinks they 
are enabled.

Actually, could you please run with the attached patch (you need lockdep 
enabled for it to build) and send me your dmesg? Ideally both from 
gcc-compiled kernel and llvm-compiled kernel as well.

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 36712e9..aaae42e 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c

@@ -38,6 +38,8 @@
 #include <linux/hidraw.h>
 #include "usbhid.h"
 
+#include <linux/lockdep.h>
+
 /*
  * Version Information
  */

@@ -725,6 +727,9 @@ void usbhid_close(struct hid_device *hid)
 
 	mutex_lock(&hid_open_mut);
 
+	if(WARN_ON(irqs_disabled()))
+		print_irqtrace_events(current);
+
 	/* protecting hid->open to make sure we don't restart
 	 * data acquistion due to a resumption we no longer
 	 * care about

-- 
Jiri Kosina
SUSE Labs

On Tue, Sep 29, 2015 at 11:27 AM, Jiri Kosina [off-list ref] wrote:

This breaks my build when CONFIG_USB_HID=m...

  find .tmp_versions -name '*.mod' | xargs -r grep -h '\.ko$' | sort
-u | sed 's/\.ko$/.o/' | scripts/mod/modpost -m -a -o ./Module.symvers
   -S   -s -T -
ERROR: "print_irqtrace_events" [drivers/hid/usbhid/usbhid.ko] undefined!
make[3]: *** [__modpost] Error 1
make[2]: *** [modules] Error 2
make[1]: *** [bindeb-pkg] Error 2
make: *** [bindeb-pkg] Error 2

- Sedat -

On Tue, 29 Sep 2015 20:54:38 +0200
Sedat Dilek [off-list ref] wrote:

This breaks my build when CONFIG_USB_HID=m...

  find .tmp_versions -name '*.mod' | xargs -r grep -h '\.ko$' | sort
-u | sed 's/\.ko$/.o/' | scripts/mod/modpost -m -a -o ./Module.symvers
   -S   -s -T -
ERROR: "print_irqtrace_events" [drivers/hid/usbhid/usbhid.ko] undefined!
make[3]: *** [__modpost] Error 1
make[2]: *** [modules] Error 2
make[1]: *** [bindeb-pkg] Error 2
make: *** [bindeb-pkg] Error 2

Add the below patch too:

-- Steve

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 8acfbf773e06..8b29b3dd518f 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c

@@ -2410,6 +2410,7 @@ void print_irqtrace_events(struct task_struct *curr)
 	printk("softirqs last disabled at (%u): ", curr->softirq_disable_event);
 	print_ip_sym(curr->softirq_disable_ip);
 }
+EXPORT_SYMBOL(print_irqtrace_events);
 
 static int HARDIRQ_verbose(struct lock_class *class)
 {

On Tue, Sep 29, 2015 at 9:08 PM, Steven Rostedt [off-list ref] wrote:

Thanks, that fixed it.

- Sedat -