Cryptography on (and in) Linux

markus reichelt | 22 Oct 2008 14:12

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

headers

Kadir | 22 Oct 2008 16:17

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.

headers

Matthias Kaehlcke | 23 Oct 2008 12:22

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

headers

markus reichelt | 23 Oct 2008 13:29

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

headers

Matthias Kaehlcke | 23 Oct 2008 14:51

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

headers

markus reichelt | 23 Oct 2008 15:49

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

headers

Matthias Kaehlcke | 23 Oct 2008 15:59

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

headers

Matthias Kaehlcke | 24 Oct 2008 10:07

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

headers

Jari Ruusu | 28 Oct 2008 14:19

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

headers

Matthias Kaehlcke | 29 Oct 2008 11:46

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

2	December 2010
4	November 2010
5	October 2010
4	September 2010
3	August 2010
2	July 2010
3	June 2010
2	May 2010
2	April 2010
4	January 2010
6	November 2009
26	October 2009
9	September 2009
7	August 2009
4	July 2009
4	June 2009
19	May 2009
4	April 2009
25	March 2009
1	February 2009
19	January 2009
2	December 2008
17	November 2008
13	October 2008
5	September 2008
23	August 2008
4	July 2008
21	June 2008
16	May 2008
8	March 2008
38	February 2008
19	January 2008
16	December 2007
13	November 2007
11	October 2007
40	September 2007
53	August 2007
32	July 2007
16	June 2007
63	May 2007
27	April 2007
24	March 2007
63	February 2007
27	January 2007
11	December 2006
24	November 2006
3	October 2006
16	September 2006
16	August 2006
22	July 2006
48	June 2006
51	May 2006
34	April 2006
37	March 2006
37	February 2006
43	January 2006
20	December 2005
42	November 2005
62	October 2005
52	September 2005
40	August 2005
43	July 2005
89	June 2005
41	May 2005
55	April 2005
47	March 2005
35	February 2005
102	January 2005
12	December 2004
21	November 2004
48	October 2004
46	September 2004
110	August 2004
95	July 2004
41	June 2004
18	May 2004
29	April 2004
32	March 2004
28	February 2004
16	January 2004
39	December 2003
27	November 2003
21	October 2003
56	September 2003
61	August 2003
7	July 2003

Mon	Tue	Wed	Thu	Fri	Sat	Sun

		1	2	3	4	5
6	7	8	9	10	11	12
13	14	15	16	17	18	19
20	21	22	23	24	25	26
27	28	29	30	31