Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1700139 > unrolled thread

Re: [GIT PULL] Please pull NFS client changes for Linux 4.13

Started by"davej@codemonkey.org.uk" <davej@codemonkey.org.uk>
First post2017-07-31 17:50 +0200
Last post2017-08-01 20:00 +0200
Articles 8 — 3 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 "davej@codemonkey.org.uk" <davej@codemonkey.org.uk> - 2017-07-31 17:50 +0200
    Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-01 07:40 +0200
      Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 "davej@codemonkey.org.uk" <davej@codemonkey.org.uk> - 2017-08-01 18:00 +0200
        Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-01 19:30 +0200
          Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 Trond Myklebust <trondmy@primarydata.com> - 2017-08-01 19:40 +0200
          Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 "davej@codemonkey.org.uk" <davej@codemonkey.org.uk> - 2017-08-01 20:00 +0200
            Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 Trond Myklebust <trondmy@primarydata.com> - 2017-08-01 20:00 +0200
          Re: [GIT PULL] Please pull NFS client changes for Linux 4.13 Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-01 20:00 +0200

#1700139 — Re: [GIT PULL] Please pull NFS client changes for Linux 4.13

From"davej@codemonkey.org.uk" <davej@codemonkey.org.uk>
Date2017-07-31 17:50 +0200
SubjectRe: [GIT PULL] Please pull NFS client changes for Linux 4.13
Message-ID<u9l7b-82B-15@gated-at.bofh.it>
Another NFSv4 KASAN splat, this time from rc3.


==================================================================
BUG: KASAN: use-after-free in nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]
Read of size 8 at addr ffff8804508af528 by task kworker/2:1/34

CPU: 2 PID: 34 Comm: kworker/2:1 Not tainted 4.13.0-rc3-think+ #1 
Workqueue: rpciod rpc_async_schedule [sunrpc]
Call Trace:
 dump_stack+0x68/0xa1
 print_address_description+0xd9/0x270
 kasan_report+0x257/0x370
 ? nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]
 check_memory_region+0x13a/0x1a0
 __asan_loadN+0xf/0x20
 nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]
 ? nfs4_exchange_id_release+0xb0/0xb0 [nfsv4]
 rpc_exit_task+0x69/0x110 [sunrpc]
 ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
 ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
 __rpc_execute+0x1a0/0x840 [sunrpc]
 ? rpc_wake_up_queued_task+0x50/0x50 [sunrpc]
 ? __lock_is_held+0x9a/0x100
 ? debug_lockdep_rcu_enabled.part.16+0x1a/0x30
 rpc_async_schedule+0x12/0x20 [sunrpc]
 process_one_work+0x4d5/0xa70
 ? flush_delayed_work+0x70/0x70
 ? lock_acquire+0xfc/0x220
 worker_thread+0x88/0x630
 ? pci_mmcfg_check_reserved+0xc0/0xc0
 kthread+0x1a6/0x1f0
 ? process_one_work+0xa70/0xa70
 ? kthread_create_on_node+0xc0/0xc0
 ret_from_fork+0x27/0x40

Allocated by task 1:
 save_stack_trace+0x1b/0x20
 save_stack+0x46/0xd0
 kasan_kmalloc+0xad/0xe0
 kasan_slab_alloc+0x12/0x20
 kmem_cache_alloc+0xe0/0x2f0
 getname_flags+0x43/0x220
 getname+0x12/0x20
 do_sys_open+0x14c/0x2b0
 SyS_open+0x1e/0x20
 do_syscall_64+0xea/0x260
 return_from_SYSCALL_64+0x0/0x7a

Freed by task 1:
 save_stack_trace+0x1b/0x20
 save_stack+0x46/0xd0
 kasan_slab_free+0x72/0xc0
 kmem_cache_free+0xa8/0x300
 putname+0x80/0x90
 do_sys_open+0x22f/0x2b0
 SyS_open+0x1e/0x20
 do_syscall_64+0xea/0x260
 return_from_SYSCALL_64+0x0/0x7a

