LegacyDevice-related lock order reversal deadlock

[anevilyak]

I was compiling something and simultaneously unplugged/replugged my USB keyboard. The shell handling the compile deadlocked, and the keyboard never came up. Looking further, I found that the shell thread was deadlocked waiting on the devfs mutex, which another thread held but was waiting to acquire the legacy device mutex, so it seems we have a lock order reversal problem here. KDL session info below.

teams
team           id  parent      name
0x90848e00     62  0x82027e00  net_server
0x82027540     63  0x82027e00  app_server
0x82027e00      1  0x00000000  kernel_team
0x9ac5a000   1707  0x82027e00  sh
0x820278c0     95  0x82027e00  mount_server
0x90af6540    443  0x82027e00  Terminal
0x82027a80    539  0x91142c40  Tracker
0x91142c40    447  0x90af6540  bash
0x90848a80    106  0x82027e00  Deskbar
0x82027380     75  0x82027e00  syslog_daemon
0x90848700    107  0x82027e00  media_server
0x908481c0    139  0x90848700  media_addon_server
0x90848540    108  0x82027e00  midi_server
0x90848380    109  0x82027e00  print_server
0x90af6c40    111  0x82027e00  cddb_daemon
0x820271c0     54  0x82027e00  registrar
0x908488c0     86  0x82027540  input_server
0x90af6000    464  0x82027e00  Vision
0x82027000     61  0x82027e00  debug_server
kdebug> bt 1707
stack trace for thread 1707 "sh"
    kernel stack: 0x80713000 to 0x80717000
      user stack: 0x7efee000 to 0x7ffee000
