markus reichelt | 22 Oct 14:12 2008
Picon

Re: Embedding keys and vulnerabilities

* Phil <philtickle200 <at> yahoo.com> wrote:

> So, my question is this: could an attacker looking at a partition
> encrypted in this way (which appears random), but knowing that at
> so-many bytes from the beginning there might be a loop-aes
> encrypted gpg key which will either have the loop-aes encrypted
> acii plaintext string above or loop-aes encrypted gpg binary
> headers, use this knowledge to crack the first (top) layer of
> encryption?

Well, there is a filesystem of your choice on that partition anyway
and its structure is known. Given that there are only so much
filesystems you can put to use you already have a known plaintext
issue of some sort. Same stuff applies for widely-used binaries,
document formats / headers etc.

In short, nope.

--

-- 
left blank, right bald
Kadir | 22 Oct 16:17 2008
Picon

OpenSSL verification problem

Hi,

I created a Certificate Authority with using openssl and CA.pl. I can sign a file with the following openssl command without any problem.

# openssl smime -sign -in hello.txt -out hello.sign -outform pem -inkey demoCA/private/cakey.pem -signer demoCA/cacert.pem

But I can't verify the signed file with the following code. And after running this command I receive the following error message. How can I solve this problem.

# openssl smime -verify -inform PEM -in hello.sign -content hello.txt  -CAfile demoCA/cacert.pem

Merhaba Dunya
Verification failure
1893:error:21071065:PKCS7 routines:PKCS7_signatureVerify:digest failure:pk7_doit.c:948:
1893:error :21075069:PKCS7 routines:PKCS7_verify:signature failure:pk7_smime.c:312:

Sincerelly,
Kadir.


Matthias Kaehlcke | 23 Oct 12:22 2008
Picon

loop-AES: timer softirq blocked after USB disconnect?

Hi,

i use loop-AES on a USB flash device. when unplugging the device while 
reading from it, the execution of the timer softirq (and others?) seems 
to be blocked for 250ms. our device has a hardware watchdog that relies 
on a kernel timer to be triggered. i don't observe this behaviour 
without encryption.

the platform is ep9307 (ARM) based, running a linux 2.6.20 and loop-AES 3.2c

below some traces:

