RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

Test case is complicated...creating 100 virtual wifi devices, running DHCP,
setting up routing rules, and most likely some ipv6 stuff as well.  It's all
automated by our tool, so hard to say exactly which command or set of commands
is causing this.  I read the ipv6 portion of the patch several times and do
not see a problem.

This kernel has no additional patches or out-of-tree modules loaded.

Here are two samples of output from the serial console.  The problem reproduces
100% of the time on this machine.


BUG: sleeping function called from invalid context at /home/greearb/git/linux-3..
0.dev.y/kernel/mutex.c:271
in_atomic(): 0, irqs_disabled(): 0, pid: 8897, name: ip
1 lock held by ip/8897:
  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffffa01f2190>] rcu_read_lock+0x0/0x35 [[
ipv6]
Pid: 8897, comm: ip Tainted: G         C  3.0.20+ #10
Call Trace:
  [<ffffffffa01f24fd>] ? rcu_read_unlock+0x23/0x23 [ipv6]
  [<ffffffff8103e46d>] __might_sleep+0x111/0x115
  [<ffffffff81447c04>] mutex_lock_nested+0x20/0x3b
  [<ffffffff8139bb59>] rtnl_lock+0x12/0x14
  [<ffffffff8139bc67>] rtnetlink_rcv_msg+0xe4/0x1ec
  [<ffffffff8139bb83>] ? rtnetlink_rcv+0x28/0x28
  [<ffffffff813ae578>] netlink_rcv_skb+0x3e/0x8f
  [<ffffffff8139bb7c>] rtnetlink_rcv+0x21/0x28
  [<ffffffff813ae353>] netlink_unicast+0xe9/0x152
  [<ffffffff813aeb1a>] netlink_sendmsg+0x240/0x25e
  [<ffffffff8137fadc>] ? rcu_read_unlock+0x21/0x23
  [<ffffffff8137aab1>] __sock_sendmsg_nosec+0x58/0x61
  [<ffffffff8137c0e0>] __sock_sendmsg+0x3d/0x48
  [<ffffffff8137c952>] sock_sendmsg+0xa3/0xbc
  [<ffffffff8137c3b0>] ? move_addr_to_user+0x71/0x8e
  [<ffffffff810fbebd>] ? fget_light+0x35/0xac
  [<ffffffff8137c9d3>] ? sockfd_lookup_light+0x1b/0x53
  [<ffffffff8137cf16>] sys_sendto+0xfa/0x11f
  [<ffffffff810fbd9a>] ? fcheck_files+0xb7/0xee
  [<ffffffff810fbebd>] ? fget_light+0x35/0xac
  [<ffffffff810cfedf>] ? remove_vma+0x7a/0x82
  [<ffffffff81095f21>] ? audit_syscall_entry+0x119/0x145
  [<ffffffff8144df12>] system_call_fastpath+0x16/0x1b

================================================
[ BUG: lock held when returning to user space! ]
------------------------------------------------
ip/8897 is leaving the kernel with locks still held!
1 lock held by ip/8897:
  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffffa01f2190>] rcu_read_lock+0x0/0x35 [[
ipv6]



BUG: sleeping function called from invalid context at /home/greearb/git/linux-3.0.dev.y/mm/memory.c:3904
in_atomic(): 0, irqs_disabled(): 0, pid: 4953, name: ip
1 lock held by ip/4953:
  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffffa0154190>] rcu_read_lock+0x0/0x35 [ipv6]
Pid: 4953, comm: ip Tainted: G         C  3.0.20+ #10
Call Trace:
  [<ffffffff8103e46d>] __might_sleep+0x111/0x115
  [<ffffffff810c977b>] might_fault+0x2f/0x9e
  [<ffffffff81386032>] ? copy_from_user+0x2a/0x2c
  [<ffffffff810c979a>] ? might_fault+0x4e/0x9e
  [<ffffffff8137c360>] move_addr_to_user+0x21/0x8e
  [<ffffffff8137c54c>] __sys_recvmsg+0x17f/0x21e
  [<ffffffff810fbebd>] ? fget_light+0x35/0xac
  [<ffffffff8137c9d3>] ? sockfd_lookup_light+0x1b/0x53
  [<ffffffff810fbd9a>] ? fcheck_files+0xb7/0xee
  [<ffffffff810fbebd>] ? fget_light+0x35/0xac
  [<ffffffff810cfedf>] ? remove_vma+0x7a/0x82
  [<ffffffff8137ccf0>] sys_recvmsg+0x3d/0x5b
eth1: no IPv6 routers present
  [<ffffffff8144df12>] system_call_fastpath+0x16/0x1b

================================================
[ BUG: lock held when returning to user space! ]
------------------------------------------------
ip/4953 is leaving the kernel with locks still held!
1 lock held by ip/4953:
  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffffa0154190>] rcu_read_lock+0x0/0x35 [ipv6]
ADDRCONF(NETDEV_UP): sta49: link is not ready



