Lockdep warning

Lockdep warning

[Jonas Bonn]

Hi,

Here's a lockdep warning that I'm seeing on an MX28 with 3.13-rc4.  This 
seems to happen as soon as the network link comes up... including the 
'netdev' list here as the backtrace shows the FEC driver in the stacktrace.

Any advice on how to proceed to track this down appreciated...

/Jonas

[   37.140857] fec 800f0000.ethernet eth0: Freescale FEC PHY driver 
[Generic PHY] (mii_bus:phy_addr=800f0000.etherne:00, irq=-1)
[   37.148951] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   39.155538] libphy: 800f0000.etherne:00 - Link is Up - 100/Full
[   39.162273] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   41.167998]
[   41.169546] =================================
[   41.173925] [ INFO: inconsistent lock state ]
[   41.178308] 3.13.0-rc4-00018-g3b78c2f-dirty #8 Not tainted
[   41.183808] ---------------------------------
[   41.188182] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
[   41.194213] connmand/337 [HC0[0]:SC1[1]:HE1:SE0] takes:
[   41.199452]  (&(&sk->sk_dst_lock)->rlock){+.?...}, at: [<c03d8088>] 
__udp4_lib_rcv+0x7e0/0x8a8
[   41.208175] {SOFTIRQ-ON-W} state was registered at:
[   41.213071]   [<c0046cb8>] __lock_acquire+0x5d0/0x1a64
[   41.218274]   [<c0048694>] lock_acquire+0x9c/0x104
[   41.223115]   [<c046a690>] _raw_spin_lock+0x28/0x38
[   41.228052]   [<c042be50>] ip6_datagram_connect+0x258/0x43c
[   41.233669]   [<c03e0478>] inet_dgram_connect+0x58/0x84
[   41.238945]   [<c0376c7c>] SyS_connect+0x64/0x8c
[   41.243610]   [<c0009560>] ret_fast_syscall+0x0/0x44
[   41.248629] irq event stamp: 70302
[   41.252050] hardirqs last  enabled at (70302): [<c0057c98>] 
__getnstimeofday+0x15c/0x178
[   41.260193] hardirqs last disabled at (70301): [<c0057b64>] 
__getnstimeofday+0x28/0x178
[   41.268243] softirqs last  enabled at (70208): [<c001a158>] 
__do_softirq+0x198/0x2c4
[   41.276049] softirqs last disabled at (70217): [<c001a640>] 
irq_exit+0xa4/0xf8
[   41.283309]
[   41.283309] other info that might help us debug this:
[   41.289856]  Possible unsafe locking scenario:
[   41.289856]
[   41.295793]        CPU0
[   41.298250]        ----
[   41.300706]   lock(&(&sk->sk_dst_lock)->rlock);
[   41.305277]   <Interrupt>
[   41.307908]     lock(&(&sk->sk_dst_lock)->rlock);
[   41.312652]
[   41.312652]  *** DEADLOCK ***
[   41.312652]
[   41.318605] 2 locks held by connmand/337:
[   41.322628]  #0:  (rcu_read_lock){.+.+..}, at: [<c0386648>] 
__netif_receive_skb_core+0x34/0x5e0
[   41.331445]  #1:  (rcu_read_lock){.+.+..}, at: [<c03abf80>] 
ip_local_deliver+0x5c/0x30c
[   41.339559]
[   41.339559] stack backtrace:
[   41.343959] CPU: 0 PID: 337 Comm: connmand Not tainted 
3.13.0-rc4-00018-g3b78c2f-dirty #8
[   41.352208] [<c000d970>] (unwind_backtrace+0x0/0xf0) from 
[<c000bd84>] (show_stack+0x10/0x14)
[   41.360797] [<c000bd84>] (show_stack+0x10/0x14) from [<c0463cb4>] 
(print_usage_bug.part.27+0x218/0x280)
[   41.370251] [<c0463cb4>] (print_usage_bug.part.27+0x218/0x280) from 
[<c0046308>] (mark_lock+0x288/0x668)
[   41.379784] [<c0046308>] (mark_lock+0x288/0x668) from [<c0046c80>] 
(__lock_acquire+0x598/0x1a64)
[   41.388620] [<c0046c80>] (__lock_acquire+0x598/0x1a64) from 
[<c0048694>] (lock_acquire+0x9c/0x104)
[   41.397639] [<c0048694>] (lock_acquire+0x9c/0x104) from [<c046a690>] 
(_raw_spin_lock+0x28/0x38)
[   41.406390] [<c046a690>] (_raw_spin_lock+0x28/0x38) from [<c03d8088>] 
(__udp4_lib_rcv+0x7e0/0x8a8)
[   41.415399] [<c03d8088>] (__udp4_lib_rcv+0x7e0/0x8a8) from 
[<c03abfec>] (ip_local_deliver+0xc8/0x30c)
[   41.424667] [<c03abfec>] (ip_local_deliver+0xc8/0x30c) from 
[<c03ac58c>] (ip_rcv+0x35c/0x74c)
[   41.433247] [<c03ac58c>] (ip_rcv+0x35c/0x74c) from [<c03868ec>] 
(__netif_receive_skb_core+0x2d8/0x5e0)
[   41.442611] [<c03868ec>] (__netif_receive_skb_core+0x2d8/0x5e0) from 
[<c03894ac>] (napi_gro_receive+0x74/0xa0)
[   41.452675] [<c03894ac>] (napi_gro_receive+0x74/0xa0) from 
[<c02d5f50>] (fec_enet_rx_napi+0x304/0x704)
[   41.462037] [<c02d5f50>] (fec_enet_rx_napi+0x304/0x704) from 
[<c038918c>] (net_rx_action+0xc0/0x20c)
[   41.471235] [<c038918c>] (net_rx_action+0xc0/0x20c) from [<c001a0ac>] 
(__do_softirq+0xec/0x2c4)
[   41.479987] [<c001a0ac>] (__do_softirq+0xec/0x2c4) from [<c001a640>] 
(irq_exit+0xa4/0xf8)
[   41.488208] [<c001a640>] (irq_exit+0xa4/0xf8) from [<c0009e44>] 
(handle_IRQ+0x34/0x84)
[   41.496172] [<c0009e44>] (handle_IRQ+0x34/0x84) from [<c000c9c4>] 
(__irq_usr+0x44/0x60)