[   89.890000] __run_timers()
[   89.900000] __run_timers()
[   89.910000] __run_timers()
[   89.920000] __run_timers()
[   89.930000] __run_timers()
[   89.930000] usb 1-3: USB disconnect, address 2
[   89.940000] __run_timers()
[   89.940000] sd 0:0:0:0: SCSI error: return code = 0x00010000
[   89.940000] end_request: I/O error, dev sda, sector 6981704
[   89.950000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.950000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.960000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   90.230000] __run_timers()
[   90.230000] sd 0:0:0:0: SCSI error: return code = 0x00010000
[   90.240000] end_request: I/O error, dev sda, sector 6981736
[   90.240000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   90.250000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   90.250000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   90.260000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
[   90.260000] __run_timers()
[   90.280000] __run_timers()
[   90.290000] __run_timers()
[   90.300000] __run_timers()
[   90.310000] __run_timers()
[   90.320000] __run_timers()
[   90.330000] __run_timers()
[   90.340000] __run_timers()

any idea what could be the problem?
Attachment (mkaehlcke.vcf): text/x-vcard, 336 bytes
markus reichelt | 23 Oct 13:29 2008
Picon

Re: loop-AES: timer softirq blocked after USB disconnect?

* Matthias Kaehlcke <mkaehlcke <at> e2s.net> wrote:

> i use loop-AES on a USB flash device. when unplugging the device
> while reading from it,

Why would you do that?

> any idea what could be the problem?

^^ obvious.

--

-- 
left blank, right bald
Matthias Kaehlcke | 23 Oct 14:51 2008
Picon

Re: loop-AES: timer softirq blocked after USB disconnect?

[replying to my own mail as i didn't received your response (i'm not 
subscribed to the list]

markus reichelt wrote:

 > * Matthias Kaehlcke <mkaehlcke <at> xxxxxxx> wrote:
 >
 > > i use loop-AES on a USB flash device. when unplugging the device
 > > while reading from it,
 >
 > Why would you do that?

though i don't like it, it is a possible use case that a user unplugs 
the USB device :(

the problem with the timers not being launched is that a hardware 
watchdog times out an resets the device ...

 > any idea what could be the problem?
 >
 > ^^ obvious.

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?

Attachment (mkaehlcke.vcf): text/x-vcard, 336 bytes
markus reichelt | 23 Oct 15:49 2008
Picon

Re: loop-AES: timer softirq blocked after USB disconnect?

* Matthias Kaehlcke <mkaehlcke <at> e2s.net> 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.

Also, the USB setup: Is the stick connected directly or via hub? What
about scheduler? PREEMPT? I'm just taking a wild guess here.

The USB mailing list at linux-usb <at> vger.kernel.org might be a better
place to ask, people there have a deeper knowledge about things that
could cause your problem. Worth a try.

--

-- 
left blank, right bald
Matthias Kaehlcke | 23 Oct 15:59 2008
Picon

Re: loop-AES: timer softirq blocked after USB disconnect?

Hi Markus,

markus reichelt wrote:
> * Matthias Kaehlcke <mkaehlcke <at> e2s.net> 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

> The USB mailing list at linux-usb <at> vger.kernel.org might be a better
> place to ask, people there have a deeper knowledge about things that
> could cause your problem. Worth a try.

thanks for the pointer, i'll give it a try

thanks for you response!
Attachment (mkaehlcke.vcf): text/x-vcard, 336 bytes
Matthias Kaehlcke | 24 Oct 10:07 2008
Picon

Re: loop-AES: timer softirq blocked after USB disconnect?

Matthias Kaehlcke wrote:

> markus reichelt wrote:
>> * Matthias Kaehlcke <mkaehlcke <at> e2s.net> 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
Attachment (mkaehlcke.vcf): text/x-vcard, 336 bytes
Jari Ruusu | 28 Oct 14:19 2008
Picon
Picon

Announce loop-AES-v3.2d file/swap crypto package

loop-AES changes since previous release:
- Worked around minix mkfs regression in build-initrd.sh script. Fix from
  Boris Wesslowski.
- Added -f option to losetup. Patch from Max Vozeler.
- Worked around block layer interface breakage on linux-2.6.28-rc kernels.

bzip2 compressed tarball is here:

    http://loop-aes.sourceforge.net/loop-AES/loop-AES-v3.2d.tar.bz2
    md5sum 8fc224978ee1f53c07a3771e733b777c

    http://loop-aes.sourceforge.net/loop-AES/loop-AES-v3.2d.tar.bz2.sign

--

-- 
Jari Ruusu  1024R/3A220F51 5B 4B F9 BB D3 3F 52 E9  DB 1D EB E3 24 0E A9 DD
Matthias Kaehlcke | 29 Oct 11:46 2008
Picon

Re: loop-AES: timer softirq blocked after USB disconnect?

hi,

Matthias Kaehlcke wrote:

> i use loop-AES on a USB flash device. when unplugging the device while 
> reading from it, the execution of the timer softirq (and others?) seems 
> to be blocked for 250ms. our device has a hardware watchdog that relies 
> on a kernel timer to be triggered. i don't observe this behaviour 
> without encryption.
> 
> the platform is ep9307 (ARM) based, running a linux 2.6.20 and loop-AES 
> 3.2c
> 
> below some traces:
> 
> [   89.890000] __run_timers()
> [   89.900000] __run_timers()
> [   89.910000] __run_timers()
> [   89.920000] __run_timers()
> [   89.930000] __run_timers()
> [   89.930000] usb 1-3: USB disconnect, address 2
> [   89.940000] __run_timers()
> [   89.940000] sd 0:0:0:0: SCSI error: return code = 0x00010000
> [   89.940000] end_request: I/O error, dev sda, sector 6981704
> [   89.950000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.950000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.960000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   89.970000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   90.230000] __run_timers()
> [   90.230000] sd 0:0:0:0: SCSI error: return code = 0x00010000
> [   90.240000] end_request: I/O error, dev sda, sector 6981736
> [   90.240000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   90.250000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   90.250000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   90.260000] loop1: loop_end_io_transfer err=-5 bi_rw=0x0
> [   90.260000] __run_timers()
> [   90.280000] __run_timers()
> [   90.290000] __run_timers()
> [   90.300000] __run_timers()
> [   90.310000] __run_timers()
> [   90.320000] __run_timers()
> [   90.330000] __run_timers()
> [   90.340000] __run_timers()

using ftrace and printk i have been able to figure out something more 
about the behaviour. it's not only the timer softirq that's not 
executing, all interrupts are disabled for 250ms.

the execution path is:

scsi_run_queue
   blk_run_queue
     __blk_run_queue
       scsi_request_fn
         elv_next_request
           end_queued_request
             __blk_end_request
               __end_that_request_first
                 req_bio_endio
                   bio_endio
                     loop_end_io_transfer

blk_run_queue() acquires the spin lock of the request queue and disables 
interrupts. at the end of the call chain loop_end_io_transfer() calls 
printk() in case of error. these (+/- 50) invokations of printk() seem 
to cause a significant delay while interrupts remain disabled. when 
commenting printk() in loop_end_io_transfer() the system behaves normally.

that's how far i could get with my limited knowledge of kernel 
internals. the easy solution for my problem is commenting the printk() 
call, but i think it would be interesting to know what's the root of the 
problem
Attachment (mkaehlcke.vcf): text/x-vcard, 336 bytes

Gmane