Deadlock discovered: usb explore (legacy mutex) - sh (devfs mutex)

[emitrax]

Since I don't know which lock should be held first (there should be an order) I'll leave it to someone else.

kdebug> thread 738
THREAD: 0x914de000
id:                 738 (0x2e2)
name:               "sh"
all_next:           0x9149d800
team_next:          0x00000000
q_next:             0x913c4800
priority:           10 (next 10)
state:              waiting
next_state:         waiting
cpu:                0x00000000 
sig_pending:        0x0 (blocked: 0x0)
in_kernel:          1
waiting for:        mutex 0x8010129c
fault_handler:      0x00000000
args:               0x90d1c4b0 0x00000000
entry:              0x800458ac
team:               0x90cc42e8, "sh"
  exit.sem:         8263
  exit.status:      0x0 (No error)
  exit.reason:      0x0
  exit.signal:      0x0
  exit.waiters:
kernel_stack_area:  15626
kernel_stack_base:  0x90b11000
user_stack_area:    15628
user_stack_base:    0x7efef000
user_local_storage: 0x7ffef000
kernel_errno:       0x0 (No error)
kernel_time:        10903338
user_time:          3868782
flags:              0x0
architecture dependant section:
        esp: 0x90b149a8
        ss: 0x00000010
        fpu_state at 0x914de380
kdebug> mutex 0x8010129c
mutex 0x8010129c:
  name:            legacy driver
  flags:           0x0
  holder:          25
  waiting threads: 738
kdebug> thread 25
THREAD: 0x913c3800
id:                 25 (0x19)
name:               "usb explore"
all_next:           0x00000000
team_next:          0x913c3000
q_next:             0x800f79c0
priority:           5 (next 5)
state:              waiting
next_state:         waiting
cpu:                0x00000000 
sig_pending:        0x0 (blocked: 0x0)
in_kernel:          1
waiting for:        mutex 0x90b7d9b8
fault_handler:      0x00000000
args:               0x90b6d500 0x00000000
entry:              0x80700858
team:               0x90b7b000, "kernel_team"
  exit.sem:         100
  exit.status:      0x0 (No error)
  exit.reason:      0x0
  exit.signal:      0x0
  exit.waiters:
kernel_stack_area:  115
kernel_stack_base:  0x8016e000
user_stack_area:    -1
user_stack_base:    0x00000000
user_local_storage: 0x00000000
kernel_errno:       0x0 (No error)
kernel_time:        452272
user_time:          0
flags:              0x0
architecture dependant section:
        esp: 0x80171cbc
        ss: 0x00000010
        fpu_state at 0x913c3b80
kdebug> mutex 0x90b7d9b8
mutex 0x90b7d9b8:
  name:            devfs lock
  flags:           0x0
  holder:          738
  waiting threads: 25 2786 2820 2825

[mmlr]

Do you have any directions on how to reproduce that? What was the shell up to when this happened (stack traces would be helpful)?

[emitrax]

Honestly I don't remember. Perhaps it was while unpacking a tarball. I'm sorry, but I totally forgot to get a stack trace of the threads.

[bonefish]

Just ran into the same problem (unplugging/replugging my USB keyboard). This is a locking order reversal issue between the devfs lock and the legacy driver lock.

thread -s 12828
thread         id  state     wait for   object  cpu pri  stack      team  name
0x818ea000  12828  waiting   mutex  0x8012cf44    - 104  0x8a7b8000   95  USB Keyboard 1 watcher
kdebug> mutex 0x8012cf44
mutex 0x8012cf44:
  name:            legacy driver
  flags:           0x0
  holder:          39
  waiting threads: 12828
kdebug> thread -s 39
thread         id  state     wait for   object  cpu pri  stack      team  name
0x817f0000     39  waiting   mutex  0x80f875f8    -   5  0x802bf000    1  usb explore
kdebug> mutex 0x80f875f8
mutex 0x80f875f8:
  name:            devfs lock
  flags:           0x0
  holder:          12828
  waiting threads: 39 241146 241158
kdebug> sc 12828
stack trace for thread 12828 "USB Keyboard 1 watcher"
    kernel stack: 0x8a7b8000 to 0x8a7bc000
      user stack: 0x70104000 to 0x70144000
frame               caller     <image>:function + offset
 0 8a7bbd24 (+  48) 80059c28   <kernel_x86> context_switch(thread*: 0x818ea000, thread*: 0x817f0000) + 0x003c
 1 8a7bbd54 (+  64) 80059f0f   <kernel_x86> simple_reschedule() + 0x029f
 2 8a7bbd94 (+  48) 8003e421   <kernel_x86>:_mutex_lock + 0x01b1
 3 8a7bbdc4 (+  48) 8003d42b   <kernel_x86>:recursive_lock_lock + 0x0053
 4 8a7bbdf4 (+  48) 80075374   <kernel_x86> LegacyDevice<0x81199460>::UninitDevice(0x0, 0x8a7bbe54, 0x835b805c) + 0x0028
 5 8a7bbe24 (+  64) 8006e021   <kernel_x86> devfs_free_cookie(fs_volume*: 0x80f77284, fs_vnode*: 0x81269cc0, 0x8101ebd0) + 0x0071
 6 8a7bbe64 (+  48) 8009be42   <kernel_x86> file_free_fd(file_descriptor*: 0x812bbd48) + 0x002e
 7 8a7bbe94 (+  48) 8008a7d0   <kernel_x86>:put_fd + 0x0038
 8 8a7bbec4 (+  64) 8008a8ba   <kernel_x86>:close_fd_index + 0x0032
 9 8a7bbf04 (+  32) 8008b3b5   <kernel_x86> common_close(int32: 12, false) + 0x0031
