Ok, this is one for those who like to look at weird crashes/bugs.
Here's a new regression that popped up in this merge window, there's
some sort of slab corruption going on in tty data structures:
[ 74.900215] =============================================================================
[ 74.908193] BUG kmalloc-8: Poison overwritten
[ 74.908193] -----------------------------------------------------------------------------
[ 74.908193]
[ 74.908193] INFO: 0x5d883a14-0x5d883a14. First byte 0x6a instead of 0x6b
[ 74.908193] INFO: Allocated in tty_ldisc_try_get+0x1a/0xb0 age=8015 cpu=0 pid=1
[ 74.908193] INFO: Freed in tty_ldisc_put+0x48/0x50 age=4 cpu=3 pid=4236
[ 74.908193] INFO: Slab 0x42c6eeb4 objects=73 used=61 fp=0x5d883a10 flags=0x1d0000c3
[ 74.908193] INFO: Object 0x5d883a10 @offset=2576 fp=0x5d883d90
[ 74.908193]
[ 74.908193] Bytes b4 0x5d883a00: 01 00 00 00 de 04 ff ff 5a 5a 5a 5a 5a 5a 5a 5a ....�.��ZZZZZZZZ
[ 74.908193] Object 0x5d883a10: 6b 6b 6b 6b 6a 6b 6b a5 kkkkjkk�
[ 74.908193] Redzone 0x5d883a18: bb bb bb bb ����
[ 74.908193] Padding 0x5d883a40: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
[ 74.908193] Pid: 4230, comm: mingetty Not tainted 2.6.30-tip #744
[ 74.908193] Call Trace:
[ 74.908193] [<410ae628>] print_trailer+0xc8/0xd0
[ 74.908193] [<410ae6a3>] check_bytes_and_report+0x73/0x90
[ 74.908193] [<410ae941>] check_object+0xa1/0x130
[ 74.908193] [<410aef1e>] alloc_debug_processing+0x5e/0xd0
[ 74.908193] [<410af99e>] __slab_alloc+0x11e/0x150
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<410afcdb>] kmem_cache_alloc+0x7b/0x120
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<413d9c7a>] tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<410b06a3>] ? __kmalloc+0x163/0x170
[ 74.908193] [<413d9d77>] tty_ldisc_get+0x17/0x40
[ 74.908193] [<413da63d>] tty_ldisc_init+0xd/0x30
[ 74.908193] [<413d4098>] initialize_tty_struct+0x38/0x210
[ 74.908193] [<413d5d6f>] tty_init_dev+0x4f/0xb0
[ 74.908193] [<413d5f25>] __tty_open+0x155/0x2d0
[ 74.908193] [<413d60b7>] tty_open+0x17/0x30
[ 74.908193] [<410bb599>] chrdev_open+0xe9/0x100
[ 74.908193] [<410b721e>] __dentry_open+0xbe/0x190
[ 74.908193] [<410b813c>] nameidata_to_filp+0x2c/0x50
[ 74.908193] [<410bb4b0>] ? chrdev_open+0x0/0x100
[ 74.908193] [<410c2eba>] do_filp_open+0x2aa/0x580
[ 74.908193] [<4100a1bb>] ? sched_clock+0xb/0x20
[ 74.908193] [<410596c7>] ? put_lock_stats+0x17/0x30
[ 74.908193] [<41059734>] ? lock_release_holdtime+0x54/0x60
[ 74.908193] [<4105d4d9>] ? lock_release_nested+0x99/0xd0
[ 74.908193] [<41377421>] ? debug_spin_unlock+0x21/0x80
[ 74.908193] [<41377495>] ? _raw_spin_unlock+0x15/0x20
[ 74.908193] [<410cad50>] ? alloc_fd+0xc0/0xd0
[ 74.908193] [<410b7020>] do_sys_open+0x40/0x80
[ 74.908193] [<410b70ae>] sys_open+0x1e/0x30
[ 74.908193] [<4100388f>] sysenter_do_call+0x12/0x3c
[ 74.908193] FIX kmalloc-8: Restoring 0x5d883a14-0x5d883a14=0x6b
[ 74.908193]
[ 74.908193] FIX kmalloc-8: Marking all objects used
It's a single bit corruption - but the hardware in question has a
good track record with thousands of bootups, so it might be a
reference count related corruption as well.
It started triggering in this merge window, so one of these might be
a starting point:
3e3b5c0: tty: use prepare/finish_wait
5fc5b42: tty: remove sleep_on
26a2e20: tty: Untangle termios and mm mutex dependencies
0b4068a: tty: simplify buffer allocator cleanups
c481c70: tty: remove buffer special casing
852e99d: tty: bring ldisc into CodingStyle
f2c4c65: tty: Move ldisc_flush
c65c9bc: tty: rewrite the ldisc locking
e8b70e7: tty: Extract various bits of ldisc code
5f0878a: tty: Fix oops when scanning the polling list for kgdb
38db897: tty: throttling race fix
1ec739b: tty: Implement a drain delay in the tty port
fcc8ac1: tty: Add carrier processing on close to the tty_port core
(But ... if it's a low-probability bug then it might be an older bug
as well.)
I tried two other reboots and the bug did not trigger in a way
visible in the log - so it's sporadic. I've started a reboot loop
with this kernel on that box, to see whether it's repeatable within
a reasonable amount of time.
This is the -tip testbox that generally triggers SMP races very well
(and as the first one amongst boxes) - so my first guess would be on
some narrow (or not so narrow but config/timing dependent) SMP race
window.
Since it's not reproducible in any easy fashion, there's no
bisection possible either, on this box. I've Cc:-ed all the
tty/kmalloc/race experts, maybe the bug can be seen ...
I've attached the config and the full bootlog.
Ingo
Hi Ingo,
Ingo Molnar wrote:
> Ok, this is one for those who like to look at weird crashes/bugs.
>
> Here's a new regression that popped up in this merge window, there's
> some sort of slab corruption going on in tty data structures:
>
> [ 74.900215] =============================================================================
> [ 74.908193] BUG kmalloc-8: Poison overwritten
> [ 74.908193] -----------------------------------------------------------------------------
> [ 74.908193]
> [ 74.908193] INFO: 0x5d883a14-0x5d883a14. First byte 0x6a instead of 0x6b
> [ 74.908193] INFO: Allocated in tty_ldisc_try_get+0x1a/0xb0 age=8015 cpu=0 pid=1
> [ 74.908193] INFO: Freed in tty_ldisc_put+0x48/0x50 age=4 cpu=3 pid=4236
> [ 74.908193] INFO: Slab 0x42c6eeb4 objects=73 used=61 fp=0x5d883a10 flags=0x1d0000c3
> [ 74.908193] INFO: Object 0x5d883a10 @offset=2576 fp=0x5d883d90
> [ 74.908193]
> [ 74.908193] Bytes b4 0x5d883a00: 01 00 00 00 de 04 ff ff 5a 5a 5a 5a 5a 5a 5a 5a ....�.��ZZZZZZZZ
> [ 74.908193] Object 0x5d883a10: 6b 6b 6b 6b 6a 6b 6b a5 kkkkjkk�
This is struct tty_ldisc and the corruption happens in the first byte of
->refcount. This probably just means that there's a race condition and
someone is doing tty_ldisc_deref() after tty_ldisc_put().
You could add something like
WARN_ON(ld->refcount == 0x6b)
to tty_ldisc_deref() to see if that triggers.
> [ 74.908193] Redzone 0x5d883a18: bb bb bb bb ����
> [ 74.908193] Padding 0x5d883a40: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
> [ 74.908193] Pid: 4230, comm: mingetty Not tainted 2.6.30-tip #744
> [ 74.908193] Call Trace:
> [ 74.908193] [<410ae628>] print_trailer+0xc8/0xd0
> [ 74.908193] [<410ae6a3>] check_bytes_and_report+0x73/0x90
> [ 74.908193] [<410ae941>] check_object+0xa1/0x130
> [ 74.908193] [<410aef1e>] alloc_debug_processing+0x5e/0xd0
> [ 74.908193] [<410af99e>] __slab_alloc+0x11e/0x150
> [ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
> [ 74.908193] [<410afcdb>] kmem_cache_alloc+0x7b/0x120
> [ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
> [ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
> [ 74.908193] [<413d9c7a>] tty_ldisc_try_get+0x1a/0xb0
> [ 74.908193] [<410b06a3>] ? __kmalloc+0x163/0x170
> [ 74.908193] [<413d9d77>] tty_ldisc_get+0x17/0x40
> [ 74.908193] [<413da63d>] tty_ldisc_init+0xd/0x30
> [ 74.908193] [<413d4098>] initialize_tty_struct+0x38/0x210
> [ 74.908193] [<413d5d6f>] tty_init_dev+0x4f/0xb0
> [ 74.908193] [<413d5f25>] __tty_open+0x155/0x2d0
> [ 74.908193] [<413d60b7>] tty_open+0x17/0x30
> [ 74.908193] [<410bb599>] chrdev_open+0xe9/0x100
> [ 74.908193] [<410b721e>] __dentry_open+0xbe/0x190
> [ 74.908193] [<410b813c>] nameidata_to_filp+0x2c/0x50
> [ 74.908193] [<410bb4b0>] ? chrdev_open+0x0/0x100
> [ 74.908193] [<410c2eba>] do_filp_open+0x2aa/0x580
> [ 74.908193] [<4100a1bb>] ? sched_clock+0xb/0x20
> [ 74.908193] [<410596c7>] ? put_lock_stats+0x17/0x30
> [ 74.908193] [<41059734>] ? lock_release_holdtime+0x54/0x60
> [ 74.908193] [<4105d4d9>] ? lock_release_nested+0x99/0xd0
> [ 74.908193] [<41377421>] ? debug_spin_unlock+0x21/0x80
> [ 74.908193] [<41377495>] ? _raw_spin_unlock+0x15/0x20
> [ 74.908193] [<410cad50>] ? alloc_fd+0xc0/0xd0
> [ 74.908193] [<410b7020>] do_sys_open+0x40/0x80
> [ 74.908193] [<410b70ae>] sys_open+0x1e/0x30
> [ 74.908193] [<4100388f>] sysenter_do_call+0x12/0x3c
> [ 74.908193] FIX kmalloc-8: Restoring 0x5d883a14-0x5d883a14=0x6b
> [ 74.908193]
> [ 74.908193] FIX kmalloc-8: Marking all objects used
>
> It's a single bit corruption - but the hardware in question has a
> good track record with thousands of bootups, so it might be a
> reference count related corruption as well.
>
> It started triggering in this merge window, so one of these might be
> a starting point:
>
> 3e3b5c0: tty: use prepare/finish_wait
> 5fc5b42: tty: remove sleep_on
> 26a2e20: tty: Untangle termios and mm mutex dependencies
> 0b4068a: tty: simplify buffer allocator cleanups
> c481c70: tty: remove buffer special casing
> 852e99d: tty: bring ldisc into CodingStyle
> f2c4c65: tty: Move ldisc_flush
> c65c9bc: tty: rewrite the ldisc locking
> e8b70e7: tty: Extract various bits of ldisc code
> 5f0878a: tty: Fix oops when scanning the polling list for kgdb
> 38db897: tty: throttling race fix
> 1ec739b: tty: Implement a drain delay in the tty port
> fcc8ac1: tty: Add carrier processing on close to the tty_port core
>
> (But ... if it's a low-probability bug then it might be an older bug
> as well.)
>
> I tried two other reboots and the bug did not trigger in a way
> visible in the log - so it's sporadic. I've started a reboot loop
> with this kernel on that box, to see whether it's repeatable within
> a reasonable amount of time.
>
> This is the -tip testbox that generally triggers SMP races very well
> (and as the first one amongst boxes) - so my first guess would be on
> some narrow (or not so narrow but config/timing dependent) SMP race
> window.
>
> Since it's not reproducible in any easy fashion, there's no
> bisection possible either, on this box. I've Cc:-ed all the
> tty/kmalloc/race experts, maybe the bug can be seen ...
>
> I've attached the config and the full bootlog.
>
> Ingo
>
On Sun, Jun 14, 2009 at 11:20 AM, Pekka Enberg<[email protected]> wrote:
> You could add something like
>
> ?WARN_ON(ld->refcount == 0x6b)
>
> to tty_ldisc_deref() to see if that triggers.
Make that
WARN_ON(ld->refcount == (int)0xa56b6b6b)
instead.
Pekka
On Sun, Jun 14, 2009 at 11:20 AM, Pekka Enberg<[email protected]> wrote:
>> You could add something like
>>
>> ?WARN_ON(ld->refcount == 0x6b)
>>
>> to tty_ldisc_deref() to see if that triggers.
On Sun, Jun 14, 2009 at 11:30 AM, Pekka Enberg<[email protected]> wrote:
> Make that
>
> ? ?WARN_ON(ld->refcount == (int)0xa56b6b6b)
>
> instead.
And oh, kmemcheck should be able to catch this too. :-)
* Pekka Enberg <[email protected]> wrote:
> Hi Ingo,
>
> Ingo Molnar wrote:
>> Ok, this is one for those who like to look at weird crashes/bugs.
>>
>> Here's a new regression that popped up in this merge window, there's
>> some sort of slab corruption going on in tty data structures:
>>
>> [ 74.900215] =============================================================================
>> [ 74.908193] BUG kmalloc-8: Poison overwritten
>> [ 74.908193] -----------------------------------------------------------------------------
>> [ 74.908193] [ 74.908193] INFO: 0x5d883a14-0x5d883a14. First byte
>> 0x6a instead of 0x6b
>> [ 74.908193] INFO: Allocated in tty_ldisc_try_get+0x1a/0xb0 age=8015 cpu=0 pid=1
>> [ 74.908193] INFO: Freed in tty_ldisc_put+0x48/0x50 age=4 cpu=3 pid=4236
>> [ 74.908193] INFO: Slab 0x42c6eeb4 objects=73 used=61 fp=0x5d883a10 flags=0x1d0000c3
>> [ 74.908193] INFO: Object 0x5d883a10 @offset=2576 fp=0x5d883d90
>> [ 74.908193] [ 74.908193] Bytes b4 0x5d883a00: 01 00 00 00 de 04
>> ff ff 5a 5a 5a 5a 5a 5a 5a 5a ....�.��ZZZZZZZZ
>> [ 74.908193] Object 0x5d883a10: 6b 6b 6b 6b 6a 6b 6b a5
>> kkkkjkk�
>
> This is struct tty_ldisc and the corruption happens in the first byte of
> ->refcount. This probably just means that there's a race condition and
> someone is doing tty_ldisc_deref() after tty_ldisc_put().
>
> You could add something like
>
> WARN_ON(ld->refcount == 0x6b)
>
> to tty_ldisc_deref() to see if that triggers.
I've committed the debug hack below - will let you know if it
triggers.
Ingo
------------->
>From 2f5eb191a6fd392d8f66f5e249bd05b3444b5420 Mon Sep 17 00:00:00 2001
From: Ingo Molnar <[email protected]>
Date: Sun, 14 Jun 2009 10:30:31 +0200
Subject: [PATCH] [not for upstream] tty: Add debug check to tty_ldisc_deref()
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit
Try to catch this SLAB corruption earlier:
[ 74.900215] =============================================================================
[ 74.908193] BUG kmalloc-8: Poison overwritten
[ 74.908193] -----------------------------------------------------------------------------
[ 74.908193]
[ 74.908193] INFO: 0x5d883a14-0x5d883a14. First byte 0x6a instead of 0x6b
[ 74.908193] INFO: Allocated in tty_ldisc_try_get+0x1a/0xb0 age=8015 cpu=0 pid=1
[ 74.908193] INFO: Freed in tty_ldisc_put+0x48/0x50 age=4 cpu=3 pid=4236
[ 74.908193] INFO: Slab 0x42c6eeb4 objects=73 used=61 fp=0x5d883a10 flags=0x1d0000c3
[ 74.908193] INFO: Object 0x5d883a10 @offset=2576 fp=0x5d883d90
[ 74.908193]
[ 74.908193] Bytes b4 0x5d883a00: 01 00 00 00 de 04 ff ff 5a 5a 5a 5a 5a 5a 5a 5a ....Þ.ÿÿZZZZZZZZ
[ 74.908193] Object 0x5d883a10: 6b 6b 6b 6b 6a 6b 6b a5 kkkkjkk¥
[ 74.908193] Redzone 0x5d883a18: bb bb bb bb »»»»
[ 74.908193] Padding 0x5d883a40: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
[ 74.908193] Pid: 4230, comm: mingetty Not tainted 2.6.30-tip #744
[ 74.908193] Call Trace:
[ 74.908193] [<410ae628>] print_trailer+0xc8/0xd0
[ 74.908193] [<410ae6a3>] check_bytes_and_report+0x73/0x90
[ 74.908193] [<410ae941>] check_object+0xa1/0x130
[ 74.908193] [<410aef1e>] alloc_debug_processing+0x5e/0xd0
[ 74.908193] [<410af99e>] __slab_alloc+0x11e/0x150
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<410afcdb>] kmem_cache_alloc+0x7b/0x120
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<413d9c7a>] tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<410b06a3>] ? __kmalloc+0x163/0x170
[ 74.908193] [<413d9d77>] tty_ldisc_get+0x17/0x40
[ 74.908193] [<413da63d>] tty_ldisc_init+0xd/0x30
[ 74.908193] [<413d4098>] initialize_tty_struct+0x38/0x210
[ 74.908193] [<413d5d6f>] tty_init_dev+0x4f/0xb0
[ 74.908193] [<413d5f25>] __tty_open+0x155/0x2d0
[ 74.908193] [<413d60b7>] tty_open+0x17/0x30
[ 74.908193] [<410bb599>] chrdev_open+0xe9/0x100
[ 74.908193] [<410b721e>] __dentry_open+0xbe/0x190
[ 74.908193] [<410b813c>] nameidata_to_filp+0x2c/0x50
[ 74.908193] [<410bb4b0>] ? chrdev_open+0x0/0x100
[ 74.908193] [<410c2eba>] do_filp_open+0x2aa/0x580
[ 74.908193] [<4100a1bb>] ? sched_clock+0xb/0x20
[ 74.908193] [<410596c7>] ? put_lock_stats+0x17/0x30
[ 74.908193] [<41059734>] ? lock_release_holdtime+0x54/0x60
[ 74.908193] [<4105d4d9>] ? lock_release_nested+0x99/0xd0
[ 74.908193] [<41377421>] ? debug_spin_unlock+0x21/0x80
[ 74.908193] [<41377495>] ? _raw_spin_unlock+0x15/0x20
[ 74.908193] [<410cad50>] ? alloc_fd+0xc0/0xd0
[ 74.908193] [<410b7020>] do_sys_open+0x40/0x80
[ 74.908193] [<410b70ae>] sys_open+0x1e/0x30
[ 74.908193] [<4100388f>] sysenter_do_call+0x12/0x3c
[ 74.908193] FIX kmalloc-8: Restoring 0x5d883a14-0x5d883a14=0x6b
[ 74.908193]
[ 74.908193] FIX kmalloc-8: Marking all objects used
[ 75.188226] warning: `sudo' uses deprecated v2 capabilities in a way that may be insecure.
Note, a value of 0x6b is legit for the refcount in theory, so this
debug hack is not suitable for upstream.
NOT-Signed-off-by: Ingo Molnar <[email protected]>
---
drivers/char/tty_ldisc.c | 1 +
1 files changed, 1 insertions(+), 0 deletions(-)
diff --git a/drivers/char/tty_ldisc.c b/drivers/char/tty_ldisc.c
index 39c8f86..dd1daf3 100644
--- a/drivers/char/tty_ldisc.c
+++ b/drivers/char/tty_ldisc.c
@@ -361,6 +361,7 @@ void tty_ldisc_deref(struct tty_ldisc *ld)
unsigned long flags;
BUG_ON(ld == NULL);
+ WARN_ON_ONCE(ld->refcount == 0x6b);
spin_lock_irqsave(&tty_ldisc_lock, flags);
if (ld->refcount == 0)
* Ingo Molnar <[email protected]> wrote:
> I've committed the debug hack below - will let you know if it
> triggers.
the one below instead.
Ingo
>From ffb32c7d24985c54e38db48e949da33c6464c6eb Mon Sep 17 00:00:00 2001
From: Ingo Molnar <[email protected]>
Date: Sun, 14 Jun 2009 10:30:31 +0200
Subject: [PATCH] [not for upstream] tty: Add debug check to tty_ldisc_deref()
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit
Try to catch this SLAB corruption earlier:
[ 74.900215] =============================================================================
[ 74.908193] BUG kmalloc-8: Poison overwritten
[ 74.908193] -----------------------------------------------------------------------------
[ 74.908193]
[ 74.908193] INFO: 0x5d883a14-0x5d883a14. First byte 0x6a instead of 0x6b
[ 74.908193] INFO: Allocated in tty_ldisc_try_get+0x1a/0xb0 age=8015 cpu=0 pid=1
[ 74.908193] INFO: Freed in tty_ldisc_put+0x48/0x50 age=4 cpu=3 pid=4236
[ 74.908193] INFO: Slab 0x42c6eeb4 objects=73 used=61 fp=0x5d883a10 flags=0x1d0000c3
[ 74.908193] INFO: Object 0x5d883a10 @offset=2576 fp=0x5d883d90
[ 74.908193]
[ 74.908193] Bytes b4 0x5d883a00: 01 00 00 00 de 04 ff ff 5a 5a 5a 5a 5a 5a 5a 5a ....?.??ZZZZZZZZ
[ 74.908193] Object 0x5d883a10: 6b 6b 6b 6b 6a 6b 6b a5 kkkkjkk?
[ 74.908193] Redzone 0x5d883a18: bb bb bb bb ????
[ 74.908193] Padding 0x5d883a40: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
[ 74.908193] Pid: 4230, comm: mingetty Not tainted 2.6.30-tip #744
[ 74.908193] Call Trace:
[ 74.908193] [<410ae628>] print_trailer+0xc8/0xd0
[ 74.908193] [<410ae6a3>] check_bytes_and_report+0x73/0x90
[ 74.908193] [<410ae941>] check_object+0xa1/0x130
[ 74.908193] [<410aef1e>] alloc_debug_processing+0x5e/0xd0
[ 74.908193] [<410af99e>] __slab_alloc+0x11e/0x150
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<410afcdb>] kmem_cache_alloc+0x7b/0x120
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<413d9c7a>] ? tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<413d9c7a>] tty_ldisc_try_get+0x1a/0xb0
[ 74.908193] [<410b06a3>] ? __kmalloc+0x163/0x170
[ 74.908193] [<413d9d77>] tty_ldisc_get+0x17/0x40
[ 74.908193] [<413da63d>] tty_ldisc_init+0xd/0x30
[ 74.908193] [<413d4098>] initialize_tty_struct+0x38/0x210
[ 74.908193] [<413d5d6f>] tty_init_dev+0x4f/0xb0
[ 74.908193] [<413d5f25>] __tty_open+0x155/0x2d0
[ 74.908193] [<413d60b7>] tty_open+0x17/0x30
[ 74.908193] [<410bb599>] chrdev_open+0xe9/0x100
[ 74.908193] [<410b721e>] __dentry_open+0xbe/0x190
[ 74.908193] [<410b813c>] nameidata_to_filp+0x2c/0x50
[ 74.908193] [<410bb4b0>] ? chrdev_open+0x0/0x100
[ 74.908193] [<410c2eba>] do_filp_open+0x2aa/0x580
[ 74.908193] [<4100a1bb>] ? sched_clock+0xb/0x20
[ 74.908193] [<410596c7>] ? put_lock_stats+0x17/0x30
[ 74.908193] [<41059734>] ? lock_release_holdtime+0x54/0x60
[ 74.908193] [<4105d4d9>] ? lock_release_nested+0x99/0xd0
[ 74.908193] [<41377421>] ? debug_spin_unlock+0x21/0x80
[ 74.908193] [<41377495>] ? _raw_spin_unlock+0x15/0x20
[ 74.908193] [<410cad50>] ? alloc_fd+0xc0/0xd0
[ 74.908193] [<410b7020>] do_sys_open+0x40/0x80
[ 74.908193] [<410b70ae>] sys_open+0x1e/0x30
[ 74.908193] [<4100388f>] sysenter_do_call+0x12/0x3c
[ 74.908193] FIX kmalloc-8: Restoring 0x5d883a14-0x5d883a14=0x6b
[ 74.908193]
[ 74.908193] FIX kmalloc-8: Marking all objects used
[ 75.188226] warning: `sudo' uses deprecated v2 capabilities in a way that may be insecure.
Note, a value of 0x6b is legit for the refcount in theory, so this
debug hack is not suitable for upstream.
NOT-Signed-off-by: Ingo Molnar <[email protected]>
---
drivers/char/tty_ldisc.c | 1 +
1 files changed, 1 insertions(+), 0 deletions(-)
diff --git a/drivers/char/tty_ldisc.c b/drivers/char/tty_ldisc.c
index 39c8f86..69b912d 100644
--- a/drivers/char/tty_ldisc.c
+++ b/drivers/char/tty_ldisc.c
@@ -361,6 +361,7 @@ void tty_ldisc_deref(struct tty_ldisc *ld)
unsigned long flags;
BUG_ON(ld == NULL);
+ WARN_ON_ONCE(ld->refcount == (int)0xa56b6b6b);
spin_lock_irqsave(&tty_ldisc_lock, flags);
if (ld->refcount == 0)
On Sun, 14 Jun 2009 10:10:52 +0200
Ingo Molnar <[email protected]> wrote:
>
> Ok, this is one for those who like to look at weird crashes/bugs.
>
> Here's a new regression that popped up in this merge window, there's
> some sort of slab corruption going on in tty data structures:
I split the ldisc and tty apart and redid the ldisc locking so its a fair
bet I know what changeset is to blame, will just need to hunt it down a
bit. kmemcheck found one leak case on Friday which I've fixed but not yet
scribbles.
> c65c9bc: tty: rewrite the ldisc locking
Almost certainly that one and will investigate on Monday
Alan
* Ingo Molnar <[email protected]> wrote:
> --- a/drivers/char/tty_ldisc.c
> +++ b/drivers/char/tty_ldisc.c
> @@ -361,6 +361,7 @@ void tty_ldisc_deref(struct tty_ldisc *ld)
> unsigned long flags;
>
> BUG_ON(ld == NULL);
> + WARN_ON_ONCE(ld->refcount == (int)0xa56b6b6b);
>
> spin_lock_irqsave(&tty_ldisc_lock, flags);
this does trigger:
[ 70.198553] PM: Adding info for No Bus:vcsa2
[ 70.223956] ------------[ cut here ]------------
[ 70.233266] warning: `sudo' uses deprecated v2 capabilities in a way that may be insecure.
[ 70.242894] WARNING: at drivers/char/tty_ldisc.c:364 tty_ldisc_deref+0x30/0x90()
[ 70.242894] Modules linked in:
[ 70.242894] Pid: 4252, comm: modprobe Not tainted 2.6.30-tip #746
[ 70.242894] Call Trace:
[ 70.242894] [<413da1b0>] ? tty_ldisc_deref+0x30/0x90
[ 70.242894] [<41035c79>] warn_slowpath_common+0x49/0x60
[ 70.242894] [<41035c9d>] warn_slowpath_null+0xd/0x10
[ 70.242894] [<413da1b0>] tty_ldisc_deref+0x30/0x90
[ 70.242894] [<413d53ee>] tty_write+0x8e/0xa0
[ 70.242894] [<413d545f>] redirected_tty_write+0x5f/0x70
[ 70.242894] [<410b9002>] vfs_write+0x82/0xe0
[ 70.242894] [<413d5400>] ? redirected_tty_write+0x0/0x70
[ 70.242894] [<410b90fb>] sys_write+0x3b/0x60
[ 70.242894] [<4100388f>] sysenter_do_call+0x12/0x3c
[ 70.242894] [<4104007b>] ? timer_stats_timer_set_start_info+0xb/0x10
[ 70.242894] [<4104007b>] ? timer_stats_timer_set_start_info+0xb/0x10
[ 70.242894] ---[ end trace 03c5764c731fa31f ]---
[ 71.663044] device: 'vcs7': device_add
i suspect the swarm of mingetty's starting up during bootup is
triggering some race.
Ingo
2009/6/14 Pekka Enberg <[email protected]>:
> On Sun, Jun 14, 2009 at 11:20 AM, Pekka Enberg<[email protected]> wrote:
>>> You could add something like
>>>
>>> WARN_ON(ld->refcount == 0x6b)
>>>
>>> to tty_ldisc_deref() to see if that triggers.
>
> On Sun, Jun 14, 2009 at 11:30 AM, Pekka Enberg<[email protected]> wrote:
>> Make that
>>
>> WARN_ON(ld->refcount == (int)0xa56b6b6b)
>>
>> instead.
>
> And oh, kmemcheck should be able to catch this too. :-)
>
I was able to get this trace:
(none) login: [ 867.947401] WARNING: kmemcheck: Caught 32-bit read
from freed memory (469e2f44)
[ 867.962162] 00000000020000000038bf41020000000038bf41020000000038bf4102000000
[ 868.012078] i i i i f f f f i i i i i i i i i i i i i i i i i i i i i i i i
[ 868.061629] ^
[ 868.067686]
[ 868.071709] Pid: 1857, comm: getty Not tainted (2.6.30 #416)
[ 868.082651] EIP: 0060:[<414772ea>] EFLAGS: 00000002 CPU: 0
[ 868.095379] EIP is at tty_ldisc_deref+0x1a/0x70
[ 868.103757] EAX: 00000216 EBX: 469e2f40 ECX: 414772e8 EDX: 41bf3870
[ 868.115752] ESI: 00000216 EDI: 4766483c EBP: 46f37f3c ESP: 41e22450
[ 868.131343] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
[ 868.141609] CR0: 8005003b CR2: 47806e04 CR3: 06b6b000 CR4: 00000690
[ 868.155263] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 868.167168] DR6: 00004000 DR7: 00000000
[ 868.175228] [<4146f26d>] tty_read+0x8d/0xc0
[ 868.184598] [<410ca219>] vfs_read+0x99/0x180
[ 868.196380] [<410ca3bd>] sys_read+0x3d/0x70
[ 868.206936] [<41003a6f>] sysenter_do_call+0x12/0x3c
[ 868.219746] [<ffffffff>] 0xffffffff
Thats:
drivers/char/tty_ldisc.c:366
drivers/char/tty_io.c:896
I also saw this a couple of times (it's not my printk):
[ 1266.934668] tty_ldisc_deref: no references.
[ 1267.531655] tty_ldisc_deref: no references.
[ 1267.790096] tty_ldisc_deref: no references.
Vegard
On Mon, Jun 15, 2009 at 2:03 AM, Vegard Nossum<[email protected]> wrote:
> 2009/6/14 Pekka Enberg <[email protected]>:
>> On Sun, Jun 14, 2009 at 11:20 AM, Pekka Enberg<[email protected]> wrote:
>>>> You could add something like
>>>>
>>>> ?WARN_ON(ld->refcount == 0x6b)
>>>>
>>>> to tty_ldisc_deref() to see if that triggers.
>>
>> On Sun, Jun 14, 2009 at 11:30 AM, Pekka Enberg<[email protected]> wrote:
>>> Make that
>>>
>>> ? ?WARN_ON(ld->refcount == (int)0xa56b6b6b)
>>>
>>> instead.
>>
>> And oh, kmemcheck should be able to catch this too. :-)
>>
>
> I was able to get this trace:
>
> (none) login: [ ?867.947401] WARNING: kmemcheck: Caught 32-bit read
> from freed memory (469e2f44)
> [ ?867.962162] 00000000020000000038bf41020000000038bf41020000000038bf4102000000
> [ ?868.012078] ?i i i i f f f f i i i i i i i i i i i i i i i i i i i i i i i i
> [ ?868.061629] ? ? ? ? ?^
> [ ?868.067686]
> [ ?868.071709] Pid: 1857, comm: getty Not tainted (2.6.30 #416)
> [ ?868.082651] EIP: 0060:[<414772ea>] EFLAGS: 00000002 CPU: 0
> [ ?868.095379] EIP is at tty_ldisc_deref+0x1a/0x70
> [ ?868.103757] EAX: 00000216 EBX: 469e2f40 ECX: 414772e8 EDX: 41bf3870
> [ ?868.115752] ESI: 00000216 EDI: 4766483c EBP: 46f37f3c ESP: 41e22450
> [ ?868.131343] ?DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
> [ ?868.141609] CR0: 8005003b CR2: 47806e04 CR3: 06b6b000 CR4: 00000690
> [ ?868.155263] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ ?868.167168] DR6: 00004000 DR7: 00000000
> [ ?868.175228] ?[<4146f26d>] tty_read+0x8d/0xc0
> [ ?868.184598] ?[<410ca219>] vfs_read+0x99/0x180
> [ ?868.196380] ?[<410ca3bd>] sys_read+0x3d/0x70
> [ ?868.206936] ?[<41003a6f>] sysenter_do_call+0x12/0x3c
> [ ?868.219746] ?[<ffffffff>] 0xffffffff
>
> Thats:
>
> drivers/char/tty_ldisc.c:366
> drivers/char/tty_io.c:896
>
> I also saw this a couple of times (it's not my printk):
>
> [ 1266.934668] tty_ldisc_deref: no references.
> [ 1267.531655] tty_ldisc_deref: no references.
> [ 1267.790096] tty_ldisc_deref: no references.
Yup, that's the tty layer complaining that we're trying to
tty_ldisc_deref() but reference count is zero. Ingo doesn't see this
because of slab poisoning which is why kmemcheck is able to produce a
nicer stack trace in this case.
Pekka
Alan Cox <[email protected]> wrote:
> On Sun, 14 Jun 2009 10:10:52 +0200
> Ingo Molnar <[email protected]> wrote:
>> Ok, this is one for those who like to look at weird crashes/bugs.
>>
>> Here's a new regression that popped up in this merge window, there's
>> some sort of slab corruption going on in tty data structures:
>
> I split the ldisc and tty apart and redid the ldisc locking so its a fair
> bet I know what changeset is to blame, will just need to hunt it down a
> bit. kmemcheck found one leak case on Friday which I've fixed but not yet
> scribbles.
That was kmemleak :-).
--
Catalin
* Alan Cox <[email protected]> wrote:
> On Sun, 14 Jun 2009 10:10:52 +0200
> Ingo Molnar <[email protected]> wrote:
>
> >
> > Ok, this is one for those who like to look at weird crashes/bugs.
> >
> > Here's a new regression that popped up in this merge window, there's
> > some sort of slab corruption going on in tty data structures:
>
> I split the ldisc and tty apart and redid the ldisc locking so its a fair
> bet I know what changeset is to blame, will just need to hunt it down a
> bit. kmemcheck found one leak case on Friday which I've fixed but not yet
> scribbles.
>
> > c65c9bc: tty: rewrite the ldisc locking
>
> Almost certainly that one and will investigate on Monday
I have applied your patch from yesterday (attached further below for
reference) and the SLAB corruption has not triggered - instead i'm
now getting this warning, after 96 reboots:
[ 20.782199] sshd used greatest stack depth: 5376 bytes left
[ 22.260149] ------------[ cut here ]------------
[ 22.261027] WARNING: at drivers/char/tty_io.c:1266 tty_open+0x1ea/0x388()
[ 22.262018] Hardware name: System Product Name
[ 22.262020] Modules linked in:
[ 22.262024] Pid: 2553, comm: modprobe Tainted: G W 2.6.30-tip #54059
[ 22.262026] Call Trace:
[ 22.262032] [<c102d810>] warn_slowpath_common+0x60/0x90
[ 22.262037] [<c102d84d>] warn_slowpath_null+0xd/0x10
[ 22.262041] [<c11a88ae>] tty_open+0x1ea/0x388
[ 22.262045] [<c108e4c2>] chrdev_open+0x11b/0x132
[ 22.262049] [<c108a8a6>] __dentry_open+0x167/0x265
[ 22.262052] [<c108aa3e>] nameidata_to_filp+0x2c/0x43
[ 22.262056] [<c108e3a7>] ? chrdev_open+0x0/0x132
[ 22.262060] [<c1094bbd>] do_filp_open+0x3cd/0x712
[ 22.262064] [<c1083460>] ? check_valid_pointer+0x1f/0x4e
[ 22.262068] [<c109cd26>] ? alloc_fd+0xcb/0xd5
[ 22.262071] [<c109cd26>] ? alloc_fd+0xcb/0xd5
[ 22.262075] [<c108a63d>] do_sys_open+0x4a/0xed
[ 22.262078] [<c1002a5e>] ? sysenter_exit+0xf/0x21
[ 22.262081] [<c108a722>] sys_open+0x1e/0x26
[ 22.262085] [<c1002a2b>] sysenter_do_call+0x12/0x36
[ 22.262087] ---[ end trace 81f0afc9843492f2 ]---
[ 31.191037] CPA self-test:
Another test-box has produced this warning too. (Same config and
same hw as i sent the details for earlier in this thread.)
So there's still something fishy going on.
Thanks,
Ingo
-------------------->
>From 9f7a9ce1955c5f7af7456363a552819a82c19896 Mon Sep 17 00:00:00 2001
From: Alan Cox <[email protected]>
Date: Mon, 15 Jun 2009 16:32:12 +0100
Subject: [PATCH] ldisc: Make sure the ldisc isn't active when we close it
Signed-off-by: Alan Cox <[email protected]>
LKML-Reference: <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
drivers/char/tty_ldisc.c | 2 ++
1 files changed, 2 insertions(+), 0 deletions(-)
diff --git a/drivers/char/tty_ldisc.c b/drivers/char/tty_ldisc.c
index 69b912d..0ea4f63 100644
--- a/drivers/char/tty_ldisc.c
+++ b/drivers/char/tty_ldisc.c
@@ -792,6 +792,8 @@ void tty_ldisc_hangup(struct tty_struct *tty)
/* Avoid racing set_ldisc */
mutex_lock(&tty->ldisc_mutex);
/* Switch back to N_TTY */
+ tty_ldisc_halt(tty);
+ tty_ldisc_wait_idle(tty);
tty_ldisc_reinit(tty);
/* At this point we have a closed ldisc and we want to
reopen it. We could defer this to the next open but
> > I split the ldisc and tty apart and redid the ldisc locking so its a fair
> > bet I know what changeset is to blame, will just need to hunt it down a
> > bit. kmemcheck found one leak case on Friday which I've fixed but not yet
> > scribbles.
> >
> > > c65c9bc: tty: rewrite the ldisc locking
> >
> > Almost certainly that one and will investigate on Monday
>
> I have applied your patch from yesterday (attached further below for
> reference) and the SLAB corruption has not triggered - instead i'm
> now getting this warning, after 96 reboots:
That's progress
> Another test-box has produced this warning too. (Same config and
> same hw as i sent the details for earlier in this thread.)
>
> So there's still something fishy going on.
Are you using a standard udev/fedora setup or something different (I know
the devtmpfs proposal stuff produces crashes like that one all the time
which are not seen anywhere else)
And is it reproducable this time - and always 96 ?
* Alan Cox <[email protected]> wrote:
> > > I split the ldisc and tty apart and redid the ldisc locking so its a fair
> > > bet I know what changeset is to blame, will just need to hunt it down a
> > > bit. kmemcheck found one leak case on Friday which I've fixed but not yet
> > > scribbles.
> > >
> > > > c65c9bc: tty: rewrite the ldisc locking
> > >
> > > Almost certainly that one and will investigate on Monday
> >
> > I have applied your patch from yesterday (attached further below for
> > reference) and the SLAB corruption has not triggered - instead i'm
> > now getting this warning, after 96 reboots:
>
> That's progress
>
> > Another test-box has produced this warning too. (Same config and
> > same hw as i sent the details for earlier in this thread.)
> >
> > So there's still something fishy going on.
>
> Are you using a standard udev/fedora setup or something different
> (I know the devtmpfs proposal stuff produces crashes like that one
> all the time which are not seen anywhere else)
>
> And is it reproducable this time - and always 96 ?
It shows up randomly and on multiple systems.
I'm wondering, how long have these patches been in linux-next? Has
no-one reported an easy (or easier) reproducer than a plain bootup
(which really doesnt hit the tty code intentionally hard)?
You should probably also write testcases and stress-tests if you
modify code in this area.
Ingo
> I'm wondering, how long have these patches been in linux-next? Has
> no-one reported an easy (or easier) reproducer than a plain bootup
> (which really doesnt hit the tty code intentionally hard)?
Quite a while - and the open side stuff hasn't changed in the post 2.6.30
patches at all. Your box seems to show stuff up that most users just
don't hit.
> You should probably also write testcases and stress-tests if you
> modify code in this area.
I did - they hang the tty layers in 2.6.30 and earlier in about 60
seconds, it then corrupts the module counts and dies shortly after. I've
not published them because they can obviously be seriously misused.
I don't have the luxury of building on solid foundations trying to sort
the tty layer out - its been broken since 2.1.x when the lock_kernel
logic stopped applying to IRQ handlers.
Alan
> I have applied your patch from yesterday (attached further below for
> reference) and the SLAB corruption has not triggered - instead i'm
> now getting this warning, after 96 reboots
That one is interesting btw - however its not a new bug. The WARN_ON()
was added in the new patches to catch cases where the tty open/close
locking was broken and see if all the ldisc related ones were nailed.
Apparently on a very SMP box they are not. It's not however a new bug -
just the result of checking for the problem.
+ WARN_ON(!test_bit(TTY_LDISC, &tty->flags));
..
which means that someone cleared the ldisc behind our back despite us
holding tty_mutex. That would suggest a hangup/reopen race which
shouldn't be too hard to find.
Dunno what you feed your SMP box but its very useful 8)
Alan
* Alan Cox <[email protected]> wrote:
> > I have applied your patch from yesterday (attached further below for
> > reference) and the SLAB corruption has not triggered - instead i'm
> > now getting this warning, after 96 reboots
>
> That one is interesting btw - however its not a new bug. The
> WARN_ON() was added in the new patches to catch cases where the
> tty open/close locking was broken and see if all the ldisc related
> ones were nailed.
>
> Apparently on a very SMP box they are not. It's not however a new
> bug - just the result of checking for the problem.
>
> + WARN_ON(!test_bit(TTY_LDISC, &tty->flags));
>
>
> ..
>
> which means that someone cleared the ldisc behind our back despite
> us holding tty_mutex. That would suggest a hangup/reopen race
> which shouldn't be too hard to find.
>
> Dunno what you feed your SMP box but its very useful 8)
it's plain old-fashioned brute force plus a randconfig search: if a
race is possible it will trigger eventually here, given the right
hardware (i use a number of different systems), given the right
user-space (i use heterogenous installations), given the right
compiler/binutils (that too is heterogenous) and the right timing
and kernel feature combo via a huge, 2^1000 randconfig space.
Plus this system is an old P4 HyperThreading dual-socket system:
pretty much the only thing HyperThreading is good for on that box is
finding SMP races: that CPU can (and will) yield between
hyperthreads on arbitrary instruction boundaries - opening up races
wide open.
In fact we had races in the past that would only trigger on that
box, ever. (note that this warning did trigger on another box as
well - after 350+ bootups ...) And we thought P4-HT is pure crap ;-)
Ingo
* Alan Cox <[email protected]> wrote:
> > I'm wondering, how long have these patches been in linux-next?
> > Has no-one reported an easy (or easier) reproducer than a plain
> > bootup (which really doesnt hit the tty code intentionally
> > hard)?
>
> Quite a while - and the open side stuff hasn't changed in the post
> 2.6.30 patches at all. Your box seems to show stuff up that most
> users just don't hit.
Another box has triggered that too btw. But with your two fixes:
69e8fd4: tty: fix sanity check
9f7a9ce: ldisc: Make sure the ldisc isn't active when we close it
i havent seen any new tty warnings today. (testing is a bit spotty
due to other bugs though - this is typical of the merge window.)
Also, the only warning that remained after your fix was the new
warning you added to catch an old bug - that's not a regression
really.
> > You should probably also write testcases and stress-tests if you
> > modify code in this area.
>
> I did - they hang the tty layers in 2.6.30 and earlier in about 60
> seconds, it then corrupts the module counts and dies shortly
> after. I've not published them because they can obviously be
> seriously misused.
Too bad - i could have ran them in the test mix.
> I don't have the luxury of building on solid foundations trying to
> sort the tty layer out - its been broken since 2.1.x when the
> lock_kernel logic stopped applying to IRQ handlers.
No complaints from me at all! You are doing fantastic cleanups and
fixes in the TTY code.
Ingo