The buggy address belongs to the object at ffff8804508aeac0\x0a which belongs to the cache names_cache of size 4096
The buggy address is located 2664 bytes inside of\x0a 4096-byte region [ffff8804508aeac0, ffff8804508afac0)
The buggy address belongs to the page:
page:ffffea0011422a00 count:1 mapcount:0 mapping:          (null) index:0x0
[CONT START]  compound_mapcount: 0
flags: 0x8000000000008100(slab|head)
raw: 8000000000008100 0000000000000000 0000000000000000 0000000100070007
raw: ffffea00113d6020 ffffea001136e220 ffff8804664f8040 0000000000000000
page dumped because: kasan: bad access detected

Memory state around the buggy address:
 ffff8804508af400: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
 ffff8804508af480: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
>ffff8804508af500: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
                                  ^
 ffff8804508af580: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
 ffff8804508af600: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
==================================================================

[toc] | [next] | [standalone]

#1700646

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2017-08-01 07:40 +0200
Message-ID<u9y4p-7Cw-1@gated-at.bofh.it>
In reply to#1700139
On Mon, Jul 31, 2017 at 8:43 AM, davej@codemonkey.org.uk
<davej@codemonkey.org.uk> wrote:
> Another NFSv4 KASAN splat, this time from rc3.
>
> BUG: KASAN: use-after-free in nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]

Ugh. It's really hard to tell what access that it - KASAN doesn't
actually give enough information. There's lots of 8-byte accesses
there in that function.

Any chance of getting the output from

   ./scripts/faddr2line vmlinux nfs4_exchange_id_done+0x3d7/0x8e0

or something? That would be extremely useful in general for
stacktraces, but it's doubly useful for KASAN because most *other*
stacktraces tend to have a very limited number of things that can warn
(ie there's one or two WARN_ON() calls in a function), but KASAN can
have tens or hundreds..

                       Linus


> Read of size 8 at addr ffff8804508af528 by task kworker/2:1/34
>
> CPU: 2 PID: 34 Comm: kworker/2:1 Not tainted 4.13.0-rc3-think+ #1
> Workqueue: rpciod rpc_async_schedule [sunrpc]
> Call Trace:
>  dump_stack+0x68/0xa1
>  print_address_description+0xd9/0x270
>  kasan_report+0x257/0x370
>  ? nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]
>  check_memory_region+0x13a/0x1a0
>  __asan_loadN+0xf/0x20
>  nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]
>  ? nfs4_exchange_id_release+0xb0/0xb0 [nfsv4]
>  rpc_exit_task+0x69/0x110 [sunrpc]
>  ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
>  ? rpc_destroy_wait_queue+0x20/0x20 [sunrpc]
>  __rpc_execute+0x1a0/0x840 [sunrpc]
>  ? rpc_wake_up_queued_task+0x50/0x50 [sunrpc]
>  ? __lock_is_held+0x9a/0x100
>  ? debug_lockdep_rcu_enabled.part.16+0x1a/0x30
>  rpc_async_schedule+0x12/0x20 [sunrpc]
>  process_one_work+0x4d5/0xa70
>  ? flush_delayed_work+0x70/0x70
>  ? lock_acquire+0xfc/0x220
>  worker_thread+0x88/0x630
>  ? pci_mmcfg_check_reserved+0xc0/0xc0
>  kthread+0x1a6/0x1f0
>  ? process_one_work+0xa70/0xa70
>  ? kthread_create_on_node+0xc0/0xc0
>  ret_from_fork+0x27/0x40
>
> Allocated by task 1:
>  save_stack_trace+0x1b/0x20
>  save_stack+0x46/0xd0
>  kasan_kmalloc+0xad/0xe0
>  kasan_slab_alloc+0x12/0x20
>  kmem_cache_alloc+0xe0/0x2f0
>  getname_flags+0x43/0x220
>  getname+0x12/0x20
>  do_sys_open+0x14c/0x2b0
>  SyS_open+0x1e/0x20
>  do_syscall_64+0xea/0x260
>  return_from_SYSCALL_64+0x0/0x7a
>
> Freed by task 1:
>  save_stack_trace+0x1b/0x20
>  save_stack+0x46/0xd0
>  kasan_slab_free+0x72/0xc0
>  kmem_cache_free+0xa8/0x300
>  putname+0x80/0x90
>  do_sys_open+0x22f/0x2b0
>  SyS_open+0x1e/0x20
>  do_syscall_64+0xea/0x260
>  return_from_SYSCALL_64+0x0/0x7a
>
> The buggy address belongs to the object at ffff8804508aeac0\x0a which belongs to the cache names_cache of size 4096
> The buggy address is located 2664 bytes inside of\x0a 4096-byte region [ffff8804508aeac0, ffff8804508afac0)
> The buggy address belongs to the page:
> page:ffffea0011422a00 count:1 mapcount:0 mapping:          (null) index:0x0
> [CONT START]  compound_mapcount: 0
> flags: 0x8000000000008100(slab|head)
> raw: 8000000000008100 0000000000000000 0000000000000000 0000000100070007
> raw: ffffea00113d6020 ffffea001136e220 ffff8804664f8040 0000000000000000
> page dumped because: kasan: bad access detected
>
> Memory state around the buggy address:
>  ffff8804508af400: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
>  ffff8804508af480: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
>>ffff8804508af500: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
>                                   ^
>  ffff8804508af580: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
>  ffff8804508af600: fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb fb
> ==================================================================
>