[greearb@fs3 linux-3.0.dev.y]$ git bisect bad
8a533666d1591cf4ea596c6bd710e2fe682cb56a is the first bad commit
commit 8a533666d1591cf4ea596c6bd710e2fe682cb56a
Author: Eric Dumazet <eric.dumazet@gmail.com>
Date:   Thu Feb 9 16:13:19 2012 -0500

     net: fix NULL dereferences in check_peer_redir()

     [ Upstream commit d3aaeb38c40e5a6c08dd31a1b64da65c4352be36, along
       with dependent backports of commits:
          69cce1d1404968f78b177a0314f5822d5afdbbfb
          9de79c127cccecb11ae6a21ab1499e87aa222880
          218fa90f072e4aeff9003d57e390857f4f35513e
          580da35a31f91a594f3090b7a2c39b85cb051a12
          f7e57044eeb1841847c24aa06766c8290c202583
          e049f28883126c689cf95859480d9ee4ab23b7fa ]

     Gergely Kalman reported crashes in check_peer_redir().

     It appears commit f39925dbde778 (ipv4: Cache learned redirect
     information in inetpeer.) added a race, leading to possible NULL ptr
     dereference.

     Since we can now change dst neighbour, we should make sure a reader can
     safely use a neighbour.

     Add RCU protection to dst neighbour, and make sure check_peer_redir()
     can be called safely by different cpus in parallel.

     As neighbours are already freed after one RCU grace period, this patch
     should not add typical RCU penalty (cache cold effects)

     Many thanks to Gergely for providing a pretty report pointing to the
     bug.

     Reported-by: Gergely Kalman <synapse@hippy.csoma.elte.hu>
     Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>
     Signed-off-by: David S. Miller <davem@davemloft.net>
     Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>


Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[David Miller]

Looks like all of those strange undiagnosable reported Dave Jones
has been feeding us.  Something in one part of the kernel leaves
a lock held, and this shows up as a warning elsewhere.

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

On 03/26/2012 02:49 PM, David Miller wrote:
>
> Looks like all of those strange undiagnosable reported Dave Jones
> has been feeding us.  Something in one part of the kernel leaves
> a lock held, and this shows up as a warning elsewhere.

Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.

And, the bisect clearly points at this commit.

I'm (re)reading the patch top to bottom to see if something
jumps out...and will be happy to liberally sprinkle debug
code if anyone has any suggestions.

Thanks,
Ben

> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html


-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

On 03/26/2012 02:53 PM, Ben Greear wrote:
> On 03/26/2012 02:49 PM, David Miller wrote:
>>
>> Looks like all of those strange undiagnosable reported Dave Jones
>> has been feeding us. Something in one part of the kernel leaves
>> a lock held, and this shows up as a warning elsewhere.
>
> Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.

I added a patch to convert rcu_read_lock/unlock to macros so
that I could automatically grab the call site (_THIS_IP_)
and pass it into the lockdep framework instead of the (useless)
_THIS_IP_ in the old rcu_read_lock method which at best seems to
only indicate which module the issue relates to...

Here's it's output:

BUG: sleeping function called from invalid context at /home/greearb/git/linux-3.0.dev.y/mm/memory.c:3904
in_atomic(): 0, irqs_disabled(): 0, pid: 4975, name: ip
1 lock held by ip/4975:
  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffffa032081a>] inet6_dump_fib+0x6c/0x233 [ipv6]
Pid: 4975, comm: ip Tainted: G         C  3.0.20+ #11
Call Trace:
  [<ffffffff8103e515>] __might_sleep+0x111/0x115
  [<ffffffff810c9e9f>] might_fault+0x2f/0x9e
  [<ffffffff81387332>] ? copy_from_user+0x2a/0x2c
  [<ffffffff810c9ebe>] ? might_fault+0x4e/0x9e
  [<ffffffff8137d5c0>] move_addr_to_user+0x21/0x8e
  [<ffffffff8137d7ac>] __sys_recvmsg+0x17f/0x21e
  [<ffffffff81063850>] ? up_read+0x1e/0x36
  [<ffffffff810fc727>] ? fcheck_files+0xb7/0xee
  [<ffffffff810fc85c>] ? fget_light+0x3b/0xbc
  [<ffffffff8137df50>] sys_recvmsg+0x3d/0x5b
  [<ffffffff8144fcd2>] system_call_fastpath+0x16/0x1b

================================================
[ BUG: lock held when returning to user space! ]
------------------------------------------------
ip/4975 is leaving the kernel with locks still held!
1 lock held by ip/4975:
  #0:  (rcu_read_lock){.+.+..}, at: [<ffffffffa032081a>] inet6_dump_fib+0x6c/0x233 [ipv6]


(gdb) l *(inet6_dump_fib+0x6c)
0x1181a is in inet6_dump_fib (/home/greearb/git/linux-3.0.dev.y/net/ipv6/ip6_fib.c:395).
390		}
391	
392		arg.skb = skb;
393		arg.cb = cb;
394		arg.net = net;
395		w->args = &arg;
396	
397		rcu_read_lock();
398		for (h = s_h; h < FIB6_TABLE_HASHSZ; h++, s_e = 0) {
399			e = 0;
(gdb)


That said, I don't see any issues with the inet6_dump_fib
method, so maybe my debug attempt is not valid..or lockdep debugging
has issues of some sort.

Off to do more poking around.

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[David Miller]

From: Ben Greear <greearb@candelatech.com>
Date: Mon, 26 Mar 2012 16:06:48 -0700

> That said, I don't see any issues with the inet6_dump_fib
> method, so maybe my debug attempt is not valid..or lockdep debugging
> has issues of some sort.

This is exactly where Eric and myself hit a dead-end on Dave
Jones's reports.

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Eric Dumazet]