Re: Lockdep warning

[Borislav Petkov]

On Thu, Dec 19, 2013 at 02:36:40PM +0100, Jonas Bonn wrote:
> Hi,
> 
> Here's a lockdep warning that I'm seeing on an MX28 with 3.13-rc4.
> This seems to happen as soon as the network link comes up...
> including the 'netdev' list here as the backtrace shows the FEC
> driver in the stacktrace.
> 
> Any advice on how to proceed to track this down appreciated...

In such situations I'd always search the net first, to see whether this
has been fixed already. Hint: try searching for "lockdep __udp4_lib_rcv"

:-)

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: Lockdep warning

[Jonas Bonn]

On 12/19/2013 03:02 PM, Borislav Petkov wrote:
> On Thu, Dec 19, 2013 at 02:36:40PM +0100, Jonas Bonn wrote:
>
> In such situations I'd always search the net first, to see whether this
> has been fixed already. Hint: try searching for "lockdep __udp4_lib_rcv"

Ah... my bad.  Thanks!

Sorry for the noise.

/Jonas

Re: Lockdep warning

[Borislav Petkov]

On Thu, Dec 19, 2013 at 03:04:37PM +0100, Jonas Bonn wrote:
> Ah... my bad.  Thanks!
> 
> Sorry for the noise.

No worries, keep testing -rcs and reporting issues - it is appreciated!

:-)

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: lockdep warning

[Jiri Kosina]

On Fri, 22 Feb 2008, Anders Eriksson wrote:

> I found this is a newly booted 2.6.25-rc2's syslog.
> Feb 21 20:46:33 tippex BUG: rwlock wrong owner on CPU#0, runscript.sh/2633, d2c04084
> Feb 21 20:46:33 tippex Pid: 2633, comm: runscript.sh Not tainted 2.6.25-rc2 #3
> Feb 21 20:46:33 tippex [<c02342d0>] rwlock_bug+0x50/0x60
> Feb 21 20:46:33 tippex [<c0234356>] _raw_write_unlock+0x56/0x60
> Feb 21 20:46:33 tippex [<c040365d>] _write_unlock+0x1d/0x50
> Feb 21 20:46:33 tippex [<c03289be>] neigh_timer_handler+0x18e/0x2d0
> Feb 21 20:46:33 tippex [<c0125449>] run_timer_softirq+0x119/0x180
> Feb 21 20:46:33 tippex [<c013856d>] ? lock_release_holdtime+0x5d/0x80
> Feb 21 20:46:33 tippex [<c0328830>] ? neigh_timer_handler+0x0/0x2d0
> Feb 21 20:46:33 tippex [<c0121a64>] __do_softirq+0x54/0xb0
> Feb 21 20:46:33 tippex [<c0121af5>] do_softirq+0x35/0x40
> Feb 21 20:46:33 tippex [<c0121cb4>] irq_exit+0x44/0x50
> Feb 21 20:46:33 tippex [<c0105757>] do_IRQ+0x47/0x80
> Feb 21 20:46:33 tippex [<c01039c3>] common_interrupt+0x23/0x28
> Feb 21 20:46:33 tippex =======================