[toc] | [prev] | [next] | [standalone]

#1701183

From"davej@codemonkey.org.uk" <davej@codemonkey.org.uk>
Date2017-08-01 18:00 +0200
Message-ID<u9HKq-5Q8-29@gated-at.bofh.it>
In reply to#1700646
On Mon, Jul 31, 2017 at 10:35:45PM -0700, Linus Torvalds wrote:
 > On Mon, Jul 31, 2017 at 8:43 AM, davej@codemonkey.org.uk
 > <davej@codemonkey.org.uk> wrote:
 > > Another NFSv4 KASAN splat, this time from rc3.
 > >
 > > BUG: KASAN: use-after-free in nfs4_exchange_id_done+0x3d7/0x8e0 [nfsv4]
 > 
 > Ugh. It's really hard to tell what access that it - KASAN doesn't
 > actually give enough information. There's lots of 8-byte accesses
 > there in that function.
 > 
 > Any chance of getting the output from
 > 
 >    ./scripts/faddr2line vmlinux nfs4_exchange_id_done+0x3d7/0x8e0
 

Hm, that points to this..

7463                 /* Save the EXCHANGE_ID verifier session trunk tests */
7464                 memcpy(clp->cl_confirm.data, cdata->args.verifier->data,
7465                        sizeof(clp->cl_confirm.data));

	Dave

[toc] | [prev] | [next] | [standalone]

#1701265

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2017-08-01 19:30 +0200
Message-ID<u9J9x-6UE-23@gated-at.bofh.it>
In reply to#1701183

[Multipart message — attachments visible in raw view] — view raw

On Tue, Aug 1, 2017 at 8:51 AM, davej@codemonkey.org.uk
<davej@codemonkey.org.uk> wrote:
> On Mon, Jul 31, 2017 at 10:35:45PM -0700, Linus Torvalds wrote:
>  > Any chance of getting the output from
>  >
>  >    ./scripts/faddr2line vmlinux nfs4_exchange_id_done+0x3d7/0x8e0
>
>
> Hm, that points to this..
>
> 7463                 /* Save the EXCHANGE_ID verifier session trunk tests */
> 7464                 memcpy(clp->cl_confirm.data, cdata->args.verifier->data,
> 7465                        sizeof(clp->cl_confirm.data));

Ok, that certainly made no sense to me, because the KASAN report made
it look like a stale pathname access (allocated in getname, freed in
putname), but I think the issue is more fundamental than that.

That cdata->args.verifier seems to be entirely broken. AT least for
the "xprt == NULL" case, it does the following:

 - use the address of a local variable ("&verifier")

 - wait for the rpc completion using rpc_wait_for_completion_task().

That's unacceptably buggy crap. rpc_wait_for_completion_task() will
happily exit on a deadly signal even if the rpc hasn't been completed,
so now you'll have a stale pointer to a stack that has been freed.