On Mon, 2012-03-26 at 16:06 -0700, Ben Greear wrote:
> On 03/26/2012 02:53 PM, Ben Greear wrote:
> > On 03/26/2012 02:49 PM, David Miller wrote:
> >>
> >> Looks like all of those strange undiagnosable reported Dave Jones
> >> has been feeding us. Something in one part of the kernel leaves
> >> a lock held, and this shows up as a warning elsewhere.
> >
> > Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.
> 
> I added a patch to convert rcu_read_lock/unlock to macros so
> that I could automatically grab the call site (_THIS_IP_)
> and pass it into the lockdep framework instead of the (useless)
> _THIS_IP_ in the old rcu_read_lock method which at best seems to
> only indicate which module the issue relates to...

Hi Ben

Is this problem also appears with current tree ?
(This could be a problem with the backport, as it was full of
dependencies)

Also, if you use a patch to better track rcu_read_lock()/unlock(), you
could add new macros as well to track that a particular unlock() matches
one given lock(). (maybe returning the rcu_preempt_depth at
rcu_read_lock() time , but maybe a more absolute ref would be better)

So we could have a warning if an unlock() doesnt match the lock()

inet6_dump_fib () was already a suspect but we could not find why.

diff --git a/net/ipv6/ip6_fib.c b/net/ipv6/ip6_fib.c
index 5b27fbc..d1719e3 100644
--- a/net/ipv6/ip6_fib.c
+++ b/net/ipv6/ip6_fib.c
@@ -362,6 +362,7 @@ static int inet6_dump_fib(struct sk_buff *skb, struct netlink_callback *cb)
 	struct hlist_node *node;
 	struct hlist_head *head;
 	int res = 0;
+	int depth;
 
 	s_h = cb->args[0];
 	s_e = cb->args[1];
@@ -390,7 +391,7 @@ static int inet6_dump_fib(struct sk_buff *skb, struct netlink_callback *cb)
 	arg.net = net;
 	w->args = &arg;
 
-	rcu_read_lock();
+	depth = rcu_read_lock_return();
 	for (h = s_h; h < FIB6_TABLE_HASHSZ; h++, s_e = 0) {
 		e = 0;
 		head = &net->ipv6.fib_table_hash[h];
@@ -405,7 +406,7 @@ next:
 		}
 	}
 out:
-	rcu_read_unlock();
+	rcu_read_unlock_check(depth);
 	cb->args[1] = e;
 	cb->args[0] = h;
 

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

On 03/26/2012 04:39 PM, Eric Dumazet wrote:
> On Mon, 2012-03-26 at 16:06 -0700, Ben Greear wrote:
>> On 03/26/2012 02:53 PM, Ben Greear wrote:
>>> On 03/26/2012 02:49 PM, David Miller wrote:
>>>>
>>>> Looks like all of those strange undiagnosable reported Dave Jones
>>>> has been feeding us. Something in one part of the kernel leaves
>>>> a lock held, and this shows up as a warning elsewhere.
>>>
>>> Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.
>>
>> I added a patch to convert rcu_read_lock/unlock to macros so
>> that I could automatically grab the call site (_THIS_IP_)
>> and pass it into the lockdep framework instead of the (useless)
>> _THIS_IP_ in the old rcu_read_lock method which at best seems to
>> only indicate which module the issue relates to...
>
> Hi Ben
>
> Is this problem also appears with current tree ?
> (This could be a problem with the backport, as it was full of
> dependencies)

I don't think so..but I will double check in a bit.

> Also, if you use a patch to better track rcu_read_lock()/unlock(), you
> could add new macros as well to track that a particular unlock() matches
> one given lock(). (maybe returning the rcu_preempt_depth at
> rcu_read_lock() time , but maybe a more absolute ref would be better)
>
> So we could have a warning if an unlock() doesnt match the lock()
>
> inet6_dump_fib () was already a suspect but we could not find why.

The 3.0.21 kernel doesn't appear to have a rcu_read_lock_return(),
so I can't use your patch below.

Thanks,
Ben



-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

On 03/26/2012 04:46 PM, Ben Greear wrote:
> On 03/26/2012 04:39 PM, Eric Dumazet wrote:

>> Is this problem also appears with current tree ?
>> (This could be a problem with the backport, as it was full of
>> dependencies)
>
> I don't think so..but I will double check in a bit.

3.3.0 (plus a bunch of may non-related patches) appears to
work just fine.

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Eric Dumazet]

On Mon, 2012-03-26 at 16:46 -0700, Ben Greear wrote:

> The 3.0.21 kernel doesn't appear to have a rcu_read_lock_return(),
> so I can't use your patch below.

This patch was only to show the point (I also CCed Paul, he might have
some time to think about it, after he clears the inline stuff with
Linus)

As I said, I was referreing to you adding stuff in rcu. ;)

Unfortunately I wont have time in the near future to do so myself.

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Paul E. McKenney]

On Tue, Mar 27, 2012 at 02:07:14AM +0200, Eric Dumazet wrote:
> On Mon, 2012-03-26 at 16:46 -0700, Ben Greear wrote:
> 
> > The 3.0.21 kernel doesn't appear to have a rcu_read_lock_return(),
> > so I can't use your patch below.
> 
> This patch was only to show the point (I also CCed Paul, he might have
> some time to think about it, after he clears the inline stuff with
> Linus)

There is an rcu_preempt_depth() that returns rcu_read_lock() nesting
level for CONFIG_PREEMPT_RCU=y on the one hand and returns zero
for CONFIG_PREEMPT_RCU=n on the other.  So if you can reproduce
with CONFIG_PREEMPT_RCU=y, you can substitute rcu_preempt_depth()
rcu_read_lock_return() in Eric's earlier patch.

							Thanx, Paul

