Bug 8473 - Oops: 0010 [1] SMP
Summary: Oops: 0010 [1] SMP
Status: CLOSED CODE_FIX
Alias: None
Product: Alternate Trees
Classification: Unclassified
Component: mm (show other bugs)
Hardware: i386 Linux
: P2 high
Assignee: Andrew Morton
URL:
Keywords:
: 8574 (view as bug list)
Depends on:
Blocks:
 
Reported: 2007-05-13 14:03 UTC by Nicolas Mailhot
Modified: 2008-09-08 22:41 UTC (History)
4 users (show)

See Also:
Kernel Version: 2.6.21-mm2 - 2.6.22-rc2.mm1
Subsystem:
Regression: ---
Bisected commit-id:


Attachments
kernel config (42.38 KB, text/plain)
2007-05-13 14:04 UTC, Nicolas Mailhot
Details
lspci (117.69 KB, text/plain)
2007-05-13 14:05 UTC, Nicolas Mailhot
Details
kernel log from bootup to oops (69.44 KB, text/plain)
2007-05-13 14:08 UTC, Nicolas Mailhot
Details

Description Nicolas Mailhot 2007-05-13 14:03:55 UTC
Most recent kernel where this bug did *NOT* occur: 2.6.21-mm1 (though I didn't
test it that long)
Distribution: Fedora Devel
Hardware Environment: AMD C2 on CK804
Software Environment: Normal workload (building a small package)
Problem Description:

Steps to reproduce:
May 13 22:59:43 rousalka kernel: Unable to handle kernel NULL pointer
dereference at 0000000000000000 RIP: 
May 13 22:59:43 rousalka kernel: [<0000000000000000>]
May 13 22:59:43 rousalka kernel: PGD bf1a067 PUD f295067 PMD 0 
May 13 22:59:43 rousalka kernel: Oops: 0010 [1] SMP 
May 13 22:59:43 rousalka kernel: CPU 0 
May 13 22:59:43 rousalka kernel: Pid: 8758, comm: bash Not tainted
2.6.21-9.mm2.fc7.nim #1
May 13 22:59:43 rousalka kernel: RIP: 0010:[<0000000000000000>] 
[<0000000000000000>]
May 13 22:59:43 rousalka kernel: RSP: 0018:ffff81000ffedee0  EFLAGS: 00010296
May 13 22:59:43 rousalka kernel: RAX: ffffffff804426a0 RBX: ffff81000abe6a80
RCX: 00007fff565bbdc4
May 13 22:59:43 rousalka kernel: RDX: 0000000000005410 RSI: ffff81000abe6a80
RDI: ffff810009cc6fa0
May 13 22:59:43 rousalka kernel: RBP: 00007fff565bbdc4 R08: 0000000000000000
R09: 00000000009033a4
May 13 22:59:43 rousalka kernel: R10: 0000000000000008 R11: 0000000000000246
R12: 0000000000005410
May 13 22:59:43 rousalka kernel: R13: 00000000000000ff R14: 00000000000000ff
R15: 0000000000000000
May 13 22:59:43 rousalka kernel: FS:  00002b2d544faf40(0000)
GS:ffffffff8056b000(0000) knlGS:0000000000000000
May 13 22:59:43 rousalka kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
May 13 22:59:43 rousalka kernel: CR2: 0000000000000000 CR3: 000000000bdf4000
CR4: 00000000000006e0
May 13 22:59:43 rousalka kernel: Process bash (pid: 8758, threadinfo
ffff81000ffec000, task ffff81000bc82ac0)
May 13 22:59:43 rousalka kernel: Stack:  ffffffff8028545d ffff81000abe6a80
00007fff565bbdc4 00007fff565bbdc4
May 13 22:59:43 rousalka kernel: ffffffff802856ca 0000000000005410
00000000000000ff ffff81000abe6a80
May 13 22:59:43 rousalka kernel: 0000000000000000 00007fff565bbdc4
0000000000005410 00000000000000ff
May 13 22:59:43 rousalka kernel: Call Trace:
May 13 22:59:43 rousalka kernel: [<ffffffff8028545d>] do_ioctl+0x55/0x6b
May 13 22:59:43 rousalka kernel: [<ffffffff802856ca>] vfs_ioctl+0x257/0x270
May 13 22:59:43 rousalka kernel: [<ffffffff8028573c>] sys_ioctl+0x59/0x79
May 13 22:59:43 rousalka kernel: [<ffffffff8020955c>] tracesys+0xdc/0xe1
May 13 22:59:43 rousalka kernel: 
May 13 22:59:43 rousalka kernel: INFO: lockdep is turned off.
May 13 22:59:43 rousalka kernel: 
May 13 22:59:43 rousalka kernel: Code:  Bad RIP value.
May 13 22:59:43 rousalka kernel: RIP  [<0000000000000000>]
May 13 22:59:43 rousalka kernel: RSP <ffff81000ffedee0>
May 13 22:59:43 rousalka kernel: CR2: 0000000000000000
Comment 1 Nicolas Mailhot 2007-05-13 14:04:32 UTC
Created attachment 11490 [details]
kernel config
Comment 2 Nicolas Mailhot 2007-05-13 14:05:06 UTC
Created attachment 11491 [details]
lspci
Comment 3 Nicolas Mailhot 2007-05-13 14:08:13 UTC
Created attachment 11492 [details]
kernel log from bootup to oops
Comment 4 Nicolas Mailhot 2007-05-13 14:46:56 UTC
May 13 22:59:43 rousalka kernel: [<ffffffff802856ca>] vfs_ioctl+0x257/0x270
&#8594; fs_vfs in CC
Comment 5 Nicolas Mailhot 2007-05-13 16:26:59 UTC
Le dimanche 13 mai 2007 à 15:47 -0700, Andrew Morton a écrit :
> On Sun, 13 May 2007 14:02:50 -0700 bugme-daemon@bugzilla.kernel.org wrote:
> 
> > http://bugzilla.kernel.org/show_bug.cgi?id=8473
> 
> Please follow up via emailed reply-to-all.
> 
> In fact, please report -mm bugs via email.  bugzilla is more suited to
> longer-term problems, and -mm bugs are super-short-term, we hope.

