by Jeff Layton

[permalink] [raw]

On Sun, 15 Jun 2008 19:10:27 +0100
"Daniel J Blueman" <[email protected]> wrote:

> On Thu, Jun 5, 2008 at 12:43 AM, Chuck Lever <[email protected]> wrote:
> > Hi Daniel-
> >
> > On Wed, Jun 4, 2008 at 7:33 PM, Daniel J Blueman
> > <[email protected]> wrote:
> >> Having experienced 'mount.nfs4: internal error' when mounting nfsv4 in
> >> the past, I have a minimal test-case I sometimes run:
> >>
> >> $ while :; do mount -t nfs4 filer:/store /store; umount /store; done
> >>
> >> After ~100 iterations, I saw the 'mount.nfs4: internal error',
> >> followed by symptoms of memory corruption [1], a locking issue with
> >> the reporting [2] and another (related?) memory-corruption issue
> >> (off-by-1?) [3]. A little analysis shows memory being overwritten by
> >> (likely) a poison value, which gets complicated if it's not
> >> use-after-free...
> >>
> >> Anyone dare confirm this issue? NFSv4 server is x86-64 Ubuntu 8.04
> >> 2.6.24-18, client U8.04 2.6.26-rc4; batteries included [4].
> >
> > We have some other reports of late model kernels with memory
> > corruption issues during NFS mount. The problem is that by the time
> > these canaries start singing, the evidence of what did the corrupting
> > is long gone.
> >
> >> I'm happy to decode addresses, test patches etc.
> >
> > If these crashes are more or less reliably reproduced, it would be
> > helpful if you could do a 'git bisect' on the client to figure out at
> > what point in the kernel revision history this problem was introduced.
> >
> > Have you seen the problem on client kernels earlier than 2.6.25?
>
> Firstly, I had omitted that I'd booted the kernel with
> debug_objects=1, which provides the canary here.
>
> The primary failure I see is 'mount.nfs4: internal error', and always
> after 358 umount/mount cycles (plus 1 initial mount) which gives us a
> clue; 'netstat' shows all these connections in a TIME_WAIT state, thus
> the bug relates to the inability to allocate a socket error path. I
> found that after the connection lifetime expired, you can mount again,
> which corroborates this theory.
>
> In this case, we saw the mount() syscall result in the mount.nfsv4
> process being SEGV'd when booted with 'debug_object=1', without this
> option, we see:
>
> # strace /sbin/mount.nfs4 x1:/ /store
> ...
> mount("x1:/", "/store", "nfs4", 0,
> "addr=192.168.0.250,clientaddr=19"...) = -1 EIO (Input/output error)
>
> So, it's impossible to tell when the corruption was introduced, as it
> has only become detectable recently.
>
> It's worth a look-over of the socket-allocation error path, if someone
> can check, and reproduces 100% with the 'debug_object=1' param,
> available since 2.6.26-rc1 and 359 mounts in quick succession.
>

For some strange reason (probably something I'm doing wrong or maybe
something environmental), I've not been able to reproduce this panic on
a stock kernel. I did, however, apply the following fault injection
patch and was able to reproduce it on the second mount attempt. The 3
patch set that I posted last week definitely prevents the oops. If
you're able to confirm that it also fixes your panic it would be a
helpful data point.

The fault injection patch I'm using is attached. It just simulates
nfs4_init_client() consistently returning an error.

Cheers,
--
Jeff Layton <[email protected]>

Attachments:

(No filename) (3.27 kB)
nfs4-mount-fault-injection.patch (401.00 B)
Download all attachments

2008-06-19 12:38:51

by Daniel J Blueman

[permalink] [raw]

Subject: Re: [2.6.26-rc4] mount.nfsv4/memory poisoning issues...