> As I said, I was referreing to you adding stuff in rcu. ;)
> 
> Unfortunately I wont have time in the near future to do so myself.
> 
> 
> 

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

On 03/26/2012 10:11 PM, Paul E. McKenney wrote:
> On Tue, Mar 27, 2012 at 02:07:14AM +0200, Eric Dumazet wrote:
>> On Mon, 2012-03-26 at 16:46 -0700, Ben Greear wrote:
>>
>>> The 3.0.21 kernel doesn't appear to have a rcu_read_lock_return(),
>>> so I can't use your patch below.
>>
>> This patch was only to show the point (I also CCed Paul, he might have
>> some time to think about it, after he clears the inline stuff with
>> Linus)
>
> There is an rcu_preempt_depth() that returns rcu_read_lock() nesting
> level for CONFIG_PREEMPT_RCU=y on the one hand and returns zero
> for CONFIG_PREEMPT_RCU=n on the other.  So if you can reproduce
> with CONFIG_PREEMPT_RCU=y, you can substitute rcu_preempt_depth()
> rcu_read_lock_return() in Eric's earlier patch.

I'll try looking at that tomorrow.  I tried adding some code to check for
recursive calls to the fib-dump, and didn't see it ever hit, though
the bug continued to happen readily.

I just #if 0 the part between rcu-read-lock and read-unlock, and
the problem went away..but of course you can't dump ipv6
routes then...

The actual logic to dump the fib is quite complex, full of
opaque types and other stuff ripe for bugs.  But, I don't see
how it could cause the rcu splats in such a repeatable manner.

The bug is always reported as being in the same place, so if
there is any other debugging code you can think of to help
shed light on this, I'll be happy to add it and give it a try.
For instance, is there a way to dump (print) all current holders of
the rcu_read_lock?  I could call that before/during/after in that
method and maybe get a clue.

Thanks,
Ben

>
> 							Thanx, Paul
>
>> As I said, I was referreing to you adding stuff in rcu. ;)
>>
>> Unfortunately I wont have time in the near future to do so myself.
>>
>>
>>


-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Ben Greear]

On 03/26/2012 04:39 PM, Eric Dumazet wrote:
> On Mon, 2012-03-26 at 16:06 -0700, Ben Greear wrote:
>> On 03/26/2012 02:53 PM, Ben Greear wrote:
>>> On 03/26/2012 02:49 PM, David Miller wrote:
>>>>
>>>> Looks like all of those strange undiagnosable reported Dave Jones
>>>> has been feeding us. Something in one part of the kernel leaves
>>>> a lock held, and this shows up as a warning elsewhere.
>>>
>>> Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.
>>
>> I added a patch to convert rcu_read_lock/unlock to macros so
>> that I could automatically grab the call site (_THIS_IP_)
>> and pass it into the lockdep framework instead of the (useless)
>> _THIS_IP_ in the old rcu_read_lock method which at best seems to
>> only indicate which module the issue relates to...
>
> Hi Ben
>
> Is this problem also appears with current tree ?
> (This could be a problem with the backport, as it was full of
> dependencies)
>
> Also, if you use a patch to better track rcu_read_lock()/unlock(), you
> could add new macros as well to track that a particular unlock() matches
> one given lock(). (maybe returning the rcu_preempt_depth at
> rcu_read_lock() time , but maybe a more absolute ref would be better)
>
> So we could have a warning if an unlock() doesnt match the lock()
>
> inet6_dump_fib () was already a suspect but we could not find why.


Ok, I tried the patch below, and got the result farther down.  Is this
what you were thinking of?  (The lockdep warning about rcu lock still
held happened immediately after this..so it appears the depth mis-match
does represent this problem...


[greearb@fs3 linux-3.0.dev.y]$ git diff
diff --git a/net/ipv6/ip6_fib.c b/net/ipv6/ip6_fib.c
index 0f9b37a..ae3c7c9 100644
--- a/net/ipv6/ip6_fib.c
+++ b/net/ipv6/ip6_fib.c
@@ -366,6 +366,7 @@ static int inet6_dump_fib(struct sk_buff *skb, struct netlink_callback *cb)
         struct hlist_node *node;
         struct hlist_head *head;
         int res = 0;
+       int depth = current->lockdep_depth;

         s_h = cb->args[0];
         s_e = cb->args[1];
@@ -410,6 +411,8 @@ next:
         }
  out:
         rcu_read_unlock();
+       WARN(depth != current->lockdep_depth, "depth: %i  lockdep-depth: %i\n",
+            depth, current->lockdep_depth);
         cb->args[1] = e;
         cb->args[0] = h;



