Re: 3.8.0-rc3: possible circular locking dependency: &tty->legacy_mutex / &tty->hangup_work with serial/RFCOMM connection via USB bluetooth dongle

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Saturday, January 12, 2013, 7:46:39 PM, you wrote:

> Hi,

> Running a 3.8.0-rc3 kernel (latest commit b719f43059903820c31edb30f4663a2818836e7f) kernel (debian squeeze os), i'm running into this lockdep warning when:

Ok, this seems to be fixed by commit: 852e4a8152b427c3f318bb0e1b5e938d64dcdc32 (tty: don't deadlock while flushing workqueue)


> - Running a perl script that uses rfcomm to communicatie via bluetooth with a bluetooth/TTL converter.
> - It can run ok for a few hours before this lockdep occurs and the perl script freezes.
> - The info related to bluetooth from syslog:

> Jan 12 10:24:08 serveerstertje kernel: [    7.919775] Bluetooth: Virtual HCI driver ver 1.3
> Jan 12 10:24:08 serveerstertje kernel: [    7.920314] Bluetooth: HCI UART driver ver 2.2
> Jan 12 10:24:08 serveerstertje kernel: [    7.920316] Bluetooth: HCI H4 protocol initialized
> Jan 12 10:24:08 serveerstertje kernel: [    7.920317] Bluetooth: HCI BCSP protocol initialized
> Jan 12 10:24:08 serveerstertje kernel: [    7.920318] Bluetooth: HCILL protocol initialized
> Jan 12 10:24:08 serveerstertje kernel: [    7.920318] Bluetooth: HCIATH3K protocol initialized
> Jan 12 10:24:08 serveerstertje kernel: [    7.920319] Bluetooth: HCI Three-wire UART (H5) protocol initialized

> Jan 12 10:24:08 serveerstertje kernel: [    8.191897] Bluetooth: RFCOMM TTY layer initialized
> Jan 12 10:24:08 serveerstertje kernel: [    8.191930] Bluetooth: RFCOMM socket layer initialized
> Jan 12 10:24:08 serveerstertje kernel: [    8.191931] Bluetooth: RFCOMM ver 1.11
> Jan 12 10:24:08 serveerstertje kernel: [    8.191932] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
> Jan 12 10:24:08 serveerstertje kernel: [    8.191933] Bluetooth: BNEP filters: protocol multicast
> Jan 12 10:24:08 serveerstertje kernel: [    8.191944] Bluetooth: BNEP socket layer initialized
> Jan 12 10:24:08 serveerstertje kernel: [    8.191945] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
> Jan 12 10:24:08 serveerstertje kernel: [    8.191954] Bluetooth: HIDP socket layer initialized

> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Bluetooth deamon 4.66
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Starting SDP server
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Starting experimental netlink support
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Failed to find Bluetooth netlink family
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Failed to init netlink plugin
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: bridge pan0 created
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: HCI dev 0 registered
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Failed to open RFKILL control device
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: HCI dev 0 up
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Starting security manager 0
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Adapter /org/bluez/3912/hci0 has been enabled
> Jan 12 10:24:09 serveerstertje bluetoothd[3912]: Failed to access HAL


> - And the lockdep warning itself:

> [28678.458250]
> [28678.476588] ======================================================
> [28678.494887] [ INFO: possible circular locking dependency detected ]
> [28678.513013] 3.8.0-rc3-20130112-netpatched-rocketscience-radeon #1 Not tainted
> [28678.530909] -------------------------------------------------------
> [28678.548636] kworker/2:1/19513 is trying to acquire lock:
> [28678.566070]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff819ba5ee>] tty_lock_nested+0x3e/0x80
> [28678.583577]
> [28678.583577] but task is already holding lock:
> [28678.617615]  ((&tty->hangup_work)){+.+...}, at: [<ffffffff81080bf8>] process_one_work+0x158/0x4b0
> [28678.634569]
> [28678.634569] which lock already depends on the new lock.
> [28678.634569]
> [28678.683868]
> [28678.683868] the existing dependency chain (in reverse order) is:
> [28678.715354]
[28678.715354] ->> #2 ((&tty->hangup_work)){+.+...}:
> [28678.745890]        [<ffffffff810b4d2e>] __lock_acquire+0x44e/0xdd0
> [28678.760975]        [<ffffffff810b576a>] lock_acquire+0xba/0x100
> [28678.775834]        [<ffffffff8108322a>] flush_work+0x3a/0x250
> [28678.790408]        [<ffffffff81451568>] tty_ldisc_flush_works+0x18/0x40
> [28678.804877]        [<ffffffff814517ae>] tty_ldisc_release+0x2e/0x90
> [28678.818952]        [<ffffffff8144b827>] tty_release+0x3c7/0x590
> [28678.832813]        [<ffffffff8114e009>] __fput+0xa9/0x2c0
> [28678.846411]        [<ffffffff8114e289>] ____fput+0x9/0x10
> [28678.859644]        [<ffffffff810854d5>] task_work_run+0x95/0xb0
> [28678.872661]        [<ffffffff8100dc4d>] do_notify_resume+0x6d/0x80
> [28678.885516]        [<ffffffff819bb5a2>] int_signal+0x12/0x17
> [28678.898047]
[28678.898047] ->> #1 (&tty->legacy_mutex/1){+.+...}:
> [28678.922334]        [<ffffffff810b4d2e>] __lock_acquire+0x44e/0xdd0
> [28678.934268]        [<ffffffff810b576a>] lock_acquire+0xba/0x100
> [28678.945916]        [<ffffffff819b754c>] mutex_lock_nested+0x4c/0x450
> [28678.957318]        [<ffffffff819ba5ee>] tty_lock_nested+0x3e/0x80
> [28678.968500]        [<ffffffff819ba6aa>] tty_lock_pair+0x6a/0x70
> [28678.979405]        [<ffffffff8144b5cb>] tty_release+0x16b/0x590
> [28678.990012]        [<ffffffff8114e009>] __fput+0xa9/0x2c0
> [28679.000367]        [<ffffffff8114e289>] ____fput+0x9/0x10
> [28679.009455] FW: BLOCKED low udp input: IN=eth0 OUT= MAC=40:61:86:f4:67:d9:00:08:ae:10:46:60:08:00 SRC=112.203.174.221 DST=88.159.69.252 LEN=131 TOS=0x00 PREC=0x00 TTL=38 ID=17898 PROTO=UDP SPT=27001 DPT=1024 LEN=111
> [28679.030869]        [<ffffffff810854d5>] task_work_run+0x95/0xb0
> [28679.040727]        [<ffffffff8100dc4d>] do_notify_resume+0x6d/0x80
> [28679.050419]        [<ffffffff819bb5a2>] int_signal+0x12/0x17
> [28679.059880]
[28679.059880] ->> #0 (&tty->legacy_mutex){+.+.+.}:
> [28679.077823]        [<ffffffff810b41d8>] validate_chain+0x1258/0x1300
> [28679.086583]        [<ffffffff810b4d2e>] __lock_acquire+0x44e/0xdd0
> [28679.095126]        [<ffffffff810b576a>] lock_acquire+0xba/0x100
> [28679.103399]        [<ffffffff819b754c>] mutex_lock_nested+0x4c/0x450
> [28679.111468]        [<ffffffff819ba5ee>] tty_lock_nested+0x3e/0x80
> [28679.119247]        [<ffffffff819ba63b>] tty_lock+0xb/0x10
> [28679.126712]        [<ffffffff814492b5>] __tty_hangup+0x65/0x3c0
> [28679.133940]        [<ffffffff81449620>] do_tty_hangup+0x10/0x20
> [28679.140970]        [<ffffffff81080c60>] process_one_work+0x1c0/0x4b0
> [28679.147755]        [<ffffffff8108134e>] worker_thread+0x11e/0x3d0
> [28679.154383]        [<ffffffff81088a36>] kthread+0xd6/0xe0
> [28679.160649]        [<ffffffff819bb1bc>] ret_from_fork+0x7c/0xb0
> [28679.166666]
> [28679.166666] other info that might help us debug this:
> [28679.166666]
> [28679.183748] Chain exists of:
> [28679.183748]   &tty->legacy_mutex --> &tty->legacy_mutex/1 --> (&tty->hangup_work)
> [28679.183748]
> [28679.200495]  Possible unsafe locking scenario:
> [28679.200495]
> [28679.211416]        CPU0                    CPU1
> [28679.216751]        ----                    ----
> [28679.222049]   lock((&tty->hangup_work));
> [28679.227206]                                lock(&tty->legacy_mutex/1);
> [28679.232380]                                lock((&tty->hangup_work));
> [28679.237532]   lock(&tty->legacy_mutex);
> [28679.242673]
> [28679.242673]  *** DEADLOCK ***
> [28679.242673]
> [28679.257840] 2 locks held by kworker/2:1/19513:
> [28679.262888]  #0:  (events){.+.+.+}, at: [<ffffffff81080bf8>] process_one_work+0x158/0x4b0
> [28679.268053]  #1:  ((&tty->hangup_work)){+.+...}, at: [<ffffffff81080bf8>] process_one_work+0x158/0x4b0
> [28679.273381]
> [28679.273381] stack backtrace:
> [28679.283820] Pid: 19513, comm: kworker/2:1 Not tainted 3.8.0-rc3-20130112-netpatched-rocketscience-radeon #1
> [28679.289347] Call Trace:
> [28679.294804]  [<ffffffff810b2c74>] print_circular_bug+0x204/0x300
> [28679.300384]  [<ffffffff810b41d8>] validate_chain+0x1258/0x1300
> [28679.305997]  [<ffffffff810b4d2e>] __lock_acquire+0x44e/0xdd0
> [28679.311599]  [<ffffffff810b4d4b>] ? __lock_acquire+0x46b/0xdd0
> [28679.317222]  [<ffffffff810b576a>] lock_acquire+0xba/0x100
> [28679.322889]  [<ffffffff819ba5ee>] ? tty_lock_nested+0x3e/0x80
> [28679.328481]  [<ffffffff819ba5ee>] ? tty_lock_nested+0x3e/0x80
> [28679.334023]  [<ffffffff819b754c>] mutex_lock_nested+0x4c/0x450
> [28679.339415]  [<ffffffff819ba5ee>] ? tty_lock_nested+0x3e/0x80
> [28679.344784]  [<ffffffff810b5788>] ? lock_acquire+0xd8/0x100
> [28679.350154]  [<ffffffff81449279>] ? __tty_hangup+0x29/0x3c0
> [28679.355506]  [<ffffffff819ba5ee>] tty_lock_nested+0x3e/0x80
> [28679.360939]  [<ffffffff819ba63b>] tty_lock+0xb/0x10
> [28679.366282]  [<ffffffff814492b5>] __tty_hangup+0x65/0x3c0
> [28679.371651]  [<ffffffff81080bf8>] ? process_one_work+0x158/0x4b0
> [28679.377032]  [<ffffffff810b1918>] ? trace_hardirqs_on_caller+0xf8/0x200
> [28679.382273]  [<ffffffff81449620>] do_tty_hangup+0x10/0x20
> [28679.387216]  [<ffffffff81080c60>] process_one_work+0x1c0/0x4b0
> [28679.392118]  [<ffffffff81080bf8>] ? process_one_work+0x158/0x4b0
> [28679.397039]  [<ffffffff81449610>] ? __tty_hangup+0x3c0/0x3c0
> [28679.401952]  [<ffffffff8108134e>] worker_thread+0x11e/0x3d0
> [28679.406859]  [<ffffffff810b1918>] ? trace_hardirqs_on_caller+0xf8/0x200
> [28679.411787]  [<ffffffff81081230>] ? manage_workers+0x2e0/0x2e0
> [28679.416683]  [<ffffffff81088a36>] kthread+0xd6/0xe0
> [28679.421538]  [<ffffffff81088960>] ? __init_kthread_worker+0x70/0x70
> [28679.426429]  [<ffffffff819bb1bc>] ret_from_fork+0x7c/0xb0
> [28679.431278]  [<ffffffff81088960>] ? __init_kthread_worker+0x70/0x70


