Matthias Kaehlcke wrote:
markus reichelt wrote:
* Matthias Kaehlcke <mkaehlcke@xxxxxxx> wrote:
i totally agree that unplugging the device without unmounting it
previously isn't how things should be done and can have side
effects. but is it really obvious that the timer softirq isn't
executed during ~250ms because an USB device is uncleanly
unplugged?
I've had my fair share of USB fun myself, yeah.
The problem is difficult to track, you are using an old kernel. If
it's possible to use a recent kernel, I'd try that first.
i tried it with 2.6.26.3 (have some prob with USB and 2.6.27) but with
the same result :(
adding more traces i see that the softirq is raised by the timer ISR but
not executed
Also, the USB setup: Is the stick connected directly or via hub? What
about scheduler? PREEMPT? I'm just taking a wild guess here.
it's connected directly. PREEMPT is enabled, i'll try what happens when
disabling it
doesn't help either
fyi: i made a test with an unencrypted loop (using the standard loop
driver). the result is somewhat different, but might give an important clue:
[42950404.410000] usb 1-3: USB disconnect, address 3
[42950404.460000] sd 1:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT
driverbyte=DRIVER_OK,SUGGEST_OK
[42950404.470000] end_request: I/O error, dev sdb, sector 181704
[42950404.470000] Buffer I/O error on device sdb1, logical block 22709
[42950404.480000] Buffer I/O error on device sdb1, logical block 22710
[42950404.480000] Buffer I/O error on device sdb1, logical block 22711
[42950404.490000] Buffer I/O error on device sdb1, logical block 22712
[42950404.500000] Buffer I/O error on device sdb1, logical block 22717
[42950404.500000] Buffer I/O error on device sdb1, logical block 22718
[42950404.500000] Buffer I/O error on device sdb1, logical block 22719
[42950404.500000] Buffer I/O error on device sdb1, logical block 22720
[42950404.500000] Buffer I/O error on device sdb1, logical block 22721
[42950404.500000] Buffer I/O error on device sdb1, logical block 22722
[42950404.540000] watchdog: executing timer ...
[42950404.540000] sd 1:0:0:0: [sdb] Result: hostbyte=DID_NO_CONNECT
driverbyte=DRIVER_OK,SUGGEST_OK
[42950404.550000] end_request: I/O error, dev sdb, sector 181736
[42950405.250000]
[42950405.250000] =======================================================
[42950405.250000] [ INFO: possible circular locking dependency detected ]
[42950405.250000] 2.6.26.3 #20
[42950405.250000] -------------------------------------------------------
[42950405.250000] exe/7044 is trying to acquire lock:
[42950405.250000] (&bdev->bd_mutex){--..}, at: [<c00dcaf0>]
__blkdev_put+0x28/0x158
[42950405.250000]
[42950405.250000] but task is already holding lock:
[42950405.250000] (&lo->lo_ctl_mutex){--..}, at: [<c01a0fb0>]
lo_ioctl+0x3c/0x8c0
[42950405.250000]
[42950405.250000] which lock already depends on the new lock.
[42950405.250000]
[42950405.250000]
[42950405.250000] the existing dependency chain (in reverse order) is:
[42950405.250000]
[42950405.250000] -> #1 (&lo->lo_ctl_mutex){--..}:
[42950405.250000] [<c007b810>] lock_acquire+0x8c/0xa8
[42950405.250000] [<c02a512c>] mutex_lock_nested+0xa8/0x2b0
[42950405.250000] [<c01a04ac>] lo_open+0x28/0x44
[42950405.250000] [<c00dce14>] do_open+0x98/0x2e8
[42950405.250000] [<c00dd2c0>] blkdev_open+0x38/0x78
[42950405.250000] [<c00ad668>] __dentry_open+0x10c/0x2b0
[42950405.250000] [<c00ad850>] nameidata_to_filp+0x44/0x50
[42950405.250000] [<c00bb700>] do_filp_open+0x1cc/0x774
[42950405.250000] [<c00ad45c>] do_sys_open+0x58/0xe4
[42950405.250000] [<c00ad520>] sys_open+0x24/0x28
[42950405.250000] [<c003bb60>] ret_fast_syscall+0x0/0x2c
[42950405.250000]
[42950405.250000] -> #0 (&bdev->bd_mutex){--..}:
[42950405.250000] [<c007b810>] lock_acquire+0x8c/0xa8
[42950405.250000] [<c02a512c>] mutex_lock_nested+0xa8/0x2b0
[42950405.250000] [<c00dcaf0>] __blkdev_put+0x28/0x158
[42950405.250000] [<c00dcc34>] blkdev_put+0x14/0x18
[42950405.250000] [<c00dd8c8>] blkdev_close+0x30/0x44
[42950405.250000] [<c00b07c4>] __fput+0xbc/0x1b4
[42950405.250000] [<c00b0bd0>] fput+0x34/0x38
[42950405.250000] [<c01a0ac4>] loop_clr_fd+0x120/0x15c
[42950405.250000] [<c01a118c>] lo_ioctl+0x218/0x8c0
[42950405.250000] [<c01512f0>] blkdev_driver_ioctl+0x80/0x8c
[42950405.250000] [<c0151554>] blkdev_ioctl+0x258/0x884
[42950405.250000] [<c00dc38c>] block_ioctl+0x2c/0x30
[42950405.250000] [<c00bcb2c>] vfs_ioctl+0x38/0x9c
[42950405.250000] [<c00bcc00>] do_vfs_ioctl+0x70/0x304
[42950405.250000] [<c00bced4>] sys_ioctl+0x40/0x64
[42950405.250000] [<c003bb60>] ret_fast_syscall+0x0/0x2c
[42950405.250000]
[42950405.250000] other info that might help us debug this:
[42950405.250000]
[42950405.250000] 1 lock held by exe/7044:
[42950405.250000] #0: (&lo->lo_ctl_mutex){--..}, at: [<c01a0fb0>]
lo_ioctl+0x3c/0x8c0
[42950405.250000]
[42950405.250000] stack backtrace:
[42950405.250000] [<c003fee4>] (dump_stack+0x0/0x14) from [<c0078c44>]
(print_circular_bug_tail+0x80/0x94)
[42950405.250000] [<c0078bc4>] (print_circular_bug_tail+0x0/0x94) from
[<c007b46c>] (__lock_acquire+0xce4/0xffc)
[42950405.250000] r5:c1c98418 r4:c1c983e0
[42950405.250000] [<c007a788>] (__lock_acquire+0x0/0xffc) from
[<c007b810>] (lock_acquire+0x8c/0xa8)
[42950405.250000] [<c007b784>] (lock_acquire+0x0/0xa8) from [<c02a512c>]
(mutex_lock_nested+0xa8/0x2b0)
[42950405.250000] r6:c191c000 r5:60000013 r4:c0fc0ccc
[42950405.250000] [<c02a5084>] (mutex_lock_nested+0x0/0x2b0) from
[<c00dcaf0>] (__blkdev_put+0x28/0x158)
[42950405.250000] [<c00dcac8>] (__blkdev_put+0x0/0x158) from
[<c00dcc34>] (blkdev_put+0x14/0x18)
[42950405.250000] [<c00dcc20>] (blkdev_put+0x0/0x18) from [<c00dd8c8>]
(blkdev_close+0x30/0x44)
[42950405.250000] [<c00dd898>] (blkdev_close+0x0/0x44) from [<c00b07c4>]
(__fput+0xbc/0x1b4)
[42950405.250000] r4:00000008
[42950405.250000] [<c00b0708>] (__fput+0x0/0x1b4) from [<c00b0bd0>]
(fput+0x34/0x38)
[42950405.250000] [<c00b0b9c>] (fput+0x0/0x38) from [<c01a0ac4>]
(loop_clr_fd+0x120/0x15c)
[42950405.250000] [<c01a09a4>] (loop_clr_fd+0x0/0x15c) from [<c01a118c>]
(lo_ioctl+0x218/0x8c0)
[42950405.250000] [<c01a0f74>] (lo_ioctl+0x0/0x8c0) from [<c01512f0>]
(blkdev_driver_ioctl+0x80/0x8c)
[42950405.250000] [<c0151270>] (blkdev_driver_ioctl+0x0/0x8c) from
[<c0151554>] (blkdev_ioctl+0x258/0x884)
[42950405.250000] [<c01512fc>] (blkdev_ioctl+0x0/0x884) from
[<c00dc38c>] (block_ioctl+0x2c/0x30)
[42950405.250000] [<c00dc360>] (block_ioctl+0x0/0x30) from [<c00bcb2c>]
(vfs_ioctl+0x38/0x9c)
[42950405.250000] r4:c128e2e0
[42950405.250000] [<c00bcaf4>] (vfs_ioctl+0x0/0x9c) from [<c00bcc00>]
(do_vfs_ioctl+0x70/0x304)
[42950405.250000] r6:00000000 r5:c128e2e0 r4:c1b120ec
[42950405.250000] [<c00bcb90>] (do_vfs_ioctl+0x0/0x304) from
[<c00bced4>] (sys_ioctl+0x40/0x64)
[42950405.250000] r8:c003bd04 r7:00000036 r6:00004c01 r5:fffffff7
r4:c128e2e0
[42950405.250000] [<c00bce94>] (sys_ioctl+0x0/0x64) from [<c003bb60>]
(ret_fast_syscall+0x0/0x2c)
[42950405.250000] r6:00000000 r5:00000001 r4:00000003
with loop-AES the lockdep message doesn't show up, but the behaviour
(softirqs blocked) is the same.
i reported this to the LKML and the block system maintainer
begin:vcard
fn:Matthias Kaehlcke
n:Kaehlcke;Matthias
org:Electronic Engineering Solutions;Dept. de Software
adr:;;C/ Sant Ferran, 10-16 bajos;Barcelona;;08031;Spain
email;internet:mkaehlcke@xxxxxxx
title:Ingeniero de Firmware
tel;work:93 407 30 80
tel;fax:93 433 56 71
x-mozilla-html:FALSE
url:http://www.e2s.net
version:2.1
end:vcard