------------[ cut here ]------------
WARNING: at /home/greearb/git/linux-3.0.dev.y/net/ipv6/ip6_fib.c:415 inet6_dump_fib+0x25c/0x292 [ipv6]()
Hardware name: To be filled by O.E.M.
depth: 1  lockdep-depth: 2
Modules linked in: 8021q garp stp llc fuse macvlan pktgen coretemp hwmon sunrpc ipv6 uinput arc4 ath9k snd_hda_codec_realtek mac80211 snd_hda_intel 
snd_hda_codec snd_hwdep snd_seq ath9k_common ath9k_hw snd_seq_device snd_pcm ath snd_timer e1000e cfg80211 snd mei(C) ppdev microcode i2c_i801 iTCO_wdt 
soundcore serio_raw pcspkr snd_page_alloc iTCO_vendor_support parport_pc parport i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
Pid: 6563, comm: ip Tainted: G         C  3.0.25+ #16
Call Trace:
  [<ffffffff81046866>] warn_slowpath_common+0x80/0x98
  [<ffffffff81046912>] warn_slowpath_fmt+0x41/0x43
  [<ffffffffa0251a3a>] inet6_dump_fib+0x25c/0x292 [ipv6]
  [<ffffffff813af450>] netlink_dump+0x5b/0x19b
  [<ffffffff81385da2>] ? consume_skb+0x28/0x2a
  [<ffffffff813af7bf>] netlink_recvmsg+0x1c7/0x2f8
  [<ffffffff8137c6cf>] __sock_recvmsg_nosec+0x65/0x6e
  [<ffffffff8137dde0>] __sock_recvmsg+0x49/0x54
  [<ffffffff8137e349>] sock_recvmsg+0xa6/0xbf
  [<ffffffff81072bf8>] ? lock_release_non_nested+0x9d/0x227
  [<ffffffff810ca002>] ? might_fault+0x4e/0x9e
  [<ffffffff810ca04b>] ? might_fault+0x97/0x9e
  [<ffffffff81387cae>] ? copy_from_user+0x2a/0x2c
  [<ffffffff810ca002>] ? might_fault+0x4e/0x9e
  [<ffffffff81388080>] ? verify_iovec+0x4f/0xa3
  [<ffffffff8137e0c4>] __sys_recvmsg+0x147/0x21e
  [<ffffffff81063868>] ? up_read+0x1e/0x36
  [<ffffffff810fc9fb>] ? fcheck_files+0xb7/0xee
  [<ffffffff810fcb30>] ? fget_light+0x3b/0xbc
  [<ffffffff8137e8a0>] sys_recvmsg+0x3d/0x5b
  [<ffffffff81450e92>] system_call_fastpath+0x16/0x1b
---[ end trace 5232c09c4fb31d15 ]---



-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Paul E. McKenney]

On Mon, Mar 26, 2012 at 10:30:52PM -0700, Ben Greear wrote:
> On 03/26/2012 10:11 PM, Paul E. McKenney wrote:
> >On Tue, Mar 27, 2012 at 02:07:14AM +0200, Eric Dumazet wrote:
> >>On Mon, 2012-03-26 at 16:46 -0700, Ben Greear wrote:
> >>
> >>>The 3.0.21 kernel doesn't appear to have a rcu_read_lock_return(),
> >>>so I can't use your patch below.
> >>
> >>This patch was only to show the point (I also CCed Paul, he might have
> >>some time to think about it, after he clears the inline stuff with
> >>Linus)
> >
> >There is an rcu_preempt_depth() that returns rcu_read_lock() nesting
> >level for CONFIG_PREEMPT_RCU=y on the one hand and returns zero
> >for CONFIG_PREEMPT_RCU=n on the other.  So if you can reproduce
> >with CONFIG_PREEMPT_RCU=y, you can substitute rcu_preempt_depth()
> >rcu_read_lock_return() in Eric's earlier patch.
> 
> I'll try looking at that tomorrow.  I tried adding some code to check for
> recursive calls to the fib-dump, and didn't see it ever hit, though
> the bug continued to happen readily.
> 
> I just #if 0 the part between rcu-read-lock and read-unlock, and
> the problem went away..but of course you can't dump ipv6
> routes then...
> 
> The actual logic to dump the fib is quite complex, full of
> opaque types and other stuff ripe for bugs.  But, I don't see
> how it could cause the rcu splats in such a repeatable manner.
> 
> The bug is always reported as being in the same place, so if
> there is any other debugging code you can think of to help
> shed light on this, I'll be happy to add it and give it a try.
> For instance, is there a way to dump (print) all current holders of
> the rcu_read_lock?  I could call that before/during/after in that
> method and maybe get a clue.

I would guess that CONFIG_PROVE_RCU's use of lockdep would permit
listing all tasks holding rcu_read_lock(), as lockdep does maintain
that state in that case.

							Thanx, Paul

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Eric Dumazet]