frame               caller     <image>:function + offset
 0 80716cb4 (+  64) 80072dc2   <kernel_x86> reschedule() + 0x036d
 1 80716cf4 (+  64) 8006feb8   <kernel_x86>:_mutex_lock + 0x01a9
 2 80716d34 (+  32) 8006ff04   <kernel_x86>:recursive_lock_lock + 0x004a
 3 80716d54 (+  64) 800919d5   <kernel_x86> devfs_lookup(fs_volume*: 0x82207b40d
 4 80716d94 (+  64) 800b960d   <kernel_x86> lookup_dir_entry(vnode*: 0x1716ee8,2
 5 80716dd4 (+  64) 800bbde7   <kernel_x86> vnode_path_to_vnode(vnode*: NULL, ca
 6 80716e14 (+  48) 800bc83a   <kernel_x86> vnode_path_to_vnode(vnode*: NULL, cc
 7 80716e44 (+  64) 800bc933   <kernel_x86> path_to_vnode(char*: 0x80716edc, fa1
 8 80716e84 (+  64) 800bdeed   <kernel_x86> fd_and_path_to_vnode(int32: -2140045
 9 80716ec4 (+  64) 800c0427   <kernel_x86> file_open(int32: 0, char*: 0x2938230
10 80716f04 (+  64) 800c0fc4   <kernel_x86>:_user_open + 0x0091
11 80716f44 (+ 100) 800f8e71   <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x80716fa8 (end = 0x80717000)
 eax 0x64           ebx 0x372de8        ecx 0x7ffedecc   edx 0xffff0114
 esi 0x7ffee538     edi 0x7ffee548      ebp 0x7ffedee8   esp 0x80716fdc
 eip 0xffff0114  eflags 0x246      user esp 0x7ffedecc
 vector: 0x63, error code: 0x0
12 80716fa8 (+   0) ffff0114   <commpage>:commpage_syscall + 0x0004
13 7ffedee8 (+  32) 002271ac   <_APP_>:check_dev_tty + 0x0024
14 7ffedf08 (+  96) 00224a1b   <_APP_>:main + 0x0054
15 7ffedf68 (+  52) 0021a0dd   <_APP_>:_start + 0x0051
16 7ffedf9c (+  64) 001052ab   </boot/system/runtime_loader@0x00100000>:unknownb
17 7ffedfdc (+   0) 7ffedfec   44887:sh_main_stack@0x7efee000 + 0xffffec
kdebug> thread 1707
THREAD: 0x90e55400
id:                 1707 (0x6ab)
name:               "sh"
all_next:           0x82354800
team_next:          0x00000000
q_next:             0x80160a00
priority:           1 (next 10, I/O: -1)
state:              waiting
next_state:         waiting
cpu:                0x00000000
sig_pending:        0x2 (blocked: 0x0, temp enabled: 0x0)
in_kernel:          1
waiting for:        mutex 0x82207b18
fault_handler:      0x00000000
args:               0x821cca80 0x00000000
entry:              0x80065751
team:               0x9ac5a000, "sh"
  exit.sem:         32369
  exit.status:      0x0 (No error)
  exit.reason:      0x0
  exit.signal:      0x0
  exit.waiters:
kernel_stack_area:  44885
kernel_stack_base:  0x80713000
user_stack_area:    44887
user_stack_base:    0x7efee000
user_local_storage: 0x7ffee000
user_thread:        0x6fff0000
kernel_errno:       0x0 (No error)
kernel_time:        10712
user_time:          534
flags:              0x1
architecture dependant section:
        esp: 0x80716c58
        ss: 0x00000010
        fpu_state at 0x90e557e0
kdebug> mutex 0x82207b18
mutex 0x82207b18:
  name:            devfs lock
  flags:           0x0
  holder:          153
  waiting threads: 29 1707
kdebug> bt 153
stack trace for thread 153 "user thread"
    kernel stack: 0x80717000 to 0x8071b000
      user stack: 0x70041000 to 0x70081000
frame               caller     <image>:function + offset
 0 8071ad34 (+  64) 80072dc2   <kernel_x86> reschedule() + 0x036d
 1 8071ad74 (+  64) 8006feb8   <kernel_x86>:_mutex_lock + 0x01a9
 2 8071adb4 (+  32) 8006ff04   <kernel_x86>:recursive_lock_lock + 0x004a
 3 8071add4 (+  48) 80094442   <kernel_x86> LegacyDevice<0x917ff548>::Removed()6
 4 8071ae04 (+  32) 800900bd   <kernel_x86> devfs_delete_vnode(devfs*: 0x8200301
 5 8071ae24 (+  48) 80091592   <kernel_x86> devfs_remove_vnode(fs_volume*: 0x828
 6 8071ae54 (+  32) 800b6b06   <kernel_x86> free_vnode(vnode*: 0x917dff20, truea
 7 8071ae74 (+  48) 800ba93a   <kernel_x86> dec_vnode_ref_count(vnode*: NULL, t6
 8 8071aea4 (+  16) 800bad5b   <kernel_x86> file_free_fd(file_descriptor*: 0x910
 9 8071aeb4 (+  32) 800ab40b   <kernel_x86>:put_fd + 0x002d
10 8071aed4 (+  64) 800ab55a   <kernel_x86>:close_fd_index + 0x00a6
11 8071af14 (+  32) 800ab5b6   <kernel_x86> common_close(int32: -2140033112, tr3
12 8071af34 (+  16) 800ab5e3   <kernel_x86>:_user_close + 0x0013
13 8071af44 (+ 100) 800f8e71   <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x8071afa8 (end = 0x8071b000)
 eax 0x90           ebx 0x2e4de8        ecx 0x70080d40   edx 0xffff0114
 esi 0x18049020     edi 0x18049020      ebp 0x70080d5c   esp 0x8071afdc
 eip 0xffff0114  eflags 0x216      user esp 0x70080d40
 vector: 0x63, error code: 0x0
14 8071afa8 (+   0) ffff0114   <commpage>:commpage_syscall + 0x0004
15 70080d5c (+  64) 017386d2   </boot/system/lib/libdevice.so@0x01730000>:unkno2
16 70080d9c (+  32) 017387f2   </boot/system/lib/libdevice.so@0x01730000>:unkno2
17 70080dbc (+  80) 017398cd   </boot/system/lib/libdevice.so@0x01730000>:unknod
18 70080e0c (+  64) 01739a75   </boot/system/lib/libdevice.so@0x01730000>:unkno5
19 70080e4c (+  64) 01739a95   </boot/system/lib/libdevice.so@0x01730000>:unkno5
20 70080e8c (+  64) 01739a95   </boot/system/lib/libdevice.so@0x01730000>:unkno5
21 70080ecc (+  96) 0173a4b2   </boot/system/lib/libdevice.so@0x01730000>:unkno2
22 70080f2c (+  32) 003c72f8   <libbe.so> BLooper<0x18035050>::DispatchMessage(0
23 70080f4c (+  80) 003c8e34   <libbe.so> BLooper<0x18035050>::task_looper() + 6
24 70080f9c (+  32) 003c8b5a   <libbe.so> BLooper<0x18035050>::_task0_(void*: N0
25 70080fbc (+  32) 0024b4ec   <libroot.so>:exit_thread (nearest) + 0x0058
26 70080fdc (+   0) 70080fec   3301:user thread_153_stack@0x70041000 + 0x3ffec
kdebug> bt 29
stack trace for thread 29 "usb explore"
    kernel stack: 0x817f3000 to 0x817f7000
frame               caller     <image>:function + offset
 0 817f6de8 (+  64) 80072dc2   <kernel_x86> reschedule() + 0x036d
 1 817f6e28 (+  64) 8006feb8   <kernel_x86>:_mutex_lock + 0x01a9
 2 817f6e68 (+  32) 8006ff04   <kernel_x86>:recursive_lock_lock + 0x004a
 3 817f6e88 (+  64) 8009085f   <kernel_x86> unpublish_node(devfs*: 0x90d28f60, d
 4 817f6ec8 (+  48) 800908e7   <kernel_x86> devfs_unpublish_device(BaseDevice*:2
 5 817f6ef8 (+  64) 80093c35   <kernel_x86> republish_driver(legacy_driver*: 0x1
 6 817f6f38 (+  16) 80094583   <kernel_x86>:legacy_driver_rescan + 0x0036
 7 817f6f48 (+  32) 8009073f   <kernel_x86>:devfs_rescan_driver + 0x000e
 8 817f6f68 (+  32) 817a054a   <usb> Stack<0x822f0730>::RescanDrivers(rescan_it6
 9 817f6f88 (+  80) 817a094c   <usb> Stack<0x822f0730>::ExploreThread(void*: NUc
10 817f6fd8 (+  32) 80069337   <kernel_x86> _create_kernel_thread_kentry() + 0x5
11 817f6ff8 (+2122354696) 8006d518   <kernel_x86> thread_kthread_exit() + 0x0000
kdebug> thread 153
THREAD: 0x90e37800
id:                 153 (0x99)
name:               "user thread"
all_next:           0x82350600
team_next:          0x90e3a800
q_next:             0x80160420
priority:           10 (next 10, I/O: -1)
state:              waiting
next_state:         waiting
cpu:                0x00000000
sig_pending:        0x0 (blocked: 0x0, temp enabled: 0x0)
in_kernel:          1
waiting for:        mutex 0x80168de4
fault_handler:      0x00000000
args:               0x003c8b2a 0x18045620
entry:              0x0024b4bf
team:               0x90848380, "print_server"
  exit.sem:         1124
  exit.status:      0x0 (No error)
  exit.reason:      0x0
  exit.signal:      0x0
  exit.waiters:
kernel_stack_area:  3300
kernel_stack_base:  0x80717000
user_stack_area:    3301
user_stack_base:    0x70041000
user_local_storage: 0x70081000
user_thread:        0x6fff0018
kernel_errno:       0x0 (No error)
kernel_time:        437
user_time:          403
flags:              0x0
architecture dependant section:
        esp: 0x8071acd8
        ss: 0x00000010
        fpu_state at 0x90e37be0
kdebug> mutex 0x80168de4
mutex 0x80168de4:
  name:            legacy driver
  flags:           0x0
  holder:          29
  waiting threads: 153

[waddlesplash]

Still reproducible? It might be related to the mutex destruction issues that are now panics, so if it is, trying that would be helpful.

[anevilyak]

I'd have to try, but I should note that if it's in some way specific to a particular combination of hardware/drivers, I no longer have the box this was originally reported on.