Can't attach trace screenshots or long log dumps to mails :(

> May 13 22:59:43 rousalka kernel: Unable to handle kernel NULL pointer
> dereference at 0000000000000000 RIP: 
> May 13 22:59:43 rousalka kernel: [<0000000000000000>]

> Anything you can do to make that wordwrapping go away for ever would be
> great, thanks.

You have the full kernel log with no wrapping there
http://bugzilla.kernel.org/attachment.cgi?id=11492

> I don't know what would have caused this.  do_ioctl() did a jump-to-zero,
> but it has code in there to explicitly test for null pointers.
> 
> Perhaps some weird race, although I find it hard to imagine how we could
> have such a race in any ioctl which bash is likely to be calling.
> 
> Is it repeatable at all?

It happened once so far. The load was moderate (and certainly not
comparable to what I did for Mel yesterday)

Comment 6 Nicolas Mailhot 2007-05-17 03:03:21 UTC
Le lundi 14 mai 2007 à 01:25 +0200, Nicolas Mailhot a écrit :

> It happened once so far. The load was moderate (and certainly not
> comparable to what I did for Mel yesterday)

Make that twice. The interesting thing is it was preceded by CD/DVD
access just before, to something is rotten there.

10:52:35 ISO 9660 Extensions: RRIP_1991A
11:52:36 Unable to handle kernel NULL pointer dereference at 0000000000000000 RIP: 
11:52:36 [<0000000000000000>]
11:52:36 PGD 2438a067 PUD c484067 PMD 0 
11:52:36 Oops: 0010 [1] SMP 
11:52:36 CPU 1 
11:52:36 Pid: 30655, comm: bash Not tainted 2.6.21-11.mm2.fc7.nim #1
11:52:36 RIP: 0010:[<0000000000000000>]  [<0000000000000000>]
11:52:36 RSP: 0000:ffff810006199ee0  EFLAGS: 00010296
11:52:36 RAX: ffffffff804426a0 RBX: ffff81000903f800 RCX: 00007fff8a5e9874
11:52:36 RDX: 0000000000005410 RSI: ffff81000903f800 RDI: ffff810006a37b88
11:52:36 RBP: 00007fff8a5e9874 R08: 0000000000000000 R09: 0000000000000004
11:52:36 R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000005410
11:52:36 R13: 00000000000000ff R14: 00000000000000ff R15: 0000000000000008
11:52:36 FS:  00002b1c204ccf40(0000) GS:ffff810004017180(0000) knlGS:0000000000000000
11:52:36 CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
11:52:36 CR2: 0000000000000000 CR3: 000000000f83b000 CR4: 00000000000006e0
11:52:36 Process bash (pid: 30655, threadinfo ffff810006198000, task ffff810024319c80)
11:52:36 Stack:  ffffffff80285451 ffff81000903f800 00007fff8a5e9874 00007fff8a5e9874
11:52:36 ffffffff802856be 0000000000005410 00000000000000ff ffff81000903f800
11:52:36 0000000000000000 00007fff8a5e9874 0000000000005410 00000000000000ff
11:52:36 Call Trace:
11:52:36 [<ffffffff80285451>] do_ioctl+0x55/0x6b
11:52:36 [<ffffffff802856be>] vfs_ioctl+0x257/0x270
11:52:36 [<ffffffff80285730>] sys_ioctl+0x59/0x79
11:52:36 [<ffffffff8020955c>] tracesys+0xdc/0xe1
11:52:36 
11:52:36 INFO: lockdep is turned off.
11:52:36 
11:52:36 Code:  Bad RIP value.
11:52:36 RIP  [<0000000000000000>]
11:52:36 RSP <ffff810006199ee0>
11:52:36 CR2: 0000000000000000

I'd try rc2-mm1, but I don't know if the patches of Mel Gorman &
Christoph Lameter for bug #8464 have been merged yet

Regards,

Comment 7 Randy Dunlap 2007-05-17 09:44:15 UTC
On Thu, 17 May 2007 12:00:02 +0200 Nicolas Mailhot wrote:

> Le lundi 14 mai 2007 
Comment 8 Nicolas Mailhot 2007-05-17 10:03:12 UTC
Le jeudi 17 mai 2007 à 09:45 -0700, Randy Dunlap a écrit :
> On Thu, 17 May 2007 12:00:02 +0200 Nicolas Mailhot wrote:
> 
> > Le lundi 14 mai 2007 à 01:25 +0200, Nicolas Mailhot a écrit :
> > 
> > > It happened once so far. The load was moderate (and certainly not
> > > comparable to what I did for Mel yesterday)
> > 
> > Make that twice. The interesting thing is it was preceded by CD/DVD
> > access just before, to something is rotten there.
> > 
> > 10:52:35 ISO 9660 Extensions: RRIP_1991A
> > 11:52:36 Unable to handle kernel NULL pointer dereference at 0000000000000000 RIP: 
> > 11:52:36 [<0000000000000000>]
> > 11:52:36 PGD 2438a067 PUD c484067 PMD 0 
> > 11:52:36 Oops: 0010 [1] SMP 
> > 11:52:36 CPU 1 
> > 11:52:36 Pid: 30655, comm: bash Not tainted 2.6.21-11.mm2.fc7.nim #1
> 
> so just what is this kernel?  A hybrid of -mm and -fc7 or what?

-mm + md-improve-partition-detection-in-md-array.patch revert + Mel's
patches for bug #8464 + the fedora nouveau patch

the fc7.nim is there because it was build in an F7 buildroot, not
because it carries the full Fedora patchset

> Can you boot with "kstack=32" so that we can see more of the stack?

I can try. It's not triggering quickly though

Comment 9 Nicolas Mailhot 2007-05-24 10:39:28 UTC
Closing as could not reproduce it a third time and moving to another kernel
Comment 10 Nicolas Mailhot 2007-05-26 12:10:17 UTC
Reopening as I just reproduced it with 2.6.22-rc2.mm1-cfs14
Comment 11 Nicolas Mailhot 2007-05-26 12:13:34 UTC
Le jeudi 17 mai 2007 à 18:59 +0200, Nicolas Mailhot a écrit :
> Le jeudi 17 mai 2007 à 09:45 -0700, Randy Dunlap a écrit :
> 
> > Can you boot with "kstack=32" so that we can see more of the stack?
> 
> I can try. It's not triggering quickly though

Seems I was completely wrong about the trigger, but anyway it happened
again, this time on 2.6.22-rc2.mm1.cfs14 (and I had kept kstack=32)

 BUG: using smp_processor_id() in preemptible [00000001] code: bash/3857
 caller is oops_begin+0xb/0x6f
 
 Call Trace:
 [<ffffffff8020ab4d>] show_trace+0x34/0x4f
 [<ffffffff8020ab7a>] dump_stack+0x12/0x17
 [<ffffffff8030d92d>] debug_smp_processor_id+0xad/0xbc
 [<ffffffff8042388f>] oops_begin+0xb/0x6f
 [<ffffffff8042520b>] do_page_fault+0x66a/0x7c0
 [<ffffffff804234bd>] error_exit+0x0/0x84
 
 Unable to handle kernel NULL pointer dereference at 0000000000000000 RIP: 
 [<0000000000000000>]
 PGD bdd2067 PUD c133067 PMD 0 
 Oops: 0010 [1] PREEMPT SMP 
 CPU 1 
 Pid: 3857, comm: bash Not tainted 2.6.22-0.8.rc2.mm1.cfs14.fc8.nim #1
 RIP: 0010:[<0000000000000000>]  [<0000000000000000>]
 RSP: 0018:ffff81000cb03ee0  EFLAGS: 00010296
 RAX: ffffffff8044dbc0 RBX: ffff81000c3aa8c0 RCX: 00007fff549dcae4
 RDX: 0000000000005410 RSI: ffff81000c3aa8c0 RDI: ffff81000ba913d8
 RBP: 00007fff549dcae4 R08: 0000000000000000 R09: 00000000ffffffff
 R10: 0000000000000008 R11: 0000000000000246 R12: 0000000000005410
 R13: 00000000000000ff R14: 00000000000000ff R15: 0000000000000000
 FS:  00002b06560d8f40(0000) GS:ffff810004017180(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
 CR2: 0000000000000000 CR3: 000000000bc55000 CR4: 00000000000006e0
 Process bash (pid: 3857, threadinfo ffff81000cb02000, task ffff81000adc59a0)
 Stack:  ffffffff8028ada9 ffff81000c3aa8c0 00007fff549dcae4 00007fff549dcae4
 ffffffff8028b016 0000000000005410 00000000000000ff ffff81000c3aa8c0
 0000000000000000 00007fff549dcae4 0000000000005410 00000000000000ff
 ffffffff8028b088 0000000000000000 0000000080209571 00000000ffffffff
 00007fff549dce87 0000000000000f11 00007fff549dcfb8 00007fff549dddb0
 ffffffff802095dc 0000000000000246 0000000000000008 00000000ffffffff
 0000000000000000 ffffffffffffffda ffffffffffffffff 00007fff549dcae4
 0000000000005410 00000000000000ff 0000000000000010 0000003d340c9117
 Call Trace:
 Inexact backtrace:
 [<ffffffff8028ada9>] do_ioctl+0x55/0x6b
 [<ffffffff8028b016>] vfs_ioctl+0x257/0x270
 [<ffffffff8028b088>] sys_ioctl+0x59/0x79
 [<ffffffff802095dc>] tracesys+0xdc/0xe1
 
 INFO: lockdep is turned off.
 
 Code:  Bad RIP value.
 RIP  [<0000000000000000>]
 RSP <ffff81000cb03ee0>
 CR2: 0000000000000000

Comment 12 Anonymous Emailer 2007-06-07 20:10:40 UTC
Reply-To: B.Steinbrink@gmx.de

On 2007.05.26 21:10:15 +0200, Nicolas Mailhot wrote:
> Le jeudi 17 mai 2007 
Comment 13 Anonymous Emailer 2007-06-07 20:21:32 UTC
Reply-To: akpm@linux-foundation.org

On Fri, 8 Jun 2007 05:06:29 +0200 Bj
Comment 14 Paul Fulghum 2007-06-08 07:15:27 UTC
On Thu, 2007-06-07 at 20:16 -0700, Andrew Morton wrote:
> On Fri, 8 Jun 2007 05:06:29 +0200 Björn Steinbrink <B.Steinbrink@gmx.de> wrote:
> > This is do_tty_hangup() exchanging the fops while we're waiting for the
> > lock. The new fops (hung_up_tty_fops) only have the unlocked variant and
> > thus we Oops our way.
> 
> ah, yes, that explains it, thanks.  Culprit:
> 
> commit e10cc1df1d2014f68a4bdcf73f6dd122c4561f94
> Author: Paul Fulghum <paulkf@microgate.com>
> Date:   Thu May 10 22:22:50 2007 -0700
> 
>     tty: add compat_ioctl
>     
>     Add compat_ioctl method for tty code to allow processing of 32 bit ioctl
>     calls on 64 bit systems by tty core, tty drivers, and line disciplines.

OK, the change of hung_up_tty_ioctl() from locked to unlocked
is not necessary for this patch. On the surface it seemed a clever
way of not needing two different functions to do the same simple:

return cmd == TIOCSPGRP ? -ENOTTY : -EIO;

which does not need any locking for its own sake. But clearly
the hangup behavior requires the locked version.

I'll redo the patch with hung_up_tty_ioctl remaining locked.

That will separate the compat ioctl stuff from this issue.

Comment 15 Paul Fulghum 2007-06-08 08:21:32 UTC
On Fri, 2007-06-08 at 05:06 +0200, Björn Steinbrink wrote:
> This is do_tty_hangup() exchanging the fops while we're waiting for the
> lock. The new fops (hung_up_tty_fops) only have the unlocked variant and
> thus we Oops our way.
> 
> The following program reproduces it quite easily on a SMP box. I'm
> running it from X as root like this:
> while true; do xterm /path/to/program; done

I am unable to reproduce the oops on either i386 SMP or x86_64 SMP
using your test program. This is against plain 2.6.21 with only
my compat ioctl patch applied.

Here is a patch that restores the locked ioctl for hung_up_tty_ioctl.
Can you try it and see if it removes your oops?

--- a/drivers/char/tty_io.c	2007-06-08 10:07:39.000000000 -0500
+++ b/drivers/char/tty_io.c	2007-06-08 10:09:59.000000000 -0500
@@ -1150,8 +1150,14 @@ static unsigned int hung_up_tty_poll(str
 	return POLLIN | POLLOUT | POLLERR | POLLHUP | POLLRDNORM | POLLWRNORM;
 }
 
-static long hung_up_tty_ioctl(struct file * file,
-			      unsigned int cmd, unsigned long arg)
+static int hung_up_tty_ioctl(struct inode * inode, struct file * file,
+			     unsigned int cmd, unsigned long arg)
+{
+	return cmd == TIOCSPGRP ? -ENOTTY : -EIO;
+}
+
+static long hung_up_tty_compat_ioctl(struct file * file,
+				     unsigned int cmd, unsigned long arg)
 {
 	return cmd == TIOCSPGRP ? -ENOTTY : -EIO;
 }
@@ -1199,8 +1205,8 @@ static const struct file_operations hung
 	.read		= hung_up_tty_read,
 	.write		= hung_up_tty_write,
 	.poll		= hung_up_tty_poll,
-	.unlocked_ioctl = hung_up_tty_ioctl,
-	.compat_ioctl	= hung_up_tty_ioctl,
+	.ioctl		= hung_up_tty_ioctl,
+	.compat_ioctl	= hung_up_tty_compat_ioctl,
 	.release	= tty_release,
 };
 


Comment 16 Paul Fulghum 2007-06-08 12:25:01 UTC
On Fri, 2007-06-08 at 10:16 -0500, Paul Fulghum wrote:
> On Fri, 2007-06-08 at 05:06 +0200, Björn Steinbrink wrote:
> > This is do_tty_hangup() exchanging the fops while we're waiting for the
> > lock. The new fops (hung_up_tty_fops) only have the unlocked variant and
> > thus we Oops our way.
...
> Here is a patch that restores the locked ioctl for hung_up_tty_ioctl.
> Can you try it and see if it removes your oops?

Unfortunately I can't get the timing right to trigger this,
but it is very clear the locked ioctl fop must not be
allowed to disappear like my original patch allows.

Andrew:

Would you prefer I resend the entire compat ioctl patch or
submit an incremental patch like in my message I'm quoting above?

Comment 17 Anonymous Emailer 2007-06-08 12:38:07 UTC
Reply-To: akpm@linux-foundation.org

On Fri, 08 Jun 2007 14:20:48 -0500
Paul Fulghum <paulkf@microgate.com> wrote:

> On Fri, 2007-06-08 at 10:16 -0500, Paul Fulghum wrote:
> > On Fri, 2007-06-08 at 05:06 +0200, Bj__rn Steinbrink wrote:
> > > This is do_tty_hangup() exchanging the fops while we're waiting for the
> > > lock. The new fops (hung_up_tty_fops) only have the unlocked variant and
> > > thus we Oops our way.
> ...
> > Here is a patch that restores the locked ioctl for hung_up_tty_ioctl.
> > Can you try it and see if it removes your oops?
> 
> Unfortunately I can't get the timing right to trigger this,
> but it is very clear the locked ioctl fop must not be
> allowed to disappear like my original patch allows.
> 
> Andrew:
> 
> Would you prefer I resend the entire compat ioctl patch or
> submit an incremental patch like in my message I'm quoting above?
> 

The compat_ioctl patch is in mainline, and has been for some time.

Hence a patch against mainline would be appropriate, thanks.

Comment 18 Nicolas Mailhot 2007-09-18 14:54:25 UTC
I suppose it's fixed, didn't hit it for a *long* time
Comment 19 Alexey Dobriyan 2008-09-08 22:41:41 UTC
*** Bug 8574 has been marked as a duplicate of this bug. ***

Note You need to log in before you can comment on or make changes to this bug.