On Thu, Jun 19, 2008 at 1:14 PM, Jeff Layton <[email protected]> wrote:
> On Sun, 15 Jun 2008 19:10:27 +0100
> "Daniel J Blueman" <[email protected]> wrote:
>
>> On Thu, Jun 5, 2008 at 12:43 AM, Chuck Lever <[email protected]> wrote:
>> > Hi Daniel-
>> >
>> > On Wed, Jun 4, 2008 at 7:33 PM, Daniel J Blueman
>> > <[email protected]> wrote:
>> >> Having experienced 'mount.nfs4: internal error' when mounting nfsv4 in
>> >> the past, I have a minimal test-case I sometimes run:
>> >>
>> >> $ while :; do mount -t nfs4 filer:/store /store; umount /store; done
>> >>
>> >> After ~100 iterations, I saw the 'mount.nfs4: internal error',
>> >> followed by symptoms of memory corruption [1], a locking issue with
>> >> the reporting [2] and another (related?) memory-corruption issue
>> >> (off-by-1?) [3]. A little analysis shows memory being overwritten by
>> >> (likely) a poison value, which gets complicated if it's not
>> >> use-after-free...
>> >>
>> >> Anyone dare confirm this issue? NFSv4 server is x86-64 Ubuntu 8.04
>> >> 2.6.24-18, client U8.04 2.6.26-rc4; batteries included [4].
>> >
>> > We have some other reports of late model kernels with memory
>> > corruption issues during NFS mount. The problem is that by the time
>> > these canaries start singing, the evidence of what did the corrupting
>> > is long gone.
>> >
>> >> I'm happy to decode addresses, test patches etc.
>> >
>> > If these crashes are more or less reliably reproduced, it would be
>> > helpful if you could do a 'git bisect' on the client to figure out at
>> > what point in the kernel revision history this problem was introduced.
>> >
>> > Have you seen the problem on client kernels earlier than 2.6.25?
>>
>> Firstly, I had omitted that I'd booted the kernel with
>> debug_objects=1, which provides the canary here.
>>
>> The primary failure I see is 'mount.nfs4: internal error', and always
>> after 358 umount/mount cycles (plus 1 initial mount) which gives us a
>> clue; 'netstat' shows all these connections in a TIME_WAIT state, thus
>> the bug relates to the inability to allocate a socket error path. I
>> found that after the connection lifetime expired, you can mount again,
>> which corroborates this theory.
>>
>> In this case, we saw the mount() syscall result in the mount.nfsv4
>> process being SEGV'd when booted with 'debug_object=1', without this
>> option, we see:
>>
>> # strace /sbin/mount.nfs4 x1:/ /store
>> ...
>> mount("x1:/", "/store", "nfs4", 0,
>> "addr=192.168.0.250,clientaddr=19"...) = -1 EIO (Input/output error)
>>
>> So, it's impossible to tell when the corruption was introduced, as it
>> has only become detectable recently.
>>
>> It's worth a look-over of the socket-allocation error path, if someone
>> can check, and reproduces 100% with the 'debug_object=1' param,
>> available since 2.6.26-rc1 and 359 mounts in quick succession.
>>
>
> For some strange reason (probably something I'm doing wrong or maybe
> something environmental), I've not been able to reproduce this panic on
> a stock kernel. I did, however, apply the following fault injection
> patch and was able to reproduce it on the second mount attempt. The 3
> patch set that I posted last week definitely prevents the oops. If
> you're able to confirm that it also fixes your panic it would be a
> helpful data point.
>
> The fault injection patch I'm using is attached. It just simulates
> nfs4_init_client() consistently returning an error.

Thanks! I hope to get time for this tonight and will get back to you;
I appreciate your help, Jeff.

The config I used to reproduce it on the client is
http://www.quora.org/config-debug and is relevant to (at least)
2.6.26-rc5. I was able to reproduce it by exporting a single NFSv4
export on 2.6.25 (eg Ubuntu 8.04 server); client and server were
x86-64.

Daniel

> Cheers,
> --
> Jeff Layton <[email protected]>
--
Daniel J Blueman

2008-06-19 17:32:48

by Chuck Lever

[permalink] [raw]

Subject: Re: [2.6.26-rc4] mount.nfsv4/memory poisoning issues...

