FAQ Search Today's Posts Mark Forums Read
» Video Reviews

» Linux Archive

Linux-archive is a website aiming to archive linux email lists and to make them easily accessible for linux users/developers.


» Sponsor

» Partners

» Sponsor

Go Back   Linux Archive > Debian > Debian Kernel

 
 
LinkBack Thread Tools
 
Old 06-02-2010, 11:16 PM
Ben Hutchings
 
Default Bug#584273: previous dmesg logs were incomplete

Here's what's happening:

On Wed, 2010-06-02 at 22:45 +0200, Tshepang Lekhonkhobe wrote:
[...]
> [ 2.430983] kjournald starting. Commit interval 5 seconds
> [ 2.431049] EXT3-fs: mounted filesystem with ordered data mode.

Root filesystem is mounted.

[...]
> [ 4.908444] tpm_tis 00:0b: 1.2 TPM (device-id 0xB, rev-id 16)

tpm_tis is loaded. I thought it was loaded from the initramfs, but I
was wrong. This is why 'blacklist=tpm_tis' on the kernel command line
did not work. Instead, you should add:

blacklist tpm_tis

to the file /etc/modprobe.d/blacklist.conf.

tpm_tis now tries to send 3 commands to the TPM, but doesn't receive any
response. Eventually it gives up on them (time-out). For this whole
time it is holding a lock which blocks parport_pc (parallel port driver)
from initialising:

[...]
> [ 127.164184] tpm_tis 00:0b: tpm_transmit: tpm_send: error 4294967234
[...]
> [ 240.560099] INFO: task modprobe:700 blocked for more than 120 seconds.
> [ 240.560107] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 240.560114] modprobe D c14b47e0 0 700 635 0x00000000
> [ 240.560126] f678f300 00000086 f67abe6c c14b47e0 00000000 c1415040
> c1415040 c1410604
> [ 240.560141] f678f4bc c2a08040 00000001 24b6f700 00000001 00000001
> 00000000 00000000
> [ 240.560156] c2a03604 f678f4bc fffedfd3 000007ff 00000078 00000000
> 00000000 000007ff
> [ 240.560171] Call Trace:
> [ 240.560188] [<c126cda9>] ? schedule_timeout+0x20/0xb0
> [ 240.560201] [<c10f33fa>] ? sysfs_find_dirent+0x13/0x23
> [ 240.560210] [<c10f3805>] ? sysfs_addrm_finish+0x13/0x199
> [ 240.560218] [<c10f354f>] ? sysfs_add_one+0x11/0xb8
> [ 240.560226] [<c126d588>] ? __down_common+0x7c/0xbe
> [ 240.560250] [<c1047bcf>] ? down+0x1f/0x2c
> [ 240.560262] [<c11b2a05>] ? __driver_attach+0x27/0x5b
> [ 240.560270] [<c11b238d>] ? bus_for_each_dev+0x37/0x5f
> [ 240.560280] [<c11b281d>] ? driver_attach+0x11/0x13
> [ 240.560289] [<c11b29de>] ? __driver_attach+0x0/0x5b
> [ 240.560297] [<c11b1e55>] ? bus_add_driver+0x99/0x1c5
> [ 240.560306] [<c11b2c4f>] ? driver_register+0x87/0xe0
> [ 240.560324] [<f8488318>] ? parport_pc_init+0x284/0x330 [parport_pc]
> [ 240.560341] [<f8488094>] ? parport_pc_init+0x0/0x330 [parport_pc]
> [ 240.560350] [<c100113e>] ? do_one_initcall+0x55/0x155
> [ 240.560360] [<c1057dd9>] ? sys_init_module+0xa7/0x1d7
> [ 240.560368] [<c10030fb>] ? sysenter_do_call+0x12/0x28
[...]
> [ 249.420078] tpm_tis 00:0b: tpm_transmit: tpm_send: error 4294967234
[...]
> [ 360.560086] INFO: task modprobe:700 blocked for more than 120 seconds.
> [ 360.560094] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 360.560101] modprobe D c14b47e0 0 700 635 0x00000000
> [ 360.560112] f678f300 00000086 f67abe6c c14b47e0 00000000 c1415040
> c1415040 c1410604
> [ 360.560128] f678f4bc c2a08040 00000001 24b6f700 00000001 00000001
> 00000000 00000000
> [ 360.560143] c2a03604 f678f4bc fffedfd3 000007ff 00000078 00000000
> 00000000 000007ff
> [ 360.560158] Call Trace:
> [ 360.560177] [<c126cda9>] ? schedule_timeout+0x20/0xb0
> [ 360.560189] [<c10f33fa>] ? sysfs_find_dirent+0x13/0x23
> [ 360.560198] [<c10f3805>] ? sysfs_addrm_finish+0x13/0x199
> [ 360.560206] [<c10f354f>] ? sysfs_add_one+0x11/0xb8
> [ 360.560214] [<c126d588>] ? __down_common+0x7c/0xbe
> [ 360.560261] [<c1047bcf>] ? down+0x1f/0x2c
> [ 360.560277] [<c11b2a05>] ? __driver_attach+0x27/0x5b
> [ 360.560285] [<c11b238d>] ? bus_for_each_dev+0x37/0x5f
> [ 360.560296] [<c11b281d>] ? driver_attach+0x11/0x13
> [ 360.560305] [<c11b29de>] ? __driver_attach+0x0/0x5b
> [ 360.560313] [<c11b1e55>] ? bus_add_driver+0x99/0x1c5
> [ 360.560323] [<c11b2c4f>] ? driver_register+0x87/0xe0
> [ 360.560342] [<f8488318>] ? parport_pc_init+0x284/0x330 [parport_pc]
> [ 360.560358] [<f8488094>] ? parport_pc_init+0x0/0x330 [parport_pc]
> [ 360.560368] [<c100113e>] ? do_one_initcall+0x55/0x155
> [ 360.560378] [<c1057dd9>] ? sys_init_module+0xa7/0x1d7
> [ 360.560386] [<c10030fb>] ? sysenter_do_call+0x12/0x28
> [ 370.172112] tpm_tis 00:0b: tpm_transmit: tpm_send: error 4294967234