> - This is followed by blocked task messages for the perl script:

> Jan 12 18:25:29 serveerstertje kernel: [28926.144229] INFO: task zabbix_slimmeme:26976 blocked for more than 120 seconds.
> Jan 12 18:25:29 serveerstertje kernel: [28926.162883] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Jan 12 18:25:29 serveerstertje kernel: [28926.181312] zabbix_slimmeme D ffff88003851d230     0 26976  22112 0x00000000
> Jan 12 18:25:29 serveerstertje kernel: [28926.199596]  ffff88002d473818 0000000000000216 ffff880000000002 ffffffff8202be38
> Jan 12 18:25:29 serveerstertje kernel: [28926.217728]  ffff88003851d230 0000000000013040 ffff88002d473fd8 ffff88002d472010
> Jan 12 18:25:29 serveerstertje kernel: [28926.235627]  0000000000013040 0000000000013040 ffff88002d473fd8 0000000000013040
> Jan 12 18:25:29 serveerstertje kernel: [28926.253346] Call Trace:
> Jan 12 18:25:29 serveerstertje kernel: [28926.270648]  [<ffffffff810be1ed>] ? __module_text_address+0xd/0x60
> Jan 12 18:25:29 serveerstertje kernel: [28926.322462]  [<ffffffff810be1ed>] ? __module_text_address+0xd/0x60
> Jan 12 18:25:29 serveerstertje kernel: [28926.339617]  [<ffffffff810be44b>] ? is_module_text_address+0x2b/0x60
> Jan 12 18:25:29 serveerstertje kernel: [28926.356452]  [<ffffffff81085958>] ? __kernel_text_address+0x58/0x80
> Jan 12 18:25:29 serveerstertje kernel: [28926.373057]  [<ffffffff81140049>] ? sysfs_slab_add+0x149/0x200
> Jan 12 18:25:29 serveerstertje kernel: [28926.389435]  [<ffffffff81140067>] ? sysfs_slab_add+0x167/0x200
> Jan 12 18:25:29 serveerstertje kernel: [28926.405516]  [<ffffffff819b8d04>] schedule+0x24/0x70
> Jan 12 18:25:29 serveerstertje kernel: [28926.421242]  [<ffffffff819b5f6d>] schedule_timeout+0x1bd/0x220
> Jan 12 18:25:29 serveerstertje kernel: [28926.436793]  [<ffffffff810b5788>] ? lock_acquire+0xd8/0x100
> Jan 12 18:25:29 serveerstertje kernel: [28926.452138]  [<ffffffff819b8201>] ? wait_for_common+0x31/0x170
> Jan 12 18:25:29 serveerstertje kernel: [28926.467171]  [<ffffffff810b5c17>] ? lock_release+0x117/0x250
> Jan 12 18:25:29 serveerstertje kernel: [28926.481938]  [<ffffffff819b82d1>] wait_for_common+0x101/0x170
> Jan 12 18:25:29 serveerstertje kernel: [28926.496482]  [<ffffffff81098730>] ? try_to_wake_up+0x310/0x310
> Jan 12 18:25:29 serveerstertje kernel: [28926.510873]  [<ffffffff819b83e8>] wait_for_completion+0x18/0x20
> Jan 12 18:25:29 serveerstertje kernel: [28926.525014]  [<ffffffff81083385>] flush_work+0x195/0x250
> Jan 12 18:25:29 serveerstertje kernel: [28926.538855]  [<ffffffff810833a0>] ? flush_work+0x1b0/0x250
> Jan 12 18:25:29 serveerstertje kernel: [28926.552411]  [<ffffffff81080400>] ? cwq_dec_nr_in_flight+0xd0/0xd0
> Jan 12 18:25:29 serveerstertje kernel: [28926.565910]  [<ffffffff81451568>] tty_ldisc_flush_works+0x18/0x40
> Jan 12 18:25:29 serveerstertje kernel: [28926.579013]  [<ffffffff814517ae>] tty_ldisc_release+0x2e/0x90
> Jan 12 18:25:29 serveerstertje kernel: [28926.591876]  [<ffffffff8144b827>] tty_release+0x3c7/0x590
> Jan 12 18:25:29 serveerstertje kernel: [28926.604527]  [<ffffffff810b1a2d>] ? trace_hardirqs_on+0xd/0x10
> Jan 12 18:25:29 serveerstertje kernel: [28926.616853]  [<ffffffff819b63a9>] ? __mutex_unlock_slowpath+0x149/0x1d0
> Jan 12 18:25:29 serveerstertje kernel: [28926.628997]  [<ffffffff81098730>] ? try_to_wake_up+0x310/0x310
> Jan 12 18:25:29 serveerstertje kernel: [28926.640952]  [<ffffffff8144bdb4>] tty_open+0x3c4/0x5f0
> Jan 12 18:25:30 serveerstertje kernel: [28926.652584]  [<ffffffff81150a18>] chrdev_open+0x98/0x170
> Jan 12 18:25:30 serveerstertje kernel: [28926.663972]  [<ffffffff810912cd>] ? lg_local_unlock+0x3d/0x70
> Jan 12 18:25:30 serveerstertje kernel: [28926.675152]  [<ffffffff81150980>] ? cdev_put+0x30/0x30
> Jan 12 18:25:30 serveerstertje kernel: [28926.686173]  [<ffffffff8114b1fe>] do_dentry_open+0x25e/0x310
> Jan 12 18:25:30 serveerstertje kernel: [28926.696868]  [<ffffffff8114b3c0>] finish_open+0x30/0x50
> Jan 12 18:25:30 serveerstertje kernel: [28926.707267]  [<ffffffff8115a79e>] do_last+0x30e/0xe90
> Jan 12 18:25:30 serveerstertje kernel: [28926.717404]  [<ffffffff81157aba>] ? link_path_walk+0x9a/0x9f0
> Jan 12 18:25:30 serveerstertje kernel: [28926.727353]  [<ffffffff8115b3ce>] path_openat+0xae/0x4e0
> Jan 12 18:25:30 serveerstertje kernel: [28926.737008]  [<ffffffff810b5c17>] ? lock_release+0x117/0x250
> Jan 12 18:25:30 serveerstertje kernel: [28926.746482]  [<ffffffff81160264>] ? do_select+0x5f4/0x6d0
> Jan 12 18:25:30 serveerstertje kernel: [28926.755613]  [<ffffffff8115b934>] do_filp_open+0x44/0xa0
> Jan 12 18:25:30 serveerstertje kernel: [28926.764542]  [<ffffffff811691e3>] ? __alloc_fd+0xb3/0x150
> Jan 12 18:25:30 serveerstertje kernel: [28926.773224]  [<ffffffff8114ad13>] do_sys_open+0x103/0x1f0
> Jan 12 18:25:30 serveerstertje kernel: [28926.781585]  [<ffffffff8114ae3c>] sys_open+0x1c/0x20
> Jan 12 18:25:30 serveerstertje kernel: [28926.789685]  [<ffffffff819bb269>] system_call_fastpath+0x16/0x1b
> Jan 12 18:25:30 serveerstertje kernel: [28926.797570] INFO: lockdep is turned off.




--
To unsubscribe from this list: send the line "unsubscribe linux-serial" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html


[Index of Archives]     [Kernel Newbies]     [Security]     [Netfilter]     [Bugtraq]     [Linux PPP]     [Linux FS]     [Yosemite News]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Samba]     [Video 4 Linux]     [Linmodem]     [Device Mapper]     [Linux Kernel for ARM]

  Powered by Linux