On Thu, Jun 19, 2008 at 8:37 AM, Daniel J Blueman
<[email protected]> wrote:
> On Thu, Jun 19, 2008 at 1:14 PM, Jeff Layton <[email protected]> wrote:
>> On Sun, 15 Jun 2008 19:10:27 +0100
>> "Daniel J Blueman" <[email protected]> wrote:
>>
>>> On Thu, Jun 5, 2008 at 12:43 AM, Chuck Lever <[email protected]> wrote:
>>> > Hi Daniel-
>>> >
>>> > On Wed, Jun 4, 2008 at 7:33 PM, Daniel J Blueman
>>> > <[email protected]> wrote:
>>> >> Having experienced 'mount.nfs4: internal error' when mounting nfsv4 in
>>> >> the past, I have a minimal test-case I sometimes run:
>>> >>
>>> >> $ while :; do mount -t nfs4 filer:/store /store; umount /store; done
>>> >>
>>> >> After ~100 iterations, I saw the 'mount.nfs4: internal error',
>>> >> followed by symptoms of memory corruption [1], a locking issue with
>>> >> the reporting [2] and another (related?) memory-corruption issue
>>> >> (off-by-1?) [3]. A little analysis shows memory being overwritten by
>>> >> (likely) a poison value, which gets complicated if it's not
>>> >> use-after-free...
>>> >>
>>> >> Anyone dare confirm this issue? NFSv4 server is x86-64 Ubuntu 8.04
>>> >> 2.6.24-18, client U8.04 2.6.26-rc4; batteries included [4].
>>> >
>>> > We have some other reports of late model kernels with memory
>>> > corruption issues during NFS mount. The problem is that by the time
>>> > these canaries start singing, the evidence of what did the corrupting
>>> > is long gone.
>>> >
>>> >> I'm happy to decode addresses, test patches etc.
>>> >
>>> > If these crashes are more or less reliably reproduced, it would be
>>> > helpful if you could do a 'git bisect' on the client to figure out at
>>> > what point in the kernel revision history this problem was introduced.
>>> >
>>> > Have you seen the problem on client kernels earlier than 2.6.25?
>>>
>>> Firstly, I had omitted that I'd booted the kernel with
>>> debug_objects=1, which provides the canary here.
>>>
>>> The primary failure I see is 'mount.nfs4: internal error', and always
>>> after 358 umount/mount cycles (plus 1 initial mount) which gives us a
>>> clue; 'netstat' shows all these connections in a TIME_WAIT state, thus
>>> the bug relates to the inability to allocate a socket error path. I
>>> found that after the connection lifetime expired, you can mount again,
>>> which corroborates this theory.
>>>
>>> In this case, we saw the mount() syscall result in the mount.nfsv4
>>> process being SEGV'd when booted with 'debug_object=1', without this
>>> option, we see:
>>>
>>> # strace /sbin/mount.nfs4 x1:/ /store
>>> ...
>>> mount("x1:/", "/store", "nfs4", 0,
>>> "addr=192.168.0.250,clientaddr=19"...) = -1 EIO (Input/output error)
>>>
>>> So, it's impossible to tell when the corruption was introduced, as it
>>> has only become detectable recently.
>>>
>>> It's worth a look-over of the socket-allocation error path, if someone
>>> can check, and reproduces 100% with the 'debug_object=1' param,
>>> available since 2.6.26-rc1 and 359 mounts in quick succession.
>>>
>>
>> For some strange reason (probably something I'm doing wrong or maybe
>> something environmental), I've not been able to reproduce this panic on
>> a stock kernel. I did, however, apply the following fault injection
>> patch and was able to reproduce it on the second mount attempt. The 3
>> patch set that I posted last week definitely prevents the oops. If
>> you're able to confirm that it also fixes your panic it would be a
>> helpful data point.
>>
>> The fault injection patch I'm using is attached. It just simulates
>> nfs4_init_client() consistently returning an error.
>
> Thanks! I hope to get time for this tonight and will get back to you;
> I appreciate your help, Jeff.
>
> The config I used to reproduce it on the client is
> http://www.quora.org/config-debug and is relevant to (at least)
> 2.6.26-rc5. I was able to reproduce it by exporting a single NFSv4
> export on 2.6.25 (eg Ubuntu 8.04 server); client and server were
> x86-64.

For the record, I was able to reproduce with a dual core 2.6.26-rc4
x86 client (using SLUB, not SLAB) on Fedora 8 against a Solaris 2008.5
NFSv4 server. When the client runs out of ports, the mount commands
start to fail with EIO. Then after a few dozen of these, the mounting
process hangs. Sometimes it will BUG because freed & poisoned memory
is passed to kthread_stop(). I haven't seen some of the other
subsequent issues that Daniel initially reported.

--
I am certain that these presidents will understand the cry of the
people of Bolivia, of the people of Latin America and the whole world,
which wants to have more food and not more cars. First food, then if
something's left over, more cars, more automobiles. I think that life
has to come first.
-- Evo Morales

2008-06-21 17:52:24

by Daniel J Blueman

[permalink] [raw]

Subject: Re: [2.6.26-rc4] mount.nfsv4/memory poisoning issues...