10 8a7bbf24 (+  32) 8008bc8c   <kernel_x86>:_user_close + 0x0018
11 8a7bbf44 (+ 100) 800d2491   <kernel_x86>:handle_syscall + 0x00be
user iframe at 0x8a7bbfa8 (end = 0x8a7bc000)
 eax 0x8a           ebx 0x573240        ecx 0x5bb800     edx 0x1800fc30
 esi 0x18060f80     edi 0x4             ebp 0x70143d2c   esp 0x8a7bbfdc
 eip 0xffff0102  eflags 0x203      user esp 0x70143d00
 vector: 0x63, error code: 0x0
12 8a7bbfa8 (+   0) ffff0102   <commpage>:commpage_syscall + 0x0002
13 70143d2c (+  48) 005b3929   <keyboard> KeyboardDevice<0x18060f80>::Stop(0x1, 0x5b4a3c70143d9c, 0x22cf5c, 0x18060f80, int32: 402717744, int8: 125, 0x0, 0x18060ec0) + 0x002d
14 70143d5c (+  48) 005b4a4f   <keyboard> KeyboardInputDevice<0x1800fc30>::Stop(0x1806b428 "USB Keyboard 1", 0x18060f80) + 0x001f
15 70143d8c (+  48) 00211fc3   <_APP_> InputDeviceListItem<0x18060ec0>::Stop(0x1806b440, 0x1802c420, 0x21549a) + 0x0033
16 70143dbc (+  80) 00215544   <_APP_> InputServer<0x1802c420>::UnregisterDevices(BInputServerDevice&: 0x1800fc30, input_device_ref*: 0x70143e74) + 0x00b8
17 70143e0c (+  48) 00217b18   <_APP_> BInputServerDevice<0x1800fc30>::UnregisterDevices(input_device_ref*: 0x70143e74) + 0x002c
18 70143e3c (+  64) 005b4d14   <keyboard> KeyboardInputDevice<0x1800fc30>::_RemoveDevice(0x18060fc0 "/dev/input/keyboard/usb/0") + 0x0048
19 70143e7c (+ 256) 005b3c93   <keyboard> KeyboardDevice<0x18060f80>::_Thread(0x0, 0x0, 0x5b3bd8, 0x573240) + 0x009f
20 70143f7c (+  48) 005b3beb   <keyboard> KeyboardDevice<0x18060f80>::_ThreadEntry(NULL) + 0x001f
21 70143fac (+  48) 004e697c   <libroot.so>:_get_next_team_info (nearest) + 0x005c
22 70143fdc (+   0) 70143fec   259800:USB Keyboard 1 watcher_12828_st@0x70104000 + 0x3ffec
kdebug> sc 39
stack trace for thread 39 "usb explore"
    kernel stack: 0x802bf000 to 0x802c3000
frame               caller     <image>:function + offset
 0 802c2cf8 (+  48) 80059c28   <kernel_x86> context_switch(thread*: 0x817f0000, thread*: 0x80123870) + 0x003c
 1 802c2d28 (+  64) 80059f0f   <kernel_x86> simple_reschedule() + 0x029f
 2 802c2d68 (+  48) 8003e421   <kernel_x86>:_mutex_lock + 0x01b1
 3 802c2d98 (+  48) 8003d42b   <kernel_x86>:recursive_lock_lock + 0x0053
 4 802c2dc8 (+  48) 8006da48   <kernel_x86> devfs_get_vnode(fs_volume*: 0x80f77284, int64: 212, fs_vnode*: 0xbbf33e14, 0x802c2e3c, 0x802c2e40, true) + 0x0028
 5 802c2df8 (+  80) 800954a8   <kernel_x86> get_vnode(int32: 2, int64: 212, vnode*: 0x802c2e94, true, int32: 1) + 0x0168
 6 802c2e48 (+  80) 80099023   <kernel_x86>:get_vnode + 0x003f
 7 802c2e98 (+  48) 8006f50b   <kernel_x86> devfs_unpublish_device(BaseDevice*: 0x811993f0, true) + 0x0023
 8 802c2ec8 (+  80) 80073095   <kernel_x86> republish_driver(legacy_driver*: 0x810b4d20) + 0x02ed
 9 802c2f18 (+  48) 80075721   <kernel_x86>:legacy_driver_rescan + 0x0075
10 802c2f48 (+  32) 8006f592   <kernel_x86>:devfs_rescan_driver + 0x0012
11 802c2f68 (+  48) 80748f73   <usb> Stack<0x80f99690>::RescanDrivers(rescan_item*: 0x8101eb68) + 0x001b
12 802c2f98 (+  64) 80748d07   <usb> Stack<0x80f99690>::ExploreThread(NULL) + 0x0107
13 802c2fd8 (+  32) 800532ab   <kernel_x86> _create_kernel_thread_kentry() + 0x001b
14 802c2ff8 (+2144587784) 80053248   <kernel_x86> thread_kthread_exit() + 0x0000

[axeld]

Fixed in hrev28551.