NULL pointer dereference in nfs_delegation_find_inode

NULL pointer dereference in nfs_delegation_find_inode

[Anders Blomdell]

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

We occasionally (about once every 2-4 weeks on 1 of a 100 machenes) get 

  BUG: unable to handle kernel NULL pointer dereference at 0000000000000548
  IP: [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]

the attached bug is from 4.1.8-100.fc21, but I have seen it on 4.1.5-100.fc21 as
well. Right now I have a realtime modified (xenomai.org) 3.8.13 system that exhibits
the problem more frequently, and that leads me to belive that the problem is
a data race problem, and by instrumenting fs/nfs/delegation.c (3.8.13) to:


  static struct inode *
  nfs_delegation_find_inode_server(struct nfs_server *server,
				 const struct nfs_fh *fhandle)
  {
	  struct nfs_delegation *delegation;
	  struct inode *res = NULL;

 	  printk(KERN_ERR "server = %p\n", server);
	  list_for_each_entry_rcu(delegation, &server->delegations, super_list) {
		  printk(KERN_ERR "delegation = %p\n", delegation);
		  printk(KERN_ERR "delegation->lock = %p\n", delegation->lock);
		  spin_lock(&delegation->lock);
		  printk(KERN_ERR "delegation->inode = %p\n", delegation->inode);
		  if (delegation->inode != NULL) {
			  printk(KERN_ERR "NFS_I(delegation->inode) = %p", NFS_I(delegation->inode));
			  printk(KERN_ERR "NFS_I(delegation->inode)->fh = %p", NFS_I(delegation->inode)->fh);
		  }
		  if (delegation->inode != NULL &&
		      nfs_compare_fh(fhandle, &NFS_I(delegation->inode)->fh) == 0) {
			  res = igrab(delegation->inode);
		  }
		  spin_unlock(&delegation->lock);
		  if (res != NULL)
			  break;
	  }
	  return res;
  }

the system dies with (delegation.c compiled with -O0):

  server = ffff8803dee58458
  delegation =           (null)
  BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
  IP: [<ffffffffa08924ae>] nfs_delegation_find_inode_server+0x80/0x1e0 [nfsv4]

Anybody thet can give me a hint how to write a program that gives rise to multiple 
delegations to further investigate this issue?

Regards

Anders Blomdell

-- 
Anders Blomdell                  Email: anders.blomdell@control.lth.se
Department of Automatic Control
Lund University                  Phone:    +46 46 222 4625
P.O. Box 118                     Fax:      +46 46 138118
SE-221 00 Lund, Sweden