On Wed, Jun 18, 2008 at 1:07 PM, Jeff Layton <[email protected]> wrote:
> On Tue, 10 Jun 2008 21:27:07 +0100
> "Daniel J Blueman" <[email protected]> wrote:
>
>> On Tue, Jun 10, 2008 at 8:18 PM, Jeff Layton <[email protected]> wrote:
>> > On Tue, 10 Jun 2008 15:13:57 -0400
>> > Jeff Layton <[email protected]> wrote:
>> >
>> >> On Tue, 10 Jun 2008 14:54:48 -0400
>> >> Trond Myklebust <[email protected]> wrote:
>> >>
>> >> > On Wed, 2008-06-04 at 20:35 -0400, Jeff Layton wrote:
>> >> > > On Thu, 5 Jun 2008 00:33:54 +0100
>> >> > > "Daniel J Blueman" <[email protected]> wrote:
>> >> > >
>> >> > > > Having experienced 'mount.nfs4: internal error' when mounting nfsv4 in
>> >> > > > the past, I have a minimal test-case I sometimes run:
>> >> > > >
>> >> > > > $ while :; do mount -t nfs4 filer:/store /store; umount /store; done
>> >> > > >
>> >> > > > After ~100 iterations, I saw the 'mount.nfs4: internal error',
>> >> > > > followed by symptoms of memory corruption [1], a locking issue with
>> >> > > > the reporting [2] and another (related?) memory-corruption issue
>> >> > > > (off-by-1?) [3]. A little analysis shows memory being overwritten by
>> >> > > > (likely) a poison value, which gets complicated if it's not
>> >> > > > use-after-free...
>> >> > > >
>> >> > > > Anyone dare confirm this issue? NFSv4 server is x86-64 Ubuntu 8.04
>> >> > > > 2.6.24-18, client U8.04 2.6.26-rc4; batteries included [4].
>> >> > > >
>> >> > > > I'm happy to decode addresses, test patches etc.
>> >> > > >
>> >> > > > Daniel
>> >> > > >
>> >> > >
>> >> > > Looks like it fell down while trying to take down the kthread during a
>> >> > > failed mount attempt. I have to wonder if I might have introduced a
>> >> > > race when I changed nfs4 callback thread to kthread API. I think we may
>> >> > > need the BKL around the last 2 statements in the main callback thread
>> >> > > function. If you can easily reproduce this, could you test the
>> >> > > following patch and let me know if it helps?
>> >> > >
>> >> > > Note that this patch is entirely untested, so test it someplace
>> >> > > non-critical ;-).
>> >> > >
>> >> > > Signed-off-by: Jeff Layton <[email protected]>
>> >> > >
>> >> > >
>> >> > > diff --git a/fs/nfs/callback.c b/fs/nfs/callback.c
>> >> > > index c1e7c83..a3e83f9 100644
>> >> > > --- a/fs/nfs/callback.c
>> >> > > +++ b/fs/nfs/callback.c
>> >> > > @@ -90,9 +90,9 @@ nfs_callback_svc(void *vrqstp)
>> >> > > preverr = err;
>> >> > > svc_process(rqstp);
>> >> > > }
>> >> > > - unlock_kernel();
>> >> > > nfs_callback_info.task = NULL;
>> >> > > svc_exit_thread(rqstp);
>> >> > > + unlock_kernel();
>> >> > > return 0;
>> >> > > }
>> >> >
>> >> > We certainly need to protect nfs_callback_info.task (and I believe I
>> >> > explained this earlier), but why do we need to protect svc_exit_thread?
>> >> >
>> >> > Also, looking at the general use of the BKL in that code, I thought we
>> >> > agreed that there was no need to hold the BKL while taking the
>> >> > nfs_callback_mutex?
>> >> >
>> >>
>> >> Hmm, I don't remember that discussion, but I'll take your word for it...
>> >>
>> >> I think you're basically correct, but it looks to me like the
>> >> nfs_callback_mutex actually protects nfs_callback_info.task as well.
>> >>
>> >> If we're starting the thread, then we can't call kthread_stop on it
>> >> until we release the mutex. So the thread can't exit until we release
>> >> the mutex, and we can be guaranteed that this:
>> >>
>> >> nfs_callback_info.task = NULL;
>> >>
>> >> ...can't happen until after kthread_run returns and nfs_callback_up
>> >> sets it.
>> >>
>> >> If that's right, then maybe this (untested, RFC only) patch would make sense?
>> >>
>> >
>> > To clarify for Dan...
>> >
>> > I don't think that this patch will help the problem you're having. This
>> > is essentially a cleanup patch to remove some locking that doesn't
>> > appear to be needed.
>> >
>> > The original patch that Trond commented on above is also probably
>> > unnecessary (assuming I'm right about the locking here).
>>
>> Thanks for the head-up, Jeff. I took it at face value, so didn't
>> harbour the notion it would fix the memory corruption.
>>
>> Let's see If I can get time for this git bisect sooner rather than later...
>
> I've tried reproducing this, but haven't had much success (probably some
> differences in my kernel config).
>
> I suspect that Trond is correct here and the race has something to
> do with the kthread being spawned but nfs_callback_svc() never getting
> a chance to run. I posted a patchset to the list late last week with the
> intro email:
>
> [PATCH 0/3] fix potential races in lockd and nfs4-callback startup/shutdown
>
> Dan, could you apply that patchset to your kernel and see if it helps
> this problem?

Yes, I confirm the problem reproduces without this patchset and I'm
unable to reproduce it with the patchset, so looks good!

Thanks again for the all the help and fixes!
Dan
--
Daniel J Blueman