Now tpm_tis is done and releases the lock, so parport_pc can continue:

> [ 370.175858] parport_pc 00:0a: activated
> [ 370.175869] parport_pc 00:0a: reported by Plug and Play ACPI
> [ 370.175998] parport0: PC-style at 0x378 (0x778), irq 5 [PCSPP,TRISTATE]
> [ 370.276537] lp0: using parport0 (interrupt-driven).
[...]

While you can work around this through blacklist.conf, there is at least
two bugs here:
1. The time-out used in tpm_tis is too long. (Or the time-out set by
the BIOS is too long, and tpm/tpm_tis are blindly trusting it.)
2. tpm_tis is ignoring the lack of response to these initial commands
and is struggling on rather than treating it as a failure.

I assume that this is only happening now because tpm_tis was not
previously loaded automatically; this was changed in stable version
2.6.32.12 (Debian version 2.6.32-12). This may have been a bad move,
considering these bugs.

Ben.

--
Ben Hutchings
Once a job is fouled up, anything done to improve it makes it worse.
 
Old 06-04-2010, 02:55 PM
Rajiv Andrade
 
Default Bug#584273: previous dmesg logs were incomplete

What's happening here is that this TPM seems to not be setting a proper
status flag after a command is sent to it, so the device driver keeps
waiting for such status flag to be set and then timeouts the attempt.

The TPM has three timeout values, and the longest one is by default
2min, given the TPM can take a good amount of time to perform asymmetric
operations. If the command being sent to the TPM isn't recognized by the
device driver, it assumes the timeout should be the maximum.

So, to accommodate this TPM the device driver should just wait for such
status to be set, in case it's doesn't, set an internal (device driver
space) flag to stop returning an error after the timeout gets reached.

I've sent a patch to a redhat bugzilla #530393 to check which ordinal is
being sent to this TPM, since it shouldn't use the 2min timeout for all
commands, just for the ones that aren't hardset in the device driver,
and also prints the status value after a command was sent to it. I'd
appreciate if someone could return the results when with the patch, but
for now I'm going to send a patch that implements the workaround I've
mentioned above.

Thanks,
Rajiv Andrade
Security Development
IBM Linux Technology Center