So I think the 'pathname' part may actually be entirely a red herring,
and it's the underlying access itself that just picks up a random
pointer from a stack that now contains something different. And KASAN
didn't notice the stale stack access itself, because the stack slot is
still valid - it's just no longer the original 'verifier' allocation.

Or *something* like that.

None of this looks even remotely new, though - the code seems to go
back to 2009. Have you just changed what you're testing to trigger
these things?

I'm not even sure why it does that stupid stack allocation. It does a
*real* allocation just a few lines later:

        struct nfs41_exchange_id_data *calldata
        ...
        calldata = kzalloc(sizeof(*calldata), GFP_NOFS);

and the whole verifier structure could easily have been part of that
same allocation as far as I can tell.

And that really might seem to be the right thing to do.

TOTALLY UNTESTED PROBABLY COMPLETE CRAP patch attatched.

That patch compiles for me. It *might* even work. Or it might just be
the ramblings of a diseased mind.

Anna? Trond?

So caveat probatorem,

              Linus

[toc] | [prev] | [next] | [standalone]

#1701271

FromTrond Myklebust <trondmy@primarydata.com>
Date2017-08-01 19:40 +0200
Message-ID<u9Jjc-6XQ-3@gated-at.bofh.it>
In reply to#1701265
On Tue, 2017-08-01 at 10:20 -0700, Linus Torvalds wrote:
> On Tue, Aug 1, 2017 at 8:51 AM, davej@codemonkey.org.uk
> <davej@codemonkey.org.uk> wrote:
> > On Mon, Jul 31, 2017 at 10:35:45PM -0700, Linus Torvalds wrote:
> >  > Any chance of getting the output from
> >  >
> >  >    ./scripts/faddr2line vmlinux
> > nfs4_exchange_id_done+0x3d7/0x8e0
> > 
> > 
> > Hm, that points to this..
> > 
> > 7463                 /* Save the EXCHANGE_ID verifier session trunk
> > tests */
> > 7464                 memcpy(clp->cl_confirm.data, cdata-
> > >args.verifier->data,
> > 7465                        sizeof(clp->cl_confirm.data));
> 
> Ok, that certainly made no sense to me, because the KASAN report made
> it look like a stale pathname access (allocated in getname, freed in
> putname), but I think the issue is more fundamental than that.
> 
> That cdata->args.verifier seems to be entirely broken. AT least for
> the "xprt == NULL" case, it does the following:
> 
>  - use the address of a local variable ("&verifier")
> 
>  - wait for the rpc completion using rpc_wait_for_completion_task().
> 
> That's unacceptably buggy crap. rpc_wait_for_completion_task() will
> happily exit on a deadly signal even if the rpc hasn't been
> completed,
> so now you'll have a stale pointer to a stack that has been freed.
> 
> So I think the 'pathname' part may actually be entirely a red
> herring,
> and it's the underlying access itself that just picks up a random
> pointer from a stack that now contains something different. And KASAN
> didn't notice the stale stack access itself, because the stack slot
> is
> still valid - it's just no longer the original 'verifier' allocation.
> 
> Or *something* like that.
> 
> None of this looks even remotely new, though - the code seems to go
> back to 2009. Have you just changed what you're testing to trigger
> these things?
> 
> I'm not even sure why it does that stupid stack allocation. It does a
> *real* allocation just a few lines later:
> 
>         struct nfs41_exchange_id_data *calldata
>         ...
>         calldata = kzalloc(sizeof(*calldata), GFP_NOFS);
> 
> and the whole verifier structure could easily have been part of that
> same allocation as far as I can tell.
> 
> And that really might seem to be the right thing to do.
> 
> TOTALLY UNTESTED PROBABLY COMPLETE CRAP patch attatched.
> 
> That patch compiles for me. It *might* even work. Or it might just be
> the ramblings of a diseased mind.
> 
> Anna? Trond?
> 

I came to the same conclusion yesterday, and have a stable patch that
does something similar. I just got distracted with the other bugs that
were introduced by the exchangeid patch series in Linux-4.9 (including
what looks like a duplicate free issue in nfs4_test_session_trunk()).