On Tue, 2012-03-27 at 09:47 -0700, Ben Greear wrote:
> On 03/26/2012 04:39 PM, Eric Dumazet wrote:
> > On Mon, 2012-03-26 at 16:06 -0700, Ben Greear wrote:
> >> On 03/26/2012 02:53 PM, Ben Greear wrote:
> >>> On 03/26/2012 02:49 PM, David Miller wrote:
> >>>>
> >>>> Looks like all of those strange undiagnosable reported Dave Jones
> >>>> has been feeding us. Something in one part of the kernel leaves
> >>>> a lock held, and this shows up as a warning elsewhere.
> >>>
> >>> Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.
> >>
> >> I added a patch to convert rcu_read_lock/unlock to macros so
> >> that I could automatically grab the call site (_THIS_IP_)
> >> and pass it into the lockdep framework instead of the (useless)
> >> _THIS_IP_ in the old rcu_read_lock method which at best seems to
> >> only indicate which module the issue relates to...
> >
> > Hi Ben
> >
> > Is this problem also appears with current tree ?
> > (This could be a problem with the backport, as it was full of
> > dependencies)
> >
> > Also, if you use a patch to better track rcu_read_lock()/unlock(), you
> > could add new macros as well to track that a particular unlock() matches
> > one given lock(). (maybe returning the rcu_preempt_depth at
> > rcu_read_lock() time , but maybe a more absolute ref would be better)
> >
> > So we could have a warning if an unlock() doesnt match the lock()
> >
> > inet6_dump_fib () was already a suspect but we could not find why.
> 
> 
> Ok, I tried the patch below, and got the result farther down.  Is this
> what you were thinking of?  (The lockdep warning about rcu lock still
> held happened immediately after this..so it appears the depth mis-match
> does represent this problem...
> 
> 
> [greearb@fs3 linux-3.0.dev.y]$ git diff
> diff --git a/net/ipv6/ip6_fib.c b/net/ipv6/ip6_fib.c
> index 0f9b37a..ae3c7c9 100644
> --- a/net/ipv6/ip6_fib.c
> +++ b/net/ipv6/ip6_fib.c
> @@ -366,6 +366,7 @@ static int inet6_dump_fib(struct sk_buff *skb, struct netlink_callback *cb)
>          struct hlist_node *node;
>          struct hlist_head *head;
>          int res = 0;
> +       int depth = current->lockdep_depth;
> 
>          s_h = cb->args[0];
>          s_e = cb->args[1];
> @@ -410,6 +411,8 @@ next:
>          }
>   out:
>          rcu_read_unlock();
> +       WARN(depth != current->lockdep_depth, "depth: %i  lockdep-depth: %i\n",
> +            depth, current->lockdep_depth);
>          cb->args[1] = e;
>          cb->args[0] = h;
> 
> 
> 
> ------------[ cut here ]------------
> WARNING: at /home/greearb/git/linux-3.0.dev.y/net/ipv6/ip6_fib.c:415 inet6_dump_fib+0x25c/0x292 [ipv6]()
> Hardware name: To be filled by O.E.M.
> depth: 1  lockdep-depth: 2
> Modules linked in: 8021q garp stp llc fuse macvlan pktgen coretemp hwmon sunrpc ipv6 uinput arc4 ath9k snd_hda_codec_realtek mac80211 snd_hda_intel 
> snd_hda_codec snd_hwdep snd_seq ath9k_common ath9k_hw snd_seq_device snd_pcm ath snd_timer e1000e cfg80211 snd mei(C) ppdev microcode i2c_i801 iTCO_wdt 
> soundcore serio_raw pcspkr snd_page_alloc iTCO_vendor_support parport_pc parport i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
> Pid: 6563, comm: ip Tainted: G         C  3.0.25+ #16
> Call Trace:
>   [<ffffffff81046866>] warn_slowpath_common+0x80/0x98
>   [<ffffffff81046912>] warn_slowpath_fmt+0x41/0x43
>   [<ffffffffa0251a3a>] inet6_dump_fib+0x25c/0x292 [ipv6]
>   [<ffffffff813af450>] netlink_dump+0x5b/0x19b
>   [<ffffffff81385da2>] ? consume_skb+0x28/0x2a
>   [<ffffffff813af7bf>] netlink_recvmsg+0x1c7/0x2f8
>   [<ffffffff8137c6cf>] __sock_recvmsg_nosec+0x65/0x6e
>   [<ffffffff8137dde0>] __sock_recvmsg+0x49/0x54
>   [<ffffffff8137e349>] sock_recvmsg+0xa6/0xbf
>   [<ffffffff81072bf8>] ? lock_release_non_nested+0x9d/0x227
>   [<ffffffff810ca002>] ? might_fault+0x4e/0x9e
>   [<ffffffff810ca04b>] ? might_fault+0x97/0x9e
>   [<ffffffff81387cae>] ? copy_from_user+0x2a/0x2c
>   [<ffffffff810ca002>] ? might_fault+0x4e/0x9e
>   [<ffffffff81388080>] ? verify_iovec+0x4f/0xa3
>   [<ffffffff8137e0c4>] __sys_recvmsg+0x147/0x21e
>   [<ffffffff81063868>] ? up_read+0x1e/0x36
>   [<ffffffff810fc9fb>] ? fcheck_files+0xb7/0xee
>   [<ffffffff810fcb30>] ? fget_light+0x3b/0xbc
>   [<ffffffff8137e8a0>] sys_recvmsg+0x3d/0x5b
>   [<ffffffff81450e92>] system_call_fastpath+0x16/0x1b
> ---[ end trace 5232c09c4fb31d15 ]---
> 
> 
> 


Now you could trace all rcu_read_lock()/rcu_read_unlock() done in this
context.

adding a current->rcu_trace_enabled flag, that you set/unset only in
inet6_dump_fib()

Re: RCU lock bug in 3.0.21 (bisected to: 682cb56a, fix NULL dereferences in check_peer_redir)

[Eric Dumazet]