On Thu, 2010-06-03 at 00:16 +0100, Ben Hutchings wrote:
> Here's what's happening:
>
> On Wed, 2010-06-02 at 22:45 +0200, Tshepang Lekhonkhobe wrote:
> [...]
> > [ 2.430983] kjournald starting. Commit interval 5 seconds
> > [ 2.431049] EXT3-fs: mounted filesystem with ordered data mode.
>
> Root filesystem is mounted.
>
> [...]
> > [ 4.908444] tpm_tis 00:0b: 1.2 TPM (device-id 0xB, rev-id 16)
>
> tpm_tis is loaded. I thought it was loaded from the initramfs, but I
> was wrong. This is why 'blacklist=tpm_tis' on the kernel command line
> did not work. Instead, you should add:
>
> blacklist tpm_tis
>
> to the file /etc/modprobe.d/blacklist.conf.
>
> tpm_tis now tries to send 3 commands to the TPM, but doesn't receive any
> response. Eventually it gives up on them (time-out). For this whole
> time it is holding a lock which blocks parport_pc (parallel port driver)
> from initialising:
>
> [...]
> > [ 127.164184] tpm_tis 00:0b: tpm_transmit: tpm_send: error 4294967234
> [...]
> > [ 240.560099] INFO: task modprobe:700 blocked for more than 120 seconds.
> > [ 240.560107] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [ 240.560114] modprobe D c14b47e0 0 700 635 0x00000000
> > [ 240.560126] f678f300 00000086 f67abe6c c14b47e0 00000000 c1415040
> > c1415040 c1410604
> > [ 240.560141] f678f4bc c2a08040 00000001 24b6f700 00000001 00000001
> > 00000000 00000000
> > [ 240.560156] c2a03604 f678f4bc fffedfd3 000007ff 00000078 00000000
> > 00000000 000007ff
> > [ 240.560171] Call Trace:
> > [ 240.560188] [<c126cda9>] ? schedule_timeout+0x20/0xb0
> > [ 240.560201] [<c10f33fa>] ? sysfs_find_dirent+0x13/0x23
> > [ 240.560210] [<c10f3805>] ? sysfs_addrm_finish+0x13/0x199
> > [ 240.560218] [<c10f354f>] ? sysfs_add_one+0x11/0xb8
> > [ 240.560226] [<c126d588>] ? __down_common+0x7c/0xbe
> > [ 240.560250] [<c1047bcf>] ? down+0x1f/0x2c
> > [ 240.560262] [<c11b2a05>] ? __driver_attach+0x27/0x5b
> > [ 240.560270] [<c11b238d>] ? bus_for_each_dev+0x37/0x5f
> > [ 240.560280] [<c11b281d>] ? driver_attach+0x11/0x13
> > [ 240.560289] [<c11b29de>] ? __driver_attach+0x0/0x5b
> > [ 240.560297] [<c11b1e55>] ? bus_add_driver+0x99/0x1c5
> > [ 240.560306] [<c11b2c4f>] ? driver_register+0x87/0xe0
> > [ 240.560324] [<f8488318>] ? parport_pc_init+0x284/0x330 [parport_pc]
> > [ 240.560341] [<f8488094>] ? parport_pc_init+0x0/0x330 [parport_pc]
> > [ 240.560350] [<c100113e>] ? do_one_initcall+0x55/0x155
> > [ 240.560360] [<c1057dd9>] ? sys_init_module+0xa7/0x1d7
> > [ 240.560368] [<c10030fb>] ? sysenter_do_call+0x12/0x28
> [...]
> > [ 249.420078] tpm_tis 00:0b: tpm_transmit: tpm_send: error 4294967234
> [...]
> > [ 360.560086] INFO: task modprobe:700 blocked for more than 120 seconds.
> > [ 360.560094] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [ 360.560101] modprobe D c14b47e0 0 700 635 0x00000000
> > [ 360.560112] f678f300 00000086 f67abe6c c14b47e0 00000000 c1415040
> > c1415040 c1410604
> > [ 360.560128] f678f4bc c2a08040 00000001 24b6f700 00000001 00000001
> > 00000000 00000000
> > [ 360.560143] c2a03604 f678f4bc fffedfd3 000007ff 00000078 00000000
> > 00000000 000007ff
> > [ 360.560158] Call Trace:
> > [ 360.560177] [<c126cda9>] ? schedule_timeout+0x20/0xb0
> > [ 360.560189] [<c10f33fa>] ? sysfs_find_dirent+0x13/0x23
> > [ 360.560198] [<c10f3805>] ? sysfs_addrm_finish+0x13/0x199
> > [ 360.560206] [<c10f354f>] ? sysfs_add_one+0x11/0xb8
> > [ 360.560214] [<c126d588>] ? __down_common+0x7c/0xbe
> > [ 360.560261] [<c1047bcf>] ? down+0x1f/0x2c
> > [ 360.560277] [<c11b2a05>] ? __driver_attach+0x27/0x5b
> > [ 360.560285] [<c11b238d>] ? bus_for_each_dev+0x37/0x5f
> > [ 360.560296] [<c11b281d>] ? driver_attach+0x11/0x13
> > [ 360.560305] [<c11b29de>] ? __driver_attach+0x0/0x5b
> > [ 360.560313] [<c11b1e55>] ? bus_add_driver+0x99/0x1c5
> > [ 360.560323] [<c11b2c4f>] ? driver_register+0x87/0xe0
> > [ 360.560342] [<f8488318>] ? parport_pc_init+0x284/0x330 [parport_pc]
> > [ 360.560358] [<f8488094>] ? parport_pc_init+0x0/0x330 [parport_pc]
> > [ 360.560368] [<c100113e>] ? do_one_initcall+0x55/0x155
> > [ 360.560378] [<c1057dd9>] ? sys_init_module+0xa7/0x1d7
> > [ 360.560386] [<c10030fb>] ? sysenter_do_call+0x12/0x28
> > [ 370.172112] tpm_tis 00:0b: tpm_transmit: tpm_send: error 4294967234
>
> Now tpm_tis is done and releases the lock, so parport_pc can continue:
>
> > [ 370.175858] parport_pc 00:0a: activated
> > [ 370.175869] parport_pc 00:0a: reported by Plug and Play ACPI
> > [ 370.175998] parport0: PC-style at 0x378 (0x778), irq 5 [PCSPP,TRISTATE]
> > [ 370.276537] lp0: using parport0 (interrupt-driven).
> [...]
>
> While you can work around this through blacklist.conf, there is at least
> two bugs here:
> 1. The time-out used in tpm_tis is too long. (Or the time-out set by
> the BIOS is too long, and tpm/tpm_tis are blindly trusting it.)
> 2. tpm_tis is ignoring the lack of response to these initial commands
> and is struggling on rather than treating it as a failure.
>
> I assume that this is only happening now because tpm_tis was not
> previously loaded automatically; this was changed in stable version
> 2.6.32.12 (Debian version 2.6.32-12). This may have been a bad move,
> considering these bugs.
>
> Ben.
>





--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Archive: 1275663307.22654.12.camel@blackbox.ibm.com">http://lists.debian.org/1275663307.22654.12.camel@blackbox.ibm.com
 
Old 06-05-2010, 08:16 PM
Ben Hutchings
 
Default Bug#584273: previous dmesg logs were incomplete

On Fri, 2010-06-04 at 11:55 -0300, Rajiv Andrade wrote:
> What's happening here is that this TPM seems to not be setting a proper
> status flag after a command is sent to it, so the device driver keeps
> waiting for such status flag to be set and then timeouts the attempt.
>
> The TPM has three timeout values, and the longest one is by default
> 2min, given the TPM can take a good amount of time to perform asymmetric
> operations. If the command being sent to the TPM isn't recognized by the
> device driver, it assumes the timeout should be the maximum.
[...]

Blocking for up to 2 minutes in a probe function is totally
unacceptable, let alone the current 6 minutes. If you really think the
time-out needs to be that high, then this initialisation should be moved
to a work item that is scheduled by the probe function.

Ben.

--
Ben Hutchings
Once a job is fouled up, anything done to improve it makes it worse.
 

Thread Tools




All times are GMT. The time now is 03:02 AM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.
Copyright 2007 - 2008, www.linux-archive.org