lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
Open Source and information security mailing list archives
| ||
|
Message-ID: <34560309.20130112194639@eikelenboom.it> Date: Sat, 12 Jan 2013 19:46:39 +0100 From: Sander Eikelenboom <linux@...elenboom.it> To: linux-kernel@...r.kernel.org, linux-serial@...r.kernel.org, <linux-bluetooth@...r.kernel.org> CC: Alan Cox <alan@...ux.intel.com>, Greg Kroah-Hartman <gregkh@...uxfoundation.org>, <marcel@...tmann.org> Subject: 3.8.0-rc3: possible circular locking dependency: &tty->legacy_mutex / &tty->hangup_work with serial/RFCOMM connection via USB bluetooth dongle Hi, Running a 3.8.0-rc3 kernel (latest commit b719f43059903820c31edb30f4663a2818836e7f) kernel (debian squeeze os), i'm running into this lockdep warning when: - 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-kernel" in the body of a message to majordomo@...r.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists