kdevtmpfs oops since yesterdays vfs merge

kdevtmpfs oops since yesterdays vfs merge

[Dave Jones]

I see an oops in handle_create when I try to boot current tree..

full trace:
https://s3.amazonaws.com/twitpic/photos/large/355006460.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311550232&Signature=IIO%2Bya1uEDJzSXTD0DXh2%2BdZpoU%3D

	Dave

Re: kdevtmpfs oops since yesterdays vfs merge

[Al Viro]

On Sun, Jul 24, 2011 at 07:17:01PM -0400, Dave Jones wrote:
> I see an oops in handle_create when I try to boot current tree..
> 
> full trace:
> https://s3.amazonaws.com/twitpic/photos/large/355006460.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311550232&Signature=IIO%2Bya1uEDJzSXTD0DXh2%2BdZpoU%3D

Where in handle_create() is that?  At least dump objdump -d of your
devtmpfs.o someplace readable...

Re: kdevtmpfs oops since yesterdays vfs merge

[Dave Jones]

On Mon, Jul 25, 2011 at 12:28:12AM +0100, Al Viro wrote:
 > On Sun, Jul 24, 2011 at 07:17:01PM -0400, Dave Jones wrote:
 > > I see an oops in handle_create when I try to boot current tree..
 > > 
 > > full trace:
 > > https://s3.amazonaws.com/twitpic/photos/large/355006460.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311550232&Signature=IIO%2Bya1uEDJzSXTD0DXh2%2BdZpoU%3D
 > 
 > Where in handle_create() is that?  At least dump objdump -d of your
 > devtmpfs.o someplace readable...

http://codemonkey.org.uk/devtmpfs.s

	Dave

Re: kdevtmpfs oops since yesterdays vfs merge

[Al Viro]

On Sun, Jul 24, 2011 at 07:40:29PM -0400, Dave Jones wrote:
> On Mon, Jul 25, 2011 at 12:28:12AM +0100, Al Viro wrote:
>  > On Sun, Jul 24, 2011 at 07:17:01PM -0400, Dave Jones wrote:
>  > > I see an oops in handle_create when I try to boot current tree..
>  > > 
>  > > full trace:
>  > > https://s3.amazonaws.com/twitpic/photos/large/355006460.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311550232&Signature=IIO%2Bya1uEDJzSXTD0DXh2%2BdZpoU%3D
>  > 
>  > Where in handle_create() is that?  At least dump objdump -d of your
>  > devtmpfs.o someplace readable...
> 
> http://codemonkey.org.uk/devtmpfs.s

Smells like req->dev somehow managing to be NULL at that point, but that
doesn't make any sense - we get to devtmpfs_create_node() only from one
place, it sets req.dev to the argument it got from callers and that caller
would have oopsed itself before getting to that call with dev == NULL...

Could you stick a BUG_ON(!dev) in the beginning of handle_create() to see
if that's what somehow manages to happen?

Re: kdevtmpfs oops since yesterdays vfs merge

[Dave Jones]

On Mon, Jul 25, 2011 at 12:51:54AM +0100, Al Viro wrote:
 > On Sun, Jul 24, 2011 at 07:40:29PM -0400, Dave Jones wrote:
 > > On Mon, Jul 25, 2011 at 12:28:12AM +0100, Al Viro wrote:
 > >  > On Sun, Jul 24, 2011 at 07:17:01PM -0400, Dave Jones wrote:
 > >  > > I see an oops in handle_create when I try to boot current tree..
 > >  > > 
 > >  > > full trace:
 > >  > > https://s3.amazonaws.com/twitpic/photos/large/355006460.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311550232&Signature=IIO%2Bya1uEDJzSXTD0DXh2%2BdZpoU%3D
 > >  > 
 > >  > Where in handle_create() is that?  At least dump objdump -d of your
 > >  > devtmpfs.o someplace readable...
 > > 
 > > http://codemonkey.org.uk/devtmpfs.s
 > 
 > Smells like req->dev somehow managing to be NULL at that point, but that
 > doesn't make any sense - we get to devtmpfs_create_node() only from one
 > place, it sets req.dev to the argument it got from callers and that caller
 > would have oopsed itself before getting to that call with dev == NULL...
 > 
 > Could you stick a BUG_ON(!dev) in the beginning of handle_create() to see
 > if that's what somehow manages to happen?

So I built a kernel with this, and then couldn't reproduce it.
Made a clean kernel again, and still nothing..  After a number of reboots,
it finally triggered again, with that BUG_ON(). fwiw 'nodename' is pointing
at garbage when that happens too.

Either it only triggers occasionally, or it's dependent on how quickly
I type my luks password in.

	Dave

Re: kdevtmpfs oops since yesterdays vfs merge

[Dave Jones]

On Sun, Jul 24, 2011 at 09:53:24PM -0400, Dave Jones wrote:
 > On Mon, Jul 25, 2011 at 12:51:54AM +0100, Al Viro wrote:
 >  > On Sun, Jul 24, 2011 at 07:40:29PM -0400, Dave Jones wrote:
 >  > > On Mon, Jul 25, 2011 at 12:28:12AM +0100, Al Viro wrote:
 >  > >  > On Sun, Jul 24, 2011 at 07:17:01PM -0400, Dave Jones wrote:
 >  > >  > > I see an oops in handle_create when I try to boot current tree..
 >  > >  > > 
 >  > >  > > full trace:
 >  > >  > > https://s3.amazonaws.com/twitpic/photos/large/355006460.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311550232&Signature=IIO%2Bya1uEDJzSXTD0DXh2%2BdZpoU%3D
 >  > >  > 
 >  > >  > Where in handle_create() is that?  At least dump objdump -d of your
 >  > >  > devtmpfs.o someplace readable...
 >  > > 
 >  > > http://codemonkey.org.uk/devtmpfs.s
 >  > 
 >  > Smells like req->dev somehow managing to be NULL at that point, but that
 >  > doesn't make any sense - we get to devtmpfs_create_node() only from one
 >  > place, it sets req.dev to the argument it got from callers and that caller
 >  > would have oopsed itself before getting to that call with dev == NULL...
 >  > 
 >  > Could you stick a BUG_ON(!dev) in the beginning of handle_create() to see
 >  > if that's what somehow manages to happen?
 > 
 > So I built a kernel with this, and then couldn't reproduce it.
 > Made a clean kernel again, and still nothing..  After a number of reboots,
 > it finally triggered again, with that BUG_ON(). fwiw 'nodename' is pointing
 > at garbage when that happens too.
 > 
 > Either it only triggers occasionally, or it's dependent on how quickly
 > I type my luks password in.

one more datapoint. On a succesful boot, I see ..

[    7.760774] dracut: luksOpen /dev/sda2 luks-b5a1fb36-5672-4191-a260-e3f389eb0bb6
[   14.787158] nodename: dm-0
[   15.082391] nodename: dm-0


when it triggers the bug_on(), it's that second nodename that is garbage.

	Dave

Re: kdevtmpfs oops since yesterdays vfs merge

[Al Viro]

On Sun, Jul 24, 2011 at 09:56:12PM -0400, Dave Jones wrote:

> [    7.760774] dracut: luksOpen /dev/sda2 luks-b5a1fb36-5672-4191-a260-e3f389eb0bb6
> [   14.787158] nodename: dm-0
> [   15.082391] nodename: dm-0
> 
> 
> when it triggers the bug_on(), it's that second nodename that is garbage.

Interesting...  The next experiment would be to stick BUG_ON(!req.dev)
into devtmpfs_create_node() right after the assigment to that field.

We couldn't be hit by the lack of barriers here, could we?  Store to
req.dev happens before spin_unlock(&req_lock), so by the time when
that request is seen by loop in devtmpfsd() and passed to handle() it
should be seen - we have grabbed req_lock, found a pointer to req, dropped
req_lock and called handle().  Should've been enough...

Might be interesting to print &req from devtmpfs_create_node(), both on
entry and on exit, and print req right before the call of handle()...

Incidentally, that disassembly shows one really ugly thing - offset of
->devt in struct device is 0x3c0.  IOW, each of those suckers eats a
kilobyte... ;-/

Re: kdevtmpfs oops since yesterdays vfs merge

[Dave Jones]

On Mon, Jul 25, 2011 at 03:44:44AM +0100, Al Viro wrote:

 > > when it triggers the bug_on(), it's that second nodename that is garbage.
 > 
 > Interesting...  The next experiment would be to stick BUG_ON(!req.dev)
 > into devtmpfs_create_node() right after the assigment to that field.

couldn't get that to trigger.

 > We couldn't be hit by the lack of barriers here, could we?  Store to
 > req.dev happens before spin_unlock(&req_lock), so by the time when
 > that request is seen by loop in devtmpfsd() and passed to handle() it
 > should be seen - we have grabbed req_lock, found a pointer to req, dropped
 > req_lock and called handle().  Should've been enough...
 > 
 > Might be interesting to print &req from devtmpfs_create_node(), both on
 > entry and on exit, and print req right before the call of handle()...