On Tue, 2012-03-27 at 09:47 -0700, Ben Greear wrote:
> On 03/26/2012 04:39 PM, Eric Dumazet wrote:
> > On Mon, 2012-03-26 at 16:06 -0700, Ben Greear wrote:
> >> On 03/26/2012 02:53 PM, Ben Greear wrote:
> >>> On 03/26/2012 02:49 PM, David Miller wrote:
> >>>>
> >>>> Looks like all of those strange undiagnosable reported Dave Jones
> >>>> has been feeding us. Something in one part of the kernel leaves
> >>>> a lock held, and this shows up as a warning elsewhere.
> >>>
> >>> Every (initial) bug printout fingers ipv6 and the 'ip' tool on my system.
> >>
> >> I added a patch to convert rcu_read_lock/unlock to macros so
> >> that I could automatically grab the call site (_THIS_IP_)
> >> and pass it into the lockdep framework instead of the (useless)
> >> _THIS_IP_ in the old rcu_read_lock method which at best seems to
> >> only indicate which module the issue relates to...
> >
> > Hi Ben
> >
> > Is this problem also appears with current tree ?
> > (This could be a problem with the backport, as it was full of
> > dependencies)
> >
> > Also, if you use a patch to better track rcu_read_lock()/unlock(), you
> > could add new macros as well to track that a particular unlock() matches
> > one given lock(). (maybe returning the rcu_preempt_depth at
> > rcu_read_lock() time , but maybe a more absolute ref would be better)
> >
> > So we could have a warning if an unlock() doesnt match the lock()
> >
> > inet6_dump_fib () was already a suspect but we could not find why.
> 
> 
> Ok, I tried the patch below, and got the result farther down.  Is this
> what you were thinking of?  (The lockdep warning about rcu lock still
> held happened immediately after this..so it appears the depth mis-match
> does represent this problem...
> 
> 
> [greearb@fs3 linux-3.0.dev.y]$ git diff
> diff --git a/net/ipv6/ip6_fib.c b/net/ipv6/ip6_fib.c
> index 0f9b37a..ae3c7c9 100644
> --- a/net/ipv6/ip6_fib.c
> +++ b/net/ipv6/ip6_fib.c
> @@ -366,6 +366,7 @@ static int inet6_dump_fib(struct sk_buff *skb, struct netlink_callback *cb)
>          struct hlist_node *node;
>          struct hlist_head *head;
>          int res = 0;
> +       int depth = current->lockdep_depth;
> 
>          s_h = cb->args[0];
>          s_e = cb->args[1];
> @@ -410,6 +411,8 @@ next:
>          }
>   out:
>          rcu_read_unlock();
> +       WARN(depth != current->lockdep_depth, "depth: %i  lockdep-depth: %i\n",
> +            depth, current->lockdep_depth);
>          cb->args[1] = e;
>          cb->args[0] = h;
> 
> 
> 
> ------------[ cut here ]------------
> WARNING: at /home/greearb/git/linux-3.0.dev.y/net/ipv6/ip6_fib.c:415 inet6_dump_fib+0x25c/0x292 [ipv6]()
> Hardware name: To be filled by O.E.M.
> depth: 1  lockdep-depth: 2
> Modules linked in: 8021q garp stp llc fuse macvlan pktgen coretemp hwmon sunrpc ipv6 uinput arc4 ath9k snd_hda_codec_realtek mac80211 snd_hda_intel 
> snd_hda_codec snd_hwdep snd_seq ath9k_common ath9k_hw snd_seq_device snd_pcm ath snd_timer e1000e cfg80211 snd mei(C) ppdev microcode i2c_i801 iTCO_wdt 
> soundcore serio_raw pcspkr snd_page_alloc iTCO_vendor_support parport_pc parport i915 drm_kms_helper drm i2c_algo_bit i2c_core video [last unloaded: scsi_wait_scan]
> Pid: 6563, comm: ip Tainted: G         C  3.0.25+ #16
> Call Trace:
>   [<ffffffff81046866>] warn_slowpath_common+0x80/0x98
>   [<ffffffff81046912>] warn_slowpath_fmt+0x41/0x43
>   [<ffffffffa0251a3a>] inet6_dump_fib+0x25c/0x292 [ipv6]
>   [<ffffffff813af450>] netlink_dump+0x5b/0x19b
>   [<ffffffff81385da2>] ? consume_skb+0x28/0x2a
>   [<ffffffff813af7bf>] netlink_recvmsg+0x1c7/0x2f8
>   [<ffffffff8137c6cf>] __sock_recvmsg_nosec+0x65/0x6e
>   [<ffffffff8137dde0>] __sock_recvmsg+0x49/0x54
>   [<ffffffff8137e349>] sock_recvmsg+0xa6/0xbf
>   [<ffffffff81072bf8>] ? lock_release_non_nested+0x9d/0x227
>   [<ffffffff810ca002>] ? might_fault+0x4e/0x9e
>   [<ffffffff810ca04b>] ? might_fault+0x97/0x9e
>   [<ffffffff81387cae>] ? copy_from_user+0x2a/0x2c
>   [<ffffffff810ca002>] ? might_fault+0x4e/0x9e
>   [<ffffffff81388080>] ? verify_iovec+0x4f/0xa3
>   [<ffffffff8137e0c4>] __sys_recvmsg+0x147/0x21e
>   [<ffffffff81063868>] ? up_read+0x1e/0x36
>   [<ffffffff810fc9fb>] ? fcheck_files+0xb7/0xee
>   [<ffffffff810fcb30>] ? fget_light+0x3b/0xbc
>   [<ffffffff8137e8a0>] sys_recvmsg+0x3d/0x5b
>   [<ffffffff81450e92>] system_call_fastpath+0x16/0x1b
> ---[ end trace 5232c09c4fb31d15 ]---
> 
> 
> 

I found the bug in rt6_fill_node()

will send a patch in a couple of minutes

[PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[Eric Dumazet]

Commit f2c31e32b378 (net: fix NULL dereferences in check_peer_redir() )
added a regression in rt6_fill_node(), leading to rcu_read_lock()
imbalance.

Thats because NLA_PUT() can make a jump to nla_put_failure label.

Fix this by using nla_put()

Many thanks to Ben Greear for his help

Reported-by: Ben Greear <greearb@candelatech.com>
Reported-by: Dave Jones <davej@redhat.com>
Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>
---
 net/ipv6/route.c |    8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/net/ipv6/route.c b/net/ipv6/route.c
index 24c456e..496b627 100644
--- a/net/ipv6/route.c
+++ b/net/ipv6/route.c
@@ -2474,8 +2474,12 @@ static int rt6_fill_node(struct net *net,
 
 	rcu_read_lock();
 	n = dst_get_neighbour_noref(&rt->dst);
-	if (n)
-		NLA_PUT(skb, RTA_GATEWAY, 16, &n->primary_key);
+	if (n) {
+		if (nla_put(skb, RTA_GATEWAY, 16, &n->primary_key) < 0) {
+			rcu_read_unlock();
+			goto nla_put_failure;
+		}
+	}
 	rcu_read_unlock();
 
 	if (rt->dst.dev)

Re: [PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[Ben Greear]

On 03/27/2012 12:53 PM, Eric Dumazet wrote:
> Commit f2c31e32b378 (net: fix NULL dereferences in check_peer_redir() )
> added a regression in rt6_fill_node(), leading to rcu_read_lock()
> imbalance.
>
> Thats because NLA_PUT() can make a jump to nla_put_failure label.

Ohhh, how truly awful!  That NLA_PUT with hidden jump seems like
bugs just waiting to happen!

Maybe at least someone clever could make some static analysis tool to
catch that....

I'm back-porting and will test shortly.

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: [PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[Ben Greear]

On 03/27/2012 12:53 PM, Eric Dumazet wrote:
> Commit f2c31e32b378 (net: fix NULL dereferences in check_peer_redir() )
> added a regression in rt6_fill_node(), leading to rcu_read_lock()
> imbalance.
>
> Thats because NLA_PUT() can make a jump to nla_put_failure label.
>
> Fix this by using nla_put()
>
> Many thanks to Ben Greear for his help
>
> Reported-by: Ben Greear<greearb@candelatech.com>
> Reported-by: Dave Jones<davej@redhat.com>
> Signed-off-by: Eric Dumazet<eric.dumazet@gmail.com>

This does indeed fix the problem for me (tested in the 3.0.25 kernel).
So, please feel free to add:

Tested-by: Ben Greear <greearb@candelatech.com>

Thanks,
Ben

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: [PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[Greg KH]

On Tue, Mar 27, 2012 at 01:17:09PM -0700, Ben Greear wrote:
> On 03/27/2012 12:53 PM, Eric Dumazet wrote:
> >Commit f2c31e32b378 (net: fix NULL dereferences in check_peer_redir() )
> >added a regression in rt6_fill_node(), leading to rcu_read_lock()
> >imbalance.
> >
> >Thats because NLA_PUT() can make a jump to nla_put_failure label.
> >
> >Fix this by using nla_put()
> >
> >Many thanks to Ben Greear for his help
> >
> >Reported-by: Ben Greear<greearb@candelatech.com>
> >Reported-by: Dave Jones<davej@redhat.com>
> >Signed-off-by: Eric Dumazet<eric.dumazet@gmail.com>
> 
> This does indeed fix the problem for me (tested in the 3.0.25 kernel).
> So, please feel free to add:
> 
> Tested-by: Ben Greear <greearb@candelatech.com>

Very nice job Eric, thanks for tracking this down.

greg k-h

Re: [PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[David Miller]

From: Eric Dumazet <eric.dumazet@gmail.com>
Date: Tue, 27 Mar 2012 21:53:52 +0200

> Commit f2c31e32b378 (net: fix NULL dereferences in check_peer_redir() )
> added a regression in rt6_fill_node(), leading to rcu_read_lock()
> imbalance.
> 
> Thats because NLA_PUT() can make a jump to nla_put_failure label.
> 
> Fix this by using nla_put()
> 
> Many thanks to Ben Greear for his help
> 
> Reported-by: Ben Greear <greearb@candelatech.com>
> Reported-by: Dave Jones <davej@redhat.com>
> Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>

Great work everyone.

I'll apply this and queue it up for stable soon.

In other news, I think the days of hidden gotos from the NLA macros
should be over.  I'll work in net-next to redo this so that the
gotos must be explicitly coded and therefore be visible when people
audit these routines.

Thanks!

Re: [PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[John Fastabend]

On 3/27/2012 3:22 PM, David Miller wrote:
> From: Eric Dumazet <eric.dumazet@gmail.com>
> Date: Tue, 27 Mar 2012 21:53:52 +0200
> 
>> Commit f2c31e32b378 (net: fix NULL dereferences in check_peer_redir() )
>> added a regression in rt6_fill_node(), leading to rcu_read_lock()
>> imbalance.
>>
>> Thats because NLA_PUT() can make a jump to nla_put_failure label.
>>
>> Fix this by using nla_put()
>>
>> Many thanks to Ben Greear for his help
>>
>> Reported-by: Ben Greear <greearb@candelatech.com>
>> Reported-by: Dave Jones <davej@redhat.com>
>> Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>
> 
> Great work everyone.
> 
> I'll apply this and queue it up for stable soon.
> 
> In other news, I think the days of hidden gotos from the NLA macros
> should be over.  I'll work in net-next to redo this so that the
> gotos must be explicitly coded and therefore be visible when people
> audit these routines.
> 
> Thanks!
> --

I can clean up the ./net/dcb/ code if it will save you some time?

.John

Re: [PATCH] net: fix a potential rcu_read_lock() imbalance in rt6_fill_node()

[David Miller]

From: John Fastabend <john.r.fastabend@intel.com>
Date: Tue, 27 Mar 2012 17:54:02 -0700

> I can clean up the ./net/dcb/ code if it will save you some time?

Thanks for offering John, but I can take care of this all myself.