I can pass a few of the more critical patches on to Anna for merging in
this cycle, then I've got some clean ups ready for the 4.14 merge
window.

Cheers
  Trond

-- 
Trond Myklebust
Linux NFS client maintainer, PrimaryData
trond.myklebust@primarydata.com

[toc] | [prev] | [next] | [standalone]

#1701282

From"davej@codemonkey.org.uk" <davej@codemonkey.org.uk>
Date2017-08-01 20:00 +0200
Message-ID<u9JCx-74V-9@gated-at.bofh.it>
In reply to#1701265
On Tue, Aug 01, 2017 at 10:20:31AM -0700, Linus Torvalds wrote:

 > So I think the 'pathname' part may actually be entirely a red herring,
 > and it's the underlying access itself that just picks up a random
 > pointer from a stack that now contains something different. And KASAN
 > didn't notice the stale stack access itself, because the stack slot is
 > still valid - it's just no longer the original 'verifier' allocation.
 > 
 > Or *something* like that.
 > 
 > None of this looks even remotely new, though - the code seems to go
 > back to 2009. Have you just changed what you're testing to trigger
 > these things?

No idea why it only just showed up, but it isn't 100% reproducable
either.  A month or so ago I did disable the V4 code on the server
completely (as I was using v3 everywhere else), so maybe I started hitting
a fallback path somewhere.  *shrug*

	Dave

[toc] | [prev] | [next] | [standalone]

#1701284

FromTrond Myklebust <trondmy@primarydata.com>
Date2017-08-01 20:00 +0200
Message-ID<u9JCy-74V-19@gated-at.bofh.it>
In reply to#1701282
On Tue, 2017-08-01 at 13:50 -0400, davej@codemonkey.org.uk wrote:
> On Tue, Aug 01, 2017 at 10:20:31AM -0700, Linus Torvalds wrote:
> 
>  > So I think the 'pathname' part may actually be entirely a red
> herring,
>  > and it's the underlying access itself that just picks up a random
>  > pointer from a stack that now contains something different. And
> KASAN
>  > didn't notice the stale stack access itself, because the stack
> slot is
>  > still valid - it's just no longer the original 'verifier'
> allocation.
>  > 
>  > Or *something* like that.
>  > 
>  > None of this looks even remotely new, though - the code seems to
> go
>  > back to 2009. Have you just changed what you're testing to trigger
>  > these things?
> 
> No idea why it only just showed up, but it isn't 100% reproducable
> either.  A month or so ago I did disable the V4 code on the server
> completely (as I was using v3 everywhere else), so maybe I started
> hitting
> a fallback path somewhere.  *shrug*
> 

I would only expect you too see it if you interrupt the wait on the
asynchronous EXCHANGE_ID call (which would allow the RPC call to
continue while the caller stack is trashed). Prior to commit
8d89bd70bc939, that code path was fully synchronous, so there was no
issue with interrupting the call.

-- 
Trond Myklebust
Linux NFS client maintainer, PrimaryData
trond.myklebust@primarydata.com

[toc] | [prev] | [next] | [standalone]

#1701294

FromLinus Torvalds <torvalds@linux-foundation.org>
Date2017-08-01 20:00 +0200
Message-ID<u9JCy-74V-37@gated-at.bofh.it>
In reply to#1701265
On Tue, Aug 1, 2017 at 10:20 AM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> So I think the 'pathname' part may actually be entirely a red herring,
> and it's the underlying access itself that just picks up a random
> pointer from a stack that now contains something different. And KASAN
> didn't notice the stale stack access itself, because the stack slot is
> still valid - it's just no longer the original 'verifier' allocation.
>
> Or *something* like that.

I think the "something like that" is actually just reading the
cdata->args.verifier->data pointer itself, and it *is* the stack
access - but the stack page has been free'd (because of the same fatal
signal that interrupted the rpc_wait_for_completion_task() call), and
then re-allocated (and free'd again) as a pathname page.

Maybe.

Regardless, my patch still looks conceptually correct, even if it
might have bugs due to total lack of testing.

                    Linus

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web