Here's latest..

https://s3.amazonaws.com/twitpic/photos/full/355219312.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311570683&Signature=xr3tusulMiV2bIsxux9YNrawUDA%3D
 
apologies for crappy picture, but it's legible at fullsize..

interesting thing here is that the req that causes the oops, I couldn't
find any call to create_handle for that address, so where devtmpfsd got it
is a mystery.  The address is curious too, in that it's way off from all the
reqs created around that time.

I'll add some more printk's to see if I can figure where that's being created.

	Dave

Re: kdevtmpfs oops since yesterdays vfs merge

[Al Viro]

On Mon, Jul 25, 2011 at 12:58:52AM -0400, Dave Jones wrote:
> On Mon, Jul 25, 2011 at 03:44:44AM +0100, Al Viro wrote:
> 
>  > > when it triggers the bug_on(), it's that second nodename that is garbage.
>  > 
>  > Interesting...  The next experiment would be to stick BUG_ON(!req.dev)
>  > into devtmpfs_create_node() right after the assigment to that field.
> 
> couldn't get that to trigger.

Interesting...

>  > We couldn't be hit by the lack of barriers here, could we?  Store to
>  > req.dev happens before spin_unlock(&req_lock), so by the time when
>  > that request is seen by loop in devtmpfsd() and passed to handle() it
>  > should be seen - we have grabbed req_lock, found a pointer to req, dropped
>  > req_lock and called handle().  Should've been enough...
>  > 
>  > Might be interesting to print &req from devtmpfs_create_node(), both on
>  > entry and on exit, and print req right before the call of handle()...
> 
> Here's latest..
> 
> https://s3.amazonaws.com/twitpic/photos/full/355219312.jpg?AWSAccessKeyId=AKIAJF3XCCKACR3QDMOA&Expires=1311570683&Signature=xr3tusulMiV2bIsxux9YNrawUDA%3D
>  
> apologies for crappy picture, but it's legible at fullsize..
> 
> interesting thing here is that the req that causes the oops, I couldn't
> find any call to create_handle for that address, so where devtmpfsd got it
> is a mystery.  The address is curious too, in that it's way off from all the
> reqs created around that time.

Arrgh...  OK, I see what's going on.

                                req->err = handle(req->name, req->mode, req->dev);
                                complete(&req->done);
                                req = req->next;
is letting the request creator to continue; if it leaves the scope, guess
what is left in *req?  That's right, garbage...  Including req->next.
All right, try this and let's see if it fixes the problem:

diff --git a/drivers/base/devtmpfs.c b/drivers/base/devtmpfs.c
index 3644dd4..49b6cba 100644
--- a/drivers/base/devtmpfs.c
+++ b/drivers/base/devtmpfs.c
@@ -406,9 +406,10 @@ static int devtmpfsd(void *p)
 			requests = NULL;
 			spin_unlock(&req_lock);
 			while (req) {
+				struct req *next = req->next;
 				req->err = handle(req->name, req->mode, req->dev);
 				complete(&req->done);
-				req = req->next;
+				req = next;
 			}
 			spin_lock(&req_lock);
 		}

Re: kdevtmpfs oops since yesterdays vfs merge

[Dave Jones]

On Mon, Jul 25, 2011 at 06:12:51AM +0100, Al Viro wrote:
 
 > Arrgh...  OK, I see what's going on.
 > 
 >                                 req->err = handle(req->name, req->mode, req->dev);
 >                                 complete(&req->done);
 >                                 req = req->next;
 > is letting the request creator to continue; if it leaves the scope, guess
 > what is left in *req?  That's right, garbage...  Including req->next.
 > All right, try this and let's see if it fixes the problem:
 
Yep, that solves the problem.

	Dave 

Re: kdevtmpfs oops since yesterdays vfs merge

[Al Viro]

On Mon, Jul 25, 2011 at 01:53:08AM -0400, Dave Jones wrote:
> On Mon, Jul 25, 2011 at 06:12:51AM +0100, Al Viro wrote:
>  
>  > Arrgh...  OK, I see what's going on.
>  > 
>  >                                 req->err = handle(req->name, req->mode, req->dev);
>  >                                 complete(&req->done);
>  >                                 req = req->next;
>  > is letting the request creator to continue; if it leaves the scope, guess
>  > what is left in *req?  That's right, garbage...  Including req->next.
>  > All right, try this and let's see if it fixes the problem:
>  
> Yep, that solves the problem.

OK, to Linus it goes tomorrow morning...  I'm about to fall asleep right now
and queue needs a bit of reordering ;-/