This needs to be CCed to netdev.

Any chance that

	git revert 69cc64d8d92

makes this report go away?

-- 
Jiri Kosina
SUSE Labs

Re: lockdep warning

[Anders Eriksson]

jkosina@suse.cz said:
> This needs to be CCed to netdev.
> Any chance that
> 	git revert 69cc64d8d92
> makes this report go away? 

I'll have to install a git repo to check, or maybe you can send me the diff to 
reverse vs. 2.6.25-rc2?

Re: lockdep warning

[Jiri Kosina]

On Fri, 22 Feb 2008, Anders Eriksson wrote:

> > This needs to be CCed to netdev.
> > Any chance that
> > 	git revert 69cc64d8d92
> > makes this report go away? 
> I'll have to install a git repo to check, or maybe you can send me the diff to 
> reverse vs. 2.6.25-rc2?

diff --git a/net/core/neighbour.c b/net/core/neighbour.c
index 7bb6a9a..a16cf1e 100644
--- a/net/core/neighbour.c
+++ b/net/core/neighbour.c
@@ -834,12 +834,18 @@ static void neigh_timer_handler(unsigned long arg)
 	}
 	if (neigh->nud_state & (NUD_INCOMPLETE | NUD_PROBE)) {
 		struct sk_buff *skb = skb_peek(&neigh->arp_queue);
-
+		/* keep skb alive even if arp_queue overflows */
+		if (skb)
+			skb_get(skb);
+		write_unlock(&neigh->lock);
 		neigh->ops->solicit(neigh, skb);
 		atomic_inc(&neigh->probes);
-	}
+		if (skb)
+			kfree_skb(skb);
+	} else {
 out:
-	write_unlock(&neigh->lock);
+		write_unlock(&neigh->lock);
+	}
 
 	if (notify)
 		neigh_update_notify(neigh);
diff --git a/net/ipv4/arp.c b/net/ipv4/arp.c
index c663fa5..8e17f65 100644
--- a/net/ipv4/arp.c
+++ b/net/ipv4/arp.c
@@ -368,6 +368,7 @@ static void arp_solicit(struct neighbour *neigh, struct sk_buff *skb)
 		if (!(neigh->nud_state&NUD_VALID))
 			printk(KERN_DEBUG "trying to ucast probe in NUD_INVALID\n");
 		dst_ha = neigh->ha;
+		read_lock_bh(&neigh->lock);
 	} else if ((probes -= neigh->parms->app_probes) < 0) {
 #ifdef CONFIG_ARPD
 		neigh_app_ns(neigh);
@@ -377,6 +378,8 @@ static void arp_solicit(struct neighbour *neigh, struct sk_buff *skb)
 
 	arp_send(ARPOP_REQUEST, ETH_P_ARP, target, dev, saddr,
 		 dst_ha, dev->dev_addr, NULL);
+	if (dst_ha)
+		read_unlock_bh(&neigh->lock);
 }
 
 static int arp_ignore(struct in_device *in_dev, __be32 sip, __be32 tip)

Re: lockdep warning

[Anders Eriksson]

jkosina@suse.cz said:
> > Any chance that
> > 	git revert 69cc64d8d92
> > makes this report go away?  

I've tested the patch and I no longer get that lock thing in my syslog.

/A

Re: lockdep warning

[Jiri Kosina]

On Fri, 22 Feb 2008, Anders Eriksson wrote:

> > > Any chance that
> > > 	git revert 69cc64d8d92
> > > makes this report go away?  
> I've tested the patch and I no longer get that lock thing in my syslog.

Thanks for verification.

Hmm, I don't immediately see how this patch could make neigh->lock owner 
to change between lock and unlock ... I have skimmed through the solicit 
methods, and they don't seem to be doing anything nasty to neigh ...

The scenario I was thinking about is that before 69cc64d8d92, if any of 
the _solicit methods could do anything bad to neigh struct, this warning 
wouldn't trigger, because the lock has been dropped before calling 
_solicit() and reacquired later, so no mismatch on ->current could happen, 
but now as long as the lock is held during _solicit() call, this would 
trigger on the next unlock.

But I am not able to see anything like that in the code. Dave, do you have 
any idea? (the thread started at http://lkml.org/lkml/2008/2/22/105).

-- 
Jiri Kosina
SUSE Labs