[-- Attachment #2: nfs_delegation_find_inode.bug --]
[-- Type: text/plain, Size: 4146 bytes --]

[436427.069349] BUG: unable to handle kernel NULL pointer dereference at 0000000000000548
[436427.071788] IP: [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
[436427.074342] PGD 0 
[436427.076834] Oops: 0000 [#1] SMP 
[436427.079313] Modules linked in: btrfs xor raid6_pq ufs hfsplus hfs minix vfat msdos fat jfs xfs libcrc32c bnep bluetooth rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache fuse xt_CHECKSUM ipt_MASQUERADE nf_nat_masquerade_ipv4 tun ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw ip6table_filter ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw dummy snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic snd_hda_intel snd_hda_controller snd_hda_codec joydev snd_hda_core intel_rapl iosf_mbi snd_hwdep snd_seq snd_seq_device snd_pcm x86_pkg_temp_thermal coretemp kvm crct10dif_pclmul snd_timer crc32_pclmul snd iTCO_wdt eeepc_wmi iTCO_vendor_support asus_wmi sparse_keymap rfkill crc32c_intel mxm_wmi ghash_clmulni_intel soundcore shpchp lpc_ich mfd_core mei_me mei i2c_i801 tpm_infineon tpm_tis tpm wmi acpi_pad nfsd auth_rpcgss nfs_acl lockd grace binfmt_misc sunrpc i915 i2c_algo_bit drm_kms_helper drm r8169 serio_raw mii video
[436427.095071] CPU: 0 PID: 2579 Comm: nfsv4.0-svc Not tainted 4.1.8-100.fc21.x86_64 #1
[436427.098729] Hardware name: ASUS All Series/Z97-P, BIOS 2801 04/08/2015
[436427.102400] task: ffff8807ec6458e0 ti: ffff8807ddb40000 task.ti: ffff8807ddb40000
[436427.106102] RIP: 0010:[<ffffffffa0651744>]  [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
[436427.109891] RSP: 0018:ffff8807ddb43c38  EFLAGS: 00010282
[436427.113659] RAX: 0000000000000000 RBX: ffff8807e5567800 RCX: fffffffffffffff8
[436427.117462] RDX: ffff8807ddb43d20 RSI: ffff8807e556780a RDI: ffff8807f258c000
[436427.121255] RBP: ffff8807ddb43c98 R08: 0000000000000000 R09: 0000000000000000
[436427.125038] R10: 0000000000000001 R11: ffffea001c18f100 R12: 0000000000000001
[436427.128818] R13: 0000000000000004 R14: 0000000011270000 R15: 0000000000000000
[436427.132604] FS:  0000000000000000(0000) GS:ffff88081fa00000(0000) knlGS:0000000000000000
[436427.136415] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[436427.140221] CR2: 0000000000000548 CR3: 0000000001c0b000 CR4: 00000000001406f0
[436427.144055] Stack:
[436427.147873]  ffff8807f258c0c8 fffffffffffffff8 ffff8807e556780a ffff8807e5567808
[436427.151782]  0000000000000000 00000000d997ee51 ffff8807e5567800 ffff8807e5567800
[436427.155700]  0000000000000001 0000000000000004 0000000011270000 0000000000000000
[436427.159630] Call Trace:
[436427.163551]  [<ffffffffa0655150>] nfs4_callback_recall+0x40/0x190 [nfsv4]
[436427.167522]  [<ffffffffa0654742>] ? decode_recall_args+0x72/0xd0 [nfsv4]
[436427.171489]  [<ffffffffa065412f>] nfs4_callback_compound+0x43f/0x750 [nfsv4]
[436427.175493]  [<ffffffffa01ebfe4>] svc_process_common+0x604/0x6a0 [sunrpc]
[436427.179500]  [<ffffffffa0652c30>] ? nfs_callback_authenticate+0x50/0x50 [nfsv4]
[436427.183514]  [<ffffffffa01ec193>] svc_process+0x113/0x1b0 [sunrpc]
[436427.187499]  [<ffffffffa0652c30>] ? nfs_callback_authenticate+0x50/0x50 [nfsv4]
[436427.191492]  [<ffffffffa0652c7d>] nfs4_callback_svc+0x4d/0x60 [nfsv4]
[436427.195459]  [<ffffffff810c06c8>] kthread+0xd8/0xf0
[436427.199408]  [<ffffffff810c05f0>] ? kthread_create_on_node+0x1b0/0x1b0
[436427.203361]  [<ffffffff81798d22>] ret_from_fork+0x42/0x70
[436427.207246]  [<ffffffff810c05f0>] ? kthread_create_on_node+0x1b0/0x1b0
[436427.211066] Code: 89 45 c0 48 8b 45 c0 48 8d 48 f8 48 89 4d a8 48 8d 8f c8 00 00 00 48 39 c1 48 89 4d a0 0f 84 c6 00 00 00 0f 1f 40 00 48 8b 4d a8 <48> 8b 81 50 05 00 00 48 8d 99 50 05 00 00 48 89 45 c0 4c 8b 6d 
[436427.215295] RIP  [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
[436427.219382]  RSP <ffff8807ddb43c38>
[436427.223438] CR2: 0000000000000548
[436427.253263] ---[ end trace 86350a4ba0ca1ba3 ]---

Re: NULL pointer dereference in nfs_delegation_find_inode

[Jeff Layton]

On Fri, 23 Oct 2015 10:00:51 +0200
Anders Blomdell <anders.blomdell@control.lth.se> wrote:

> We occasionally (about once every 2-4 weeks on 1 of a 100 machenes) get 
> 
>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000548
>   IP: [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
> 
> the attached bug is from 4.1.8-100.fc21, but I have seen it on 4.1.5-100.fc21 as
> well. Right now I have a realtime modified (xenomai.org) 3.8.13 system that exhibits
> the problem more frequently, and that leads me to belive that the problem is
> a data race problem, and by instrumenting fs/nfs/delegation.c (3.8.13) to:
> 
> 
>   static struct inode *
>   nfs_delegation_find_inode_server(struct nfs_server *server,
> 				 const struct nfs_fh *fhandle)
>   {
> 	  struct nfs_delegation *delegation;
> 	  struct inode *res = NULL;
> 
>  	  printk(KERN_ERR "server = %p\n", server);
> 	  list_for_each_entry_rcu(delegation, &server->delegations, super_list) {
> 		  printk(KERN_ERR "delegation = %p\n", delegation);
> 		  printk(KERN_ERR "delegation->lock = %p\n", delegation->lock);
> 		  spin_lock(&delegation->lock);
> 		  printk(KERN_ERR "delegation->inode = %p\n", delegation->inode);
> 		  if (delegation->inode != NULL) {
> 			  printk(KERN_ERR "NFS_I(delegation->inode) = %p", NFS_I(delegation->inode));
> 			  printk(KERN_ERR "NFS_I(delegation->inode)->fh = %p", NFS_I(delegation->inode)->fh);
> 		  }
> 		  if (delegation->inode != NULL &&
> 		      nfs_compare_fh(fhandle, &NFS_I(delegation->inode)->fh) == 0) {
> 			  res = igrab(delegation->inode);
> 		  }
> 		  spin_unlock(&delegation->lock);
> 		  if (res != NULL)
> 			  break;
> 	  }
> 	  return res;
>   }
> 
> the system dies with (delegation.c compiled with -O0):
> 
>   server = ffff8803dee58458
>   delegation =           (null)
>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
>   IP: [<ffffffffa08924ae>] nfs_delegation_find_inode_server+0x80/0x1e0 [nfsv4]
> 
> Anybody thet can give me a hint how to write a program that gives rise to multiple 
> delegations to further investigate this issue?
> 
> Regards
> 
> Anders Blomdell
> 

Huh. That delegation pointer really never be NULL. I'm unclear on how
that could even happen in the context of a list_for_each_entry_rcu
loop. Oh, but super_list is the first struct member in nfs_delegation
so it probably means that server->delegations was NULL.

Maybe this is a use-after free of some sort or there's a memory
scribble involved? You might want to consider turning up some memory
debugging options while reproducing this.

-- 
Jeff Layton <jlayton@poochiereds.net>

Re: NULL pointer dereference in nfs_delegation_find_inode

[Anders Blomdell]

On 2015-10-23 13:28, Jeff Layton wrote:
> On Fri, 23 Oct 2015 10:00:51 +0200
> Anders Blomdell <anders.blomdell@control.lth.se> wrote:
> 
>> We occasionally (about once every 2-4 weeks on 1 of a 100 machenes) get 
>>
>>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000548
>>   IP: [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
>>
>> the attached bug is from 4.1.8-100.fc21, but I have seen it on 4.1.5-100.fc21 as
>> well. Right now I have a realtime modified (xenomai.org) 3.8.13 system that exhibits
>> the problem more frequently, and that leads me to belive that the problem is
>> a data race problem, and by instrumenting fs/nfs/delegation.c (3.8.13) to:
>>
>>
>>   static struct inode *
>>   nfs_delegation_find_inode_server(struct nfs_server *server,
>> 				 const struct nfs_fh *fhandle)
>>   {
>> 	  struct nfs_delegation *delegation;
>> 	  struct inode *res = NULL;
>>
>>  	  printk(KERN_ERR "server = %p\n", server);
>> 	  list_for_each_entry_rcu(delegation, &server->delegations, super_list) {
>> 		  printk(KERN_ERR "delegation = %p\n", delegation);
>> 		  printk(KERN_ERR "delegation->lock = %p\n", delegation->lock);
>> 		  spin_lock(&delegation->lock);
>> 		  printk(KERN_ERR "delegation->inode = %p\n", delegation->inode);
>> 		  if (delegation->inode != NULL) {
>> 			  printk(KERN_ERR "NFS_I(delegation->inode) = %p", NFS_I(delegation->inode));
>> 			  printk(KERN_ERR "NFS_I(delegation->inode)->fh = %p", NFS_I(delegation->inode)->fh);
>> 		  }
>> 		  if (delegation->inode != NULL &&
>> 		      nfs_compare_fh(fhandle, &NFS_I(delegation->inode)->fh) == 0) {
>> 			  res = igrab(delegation->inode);
>> 		  }
>> 		  spin_unlock(&delegation->lock);
>> 		  if (res != NULL)
>> 			  break;
>> 	  }
>> 	  return res;
>>   }
>>
>> the system dies with (delegation.c compiled with -O0):
>>
>>   server = ffff8803dee58458
>>   delegation =           (null)
>>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
>>   IP: [<ffffffffa08924ae>] nfs_delegation_find_inode_server+0x80/0x1e0 [nfsv4]
>>
>> Anybody thet can give me a hint how to write a program that gives rise to multiple 
>> delegations to further investigate this issue?
>>
>> Regards
>>
>> Anders Blomdell
>>
> 
> Huh. That delegation pointer really never be NULL. 
                                      ^should
> I'm unclear on how
> that could even happen in the context of a list_for_each_entry_rcu
> loop. Oh, but super_list is the first struct member in nfs_delegation
> so it probably means that server->delegations was NULL.
> 
> Maybe this is a use-after free of some sort or there's a memory
> scribble involved?
That is my guess, and the realtime patch used probably makes the window of opportunity
much larger (since the bug happens every few hours instead of every few years on average).


> You might want to consider turning up some memory
> debugging options while reproducing this.
Any hints on what options? Could/should they beturned on for the NFS module only

Any hints of what file operations to use to force delegations to happen?

Regards

Anders Blomdell
 


-- 
Anders Blomdell                  Email: anders.blomdell@control.lth.se
Department of Automatic Control
Lund University                  Phone:    +46 46 222 4625
P.O. Box 118                     Fax:      +46 46 138118
SE-221 00 Lund, Sweden

Re: NULL pointer dereference in nfs_delegation_find_inode

[Jeff Layton]

On Fri, 23 Oct 2015 14:28:58 +0200
Anders Blomdell <anders.blomdell@control.lth.se> wrote:

> On 2015-10-23 13:28, Jeff Layton wrote:
> > On Fri, 23 Oct 2015 10:00:51 +0200
> > Anders Blomdell <anders.blomdell@control.lth.se> wrote:
> > 
> >> We occasionally (about once every 2-4 weeks on 1 of a 100 machenes) get 
> >>
> >>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000548
> >>   IP: [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
> >>
> >> the attached bug is from 4.1.8-100.fc21, but I have seen it on 4.1.5-100.fc21 as
> >> well. Right now I have a realtime modified (xenomai.org) 3.8.13 system that exhibits
> >> the problem more frequently, and that leads me to belive that the problem is
> >> a data race problem, and by instrumenting fs/nfs/delegation.c (3.8.13) to:
> >>
> >>
> >>   static struct inode *
> >>   nfs_delegation_find_inode_server(struct nfs_server *server,
> >> 				 const struct nfs_fh *fhandle)
> >>   {
> >> 	  struct nfs_delegation *delegation;
> >> 	  struct inode *res = NULL;
> >>
> >>  	  printk(KERN_ERR "server = %p\n", server);
> >> 	  list_for_each_entry_rcu(delegation, &server->delegations, super_list) {
> >> 		  printk(KERN_ERR "delegation = %p\n", delegation);
> >> 		  printk(KERN_ERR "delegation->lock = %p\n", delegation->lock);
> >> 		  spin_lock(&delegation->lock);
> >> 		  printk(KERN_ERR "delegation->inode = %p\n", delegation->inode);
> >> 		  if (delegation->inode != NULL) {
> >> 			  printk(KERN_ERR "NFS_I(delegation->inode) = %p", NFS_I(delegation->inode));
> >> 			  printk(KERN_ERR "NFS_I(delegation->inode)->fh = %p", NFS_I(delegation->inode)->fh);
> >> 		  }
> >> 		  if (delegation->inode != NULL &&
> >> 		      nfs_compare_fh(fhandle, &NFS_I(delegation->inode)->fh) == 0) {
> >> 			  res = igrab(delegation->inode);
> >> 		  }
> >> 		  spin_unlock(&delegation->lock);
> >> 		  if (res != NULL)
> >> 			  break;
> >> 	  }
> >> 	  return res;
> >>   }
> >>
> >> the system dies with (delegation.c compiled with -O0):
> >>
> >>   server = ffff8803dee58458
> >>   delegation =           (null)
> >>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
> >>   IP: [<ffffffffa08924ae>] nfs_delegation_find_inode_server+0x80/0x1e0 [nfsv4]
> >>
> >> Anybody thet can give me a hint how to write a program that gives rise to multiple 
> >> delegations to further investigate this issue?
> >>
> >> Regards
> >>
> >> Anders Blomdell
> >>
> > 
> > Huh. That delegation pointer really never be NULL. 
>                                       ^should
> > I'm unclear on how
> > that could even happen in the context of a list_for_each_entry_rcu
> > loop. Oh, but super_list is the first struct member in nfs_delegation
> > so it probably means that server->delegations was NULL.
> > 
> > Maybe this is a use-after free of some sort or there's a memory
> > scribble involved?
> That is my guess, and the realtime patch used probably makes the window of opportunity
> much larger (since the bug happens every few hours instead of every few years on average).
> 
> 
> > You might want to consider turning up some memory
> > debugging options while reproducing this.
> Any hints on what options? Could/should they beturned on for the NFS module only
> 

If your kernel uses SLUB then you can poke around with the options
under /sys/kernel/slab. Figure out which cache that object belongs too
(it appears to be kmalloc'ed) and enable stuff like "poison" and
red_zone.

If you can get a vmcore then you could also open it up with the
debugger and see what at "server" object looks like. Has it been freed?
Does it belong to the right slabcache? etc...

> Any hints of what file operations to use to force delegations to happen?
> 

You can't really force it as it's 100% up to the server. They are
handed out at OPEN time. So any open-heavy workload should help
reproduce it.

-- 
Jeff Layton <jlayton@poochiereds.net>

Re: NULL pointer dereference in nfs_delegation_find_inode

[J. Bruce Fields]

On Fri, Oct 23, 2015 at 03:17:12PM -0400, Jeff Layton wrote:
> On Fri, 23 Oct 2015 14:28:58 +0200
> Anders Blomdell <anders.blomdell@control.lth.se> wrote:
> 
> > On 2015-10-23 13:28, Jeff Layton wrote:
> > > On Fri, 23 Oct 2015 10:00:51 +0200
> > > Anders Blomdell <anders.blomdell@control.lth.se> wrote:
> > > 
> > >> We occasionally (about once every 2-4 weeks on 1 of a 100 machenes) get 
> > >>
> > >>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000548
> > >>   IP: [<ffffffffa0651744>] nfs_delegation_find_inode+0x64/0x150 [nfsv4]
> > >>
> > >> the attached bug is from 4.1.8-100.fc21, but I have seen it on 4.1.5-100.fc21 as
> > >> well. Right now I have a realtime modified (xenomai.org) 3.8.13 system that exhibits
> > >> the problem more frequently, and that leads me to belive that the problem is
> > >> a data race problem, and by instrumenting fs/nfs/delegation.c (3.8.13) to:
> > >>
> > >>
> > >>   static struct inode *
> > >>   nfs_delegation_find_inode_server(struct nfs_server *server,
> > >> 				 const struct nfs_fh *fhandle)
> > >>   {
> > >> 	  struct nfs_delegation *delegation;
> > >> 	  struct inode *res = NULL;
> > >>
> > >>  	  printk(KERN_ERR "server = %p\n", server);
> > >> 	  list_for_each_entry_rcu(delegation, &server->delegations, super_list) {
> > >> 		  printk(KERN_ERR "delegation = %p\n", delegation);
> > >> 		  printk(KERN_ERR "delegation->lock = %p\n", delegation->lock);
> > >> 		  spin_lock(&delegation->lock);
> > >> 		  printk(KERN_ERR "delegation->inode = %p\n", delegation->inode);
> > >> 		  if (delegation->inode != NULL) {
> > >> 			  printk(KERN_ERR "NFS_I(delegation->inode) = %p", NFS_I(delegation->inode));
> > >> 			  printk(KERN_ERR "NFS_I(delegation->inode)->fh = %p", NFS_I(delegation->inode)->fh);
> > >> 		  }
> > >> 		  if (delegation->inode != NULL &&
> > >> 		      nfs_compare_fh(fhandle, &NFS_I(delegation->inode)->fh) == 0) {
> > >> 			  res = igrab(delegation->inode);
> > >> 		  }
> > >> 		  spin_unlock(&delegation->lock);
> > >> 		  if (res != NULL)
> > >> 			  break;
> > >> 	  }
> > >> 	  return res;
> > >>   }
> > >>
> > >> the system dies with (delegation.c compiled with -O0):
> > >>
> > >>   server = ffff8803dee58458
> > >>   delegation =           (null)
> > >>   BUG: unable to handle kernel NULL pointer dereference at 0000000000000050
> > >>   IP: [<ffffffffa08924ae>] nfs_delegation_find_inode_server+0x80/0x1e0 [nfsv4]
> > >>
> > >> Anybody thet can give me a hint how to write a program that gives rise to multiple 
> > >> delegations to further investigate this issue?
> > >>
> > >> Regards
> > >>
> > >> Anders Blomdell
> > >>
> > > 
> > > Huh. That delegation pointer really never be NULL. 
> >                                       ^should
> > > I'm unclear on how
> > > that could even happen in the context of a list_for_each_entry_rcu
> > > loop. Oh, but super_list is the first struct member in nfs_delegation
> > > so it probably means that server->delegations was NULL.
> > > 
> > > Maybe this is a use-after free of some sort or there's a memory
> > > scribble involved?
> > That is my guess, and the realtime patch used probably makes the window of opportunity
> > much larger (since the bug happens every few hours instead of every few years on average).
> > 
> > 
> > > You might want to consider turning up some memory
> > > debugging options while reproducing this.
> > Any hints on what options? Could/should they beturned on for the NFS module only
> > 
> 
> If your kernel uses SLUB then you can poke around with the options
> under /sys/kernel/slab. Figure out which cache that object belongs too
> (it appears to be kmalloc'ed) and enable stuff like "poison" and
> red_zone.
> 
> If you can get a vmcore then you could also open it up with the
> debugger and see what at "server" object looks like. Has it been freed?
> Does it belong to the right slabcache? etc...
> 
> > Any hints of what file operations to use to force delegations to happen?
> > 
> 
> You can't really force it as it's 100% up to the server. They are
> handed out at OPEN time. So any open-heavy workload should help
> reproduce it.

Also if it's a Linux server it will only give out delegations on
read-only opens.  (But I didn't notice if you said what the server was.)

--b.