extra reference to fl->fl_file, possible regression

extra reference to fl->fl_file, possible regression

[William Dauchy]

[-- Attachment #1: Type: text/plain, Size: 1729 bytes --]

Hello,

We have been testing the two following patches on top of the last 3.14.x.
(they have been queued up for stable releases)

commit db2efec0caba4f81a22d95a34da640b86c313c8e
Author: Jeff Layton <jlayton@poochiereds.net>
Date:   Tue Jun 30 14:12:30 2015 -0400

    nfs: take extra reference to fl->fl_file when running a LOCKU operation

commit feaff8e5b2cfc3eae02cf65db7a400b0b9ffc596
Author: Jeff Layton <jlayton@poochiereds.net>
Date:   Tue May 12 15:48:10 2015 -0400

    nfs: take extra reference to fl->fl_file when running a setlk


It resulted in random instabilities; we are unable to reproduce it reliably for now;
the only trace we got was the one below.

------------[ cut here ]------------
WARNING: CPU: 0 PID: 8 at kernel/rcu/tree.c:2191 rcu_do_batch.isra.51+0x384/0x3d0()
CPU: 0 PID: 8 Comm: rcuc/0 Not tainted 3.14 #1
0000000000000009 ffff88061e5dfd10 ffffffff815f5143 0000000000000000
ffff88061e5dfd48 ffffffff8105eece 000000000000002f ffff880627c0b600
000000000000002f 0000000000000246 0000000000000000 ffff88061e5dfd58
Call Trace:
[<ffffffff815f5143>] dump_stack+0x4d/0x81
[<ffffffff8105eece>] warn_slowpath_common+0x6e/0x90
[<ffffffff8105efd5>] warn_slowpath_null+0x15/0x20
[<ffffffff810bc634>] rcu_do_batch.isra.51+0x384/0x3d0
[<ffffffff810bc42a>] ? rcu_do_batch.isra.51+0x17a/0x3d0
[<ffffffff810bc9ed>] rcu_cpu_kthread+0xed/0x130
[<ffffffff8108aabe>] smpboot_thread_fn+0x18e/0x2e0
[<ffffffff8108a930>] ? in_egroup_p+0x40/0x40
[<ffffffff8108358c>] kthread+0xec/0x110
[<ffffffff810834a0>] ? __kthread_parkme+0x80/0x80
[<ffffffff815fcb39>] ret_from_fork+0x49/0x80
[<ffffffff810834a0>] ? __kthread_parkme+0x80/0x80
---[ end trace 27f9589ec4225b03 ]---
-- 
William

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: extra reference to fl->fl_file, possible regression

[Jeff Layton]

[-- Attachment #1: Type: text/plain, Size: 2493 bytes --]

On Fri, 10 Jul 2015 11:29:10 +0200
William Dauchy <william@gandi.net> wrote:

> Hello,
> 
> We have been testing the two following patches on top of the last 3.14.x.
> (they have been queued up for stable releases)
> 
> commit db2efec0caba4f81a22d95a34da640b86c313c8e
> Author: Jeff Layton <jlayton@poochiereds.net>
> Date:   Tue Jun 30 14:12:30 2015 -0400
> 
>     nfs: take extra reference to fl->fl_file when running a LOCKU operation
> 
> commit feaff8e5b2cfc3eae02cf65db7a400b0b9ffc596
> Author: Jeff Layton <jlayton@poochiereds.net>
> Date:   Tue May 12 15:48:10 2015 -0400
> 
>     nfs: take extra reference to fl->fl_file when running a setlk
> 
> 
> It resulted in random instabilities; we are unable to reproduce it reliably for now;
> the only trace we got was the one below.
> 
> ------------[ cut here ]------------
> WARNING: CPU: 0 PID: 8 at kernel/rcu/tree.c:2191 rcu_do_batch.isra.51+0x384/0x3d0()
> CPU: 0 PID: 8 Comm: rcuc/0 Not tainted 3.14 #1
> 0000000000000009 ffff88061e5dfd10 ffffffff815f5143 0000000000000000
> ffff88061e5dfd48 ffffffff8105eece 000000000000002f ffff880627c0b600
> 000000000000002f 0000000000000246 0000000000000000 ffff88061e5dfd58
> Call Trace:
> [<ffffffff815f5143>] dump_stack+0x4d/0x81
> [<ffffffff8105eece>] warn_slowpath_common+0x6e/0x90
> [<ffffffff8105efd5>] warn_slowpath_null+0x15/0x20
> [<ffffffff810bc634>] rcu_do_batch.isra.51+0x384/0x3d0
> [<ffffffff810bc42a>] ? rcu_do_batch.isra.51+0x17a/0x3d0
> [<ffffffff810bc9ed>] rcu_cpu_kthread+0xed/0x130
> [<ffffffff8108aabe>] smpboot_thread_fn+0x18e/0x2e0
> [<ffffffff8108a930>] ? in_egroup_p+0x40/0x40
> [<ffffffff8108358c>] kthread+0xec/0x110
> [<ffffffff810834a0>] ? __kthread_parkme+0x80/0x80
> [<ffffffff815fcb39>] ret_from_fork+0x49/0x80
> [<ffffffff810834a0>] ? __kthread_parkme+0x80/0x80
> ---[ end trace 27f9589ec4225b03 ]---

Huh. I'm stumped...

These patches are pretty straightforward. We're just taking an extra
reference to the filp when running lock operations so that it doesn't
disappear before the replies can be processed (typically in the event
that a signal comes in while waiting on the reply). Given the odd stack
trace above, I have to wonder if there's some sort of memory scribble
going on.

Just to be clear...you are mounting with NFSv4 and running something on
the mount when you see this, right? If you don't use NFSv4, then is
everything fine?

Thanks,
-- 
Jeff Layton <jlayton@poochiereds.net>

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]

Re: extra reference to fl->fl_file, possible regression

[William Dauchy]

[-- Attachment #1: Type: text/plain, Size: 702 bytes --]

On Jul10 07:24, Jeff Layton wrote:
> These patches are pretty straightforward. We're just taking an extra
> reference to the filp when running lock operations so that it doesn't
> disappear before the replies can be processed (typically in the event
> that a signal comes in while waiting on the reply). Given the odd stack
> trace above, I have to wonder if there's some sort of memory scribble
> going on.

I was also surprised by such new behavior looking at the impact of those
patches.

> Just to be clear...you are mounting with NFSv4 and running something on
> the mount when you see this, right? If you don't use NFSv4, then is
> everything fine?

yes, it's nfv4.
-- 
William

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: extra reference to fl->fl_file, possible regression

[William Dauchy]

[-- Attachment #1: Type: text/plain, Size: 574 bytes --]

On Jul10 07:24, Jeff Layton wrote:
> Huh. I'm stumped...
> 
> These patches are pretty straightforward. We're just taking an extra
> reference to the filp when running lock operations so that it doesn't
> disappear before the replies can be processed (typically in the event
> that a signal comes in while waiting on the reply). Given the odd stack
> trace above, I have to wonder if there's some sort of memory scribble
> going on.

I also forgot to mention that I also had the following messgae before
the trace:

VFS: Close: file count is 0

-- 
William

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: extra reference to fl->fl_file, possible regression

[Jeff Layton]

[-- Attachment #1: Type: text/plain, Size: 1738 bytes --]

On Fri, 10 Jul 2015 14:54:44 +0200
William Dauchy <william@gandi.net> wrote:

> On Jul10 07:24, Jeff Layton wrote:
> > Huh. I'm stumped...
> > 
> > These patches are pretty straightforward. We're just taking an extra
> > reference to the filp when running lock operations so that it doesn't
> > disappear before the replies can be processed (typically in the event
> > that a signal comes in while waiting on the reply). Given the odd stack
> > trace above, I have to wonder if there's some sort of memory scribble
> > going on.
> 
> I also forgot to mention that I also had the following messgae before
> the trace:
> 
> VFS: Close: file count is 0
> 

Ok, that may be an important clue. From filp_close:

        if (!file_count(filp)) {
                printk(KERN_ERR "VFS: Close: file count is 0\n");
                return 0;
        }

...so looks like there could be a use-after free going on? Somehow
we're ending up with with an actual close being done after the last
reference has already been put. I'm not s

So, I suspect that the problem is with the second patch (the LOCKU
one).

I'm not sure if it's responsible for that message, but one of the
things we do in __fput() is call locks_remove_flock, which can dip down
into the NFS unlock codepath.

So if a file happened to have some flock locks on it, then we could
be taking a new reference to a file that has already had its refcount
go to zero.

I'll have to think about how best to deal with this as I totally missed
this when I did the original analysis of the bug. For now it's probably
best to revert that patch (though I think the one for the setlk is
likely OK).

Thanks,
-- 
Jeff Layton <jlayton@poochiereds.net>

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]

Re: extra reference to fl->fl_file, possible regression

[William Dauchy]

[-- Attachment #1: Type: text/plain, Size: 358 bytes --]

On Jul10 10:39, Jeff Layton wrote:
> So if a file happened to have some flock locks on it, then we could
> be taking a new reference to a file that has already had its refcount
> go to zero.

do you have any test case which may confirm that?
in the commit messages, you also were refering to some tests; I wonder
if you could share it.
-- 
William

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: extra reference to fl->fl_file, possible regression

[Jeff Layton]

[-- Attachment #1: Type: text/plain, Size: 846 bytes --]

On Fri, 10 Jul 2015 17:06:59 +0200
William Dauchy <william@gandi.net> wrote:

> On Jul10 10:39, Jeff Layton wrote:
> > So if a file happened to have some flock locks on it, then we could
> > be taking a new reference to a file that has already had its refcount
> > go to zero.
> 
> do you have any test case which may confirm that?

Not right offhand, at least not with a stock kernel.

I was planning to turn that get_file call into an
atomic_long_inc_return and then test the return value and WARN if it
was 1. Then, set a flock lock on a file, and close it without
explicitly unlocking. I suspect that would make the WARN pop.

> in the commit messages, you also were refering to some tests; I wonder
> if you could share it.

Jean? Are those tests something you could share?

-- 
Jeff Layton <jlayton@poochiereds.net>

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]