Bug 185043 - Kernel panic: Sleeping thread (tid , pid ) owns a non-sleepable lock from netinet/in_multi.c
Summary: Kernel panic: Sleeping thread (tid , pid ) owns a non-sleepable lock from net...
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: Unspecified
Hardware: Any Any
: Normal Affects Only Me
Assignee: George V. Neville-Neil
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-12-20 18:50 UTC by Michael Bentkofsky
Modified: 2017-01-05 21:57 UTC (History)
1 user (show)

See Also:


Attachments
in_multi_patch (2.32 KB, application/octet-stream)
2014-01-06 13:23 UTC, Michael Bentkofsky
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Bentkofsky 2013-12-20 18:50:04 UTC
Running ospfd from Quagga and restarting the network can trigger a kernel panic with the following stack trace:

root@omg022-std1:~ # Sleeping thread (tid 100188, pid 2047) owns a non-sleepable lock
KDB: stack backtrace of thread 100188:
#0 0xffffffff8064a4d6 at mi_switch+0x186
#1 0xffffffff8067f18c at sleepq_catch_signals+0x31c
#2 0xffffffff8067f9a9 at sleepq_timedwait_sig+0x19
#3 0xffffffff805fcdec at _cv_timedwait_sig+0x13c
#4 0xffffffff806850e8 at seltdwait+0x98
#5 0xffffffff806870df at kern_select+0x6ef
#6 0xffffffff8068737d at select+0x5d
#7 0xffffffff809ca3c4 at amd64_syscall+0x1f4
#8 0xffffffff809b253c at Xfast_syscall+0xfc
panic: sleeping thread
cpuid = 11
KDB: stack backtrace:
#0 0xffffffff806756d6 at kdb_backtrace+0x66
#1 0xffffffff80641d9e at panic+0x1ce
#2 0xffffffff806826bb at propagate_priority+0x1cb
#3 0xffffffff806833ff at turnstile_wait+0x1bf
#4 0xffffffff806322dd at _mtx_lock_sleep+0xbd
#5 0xffffffff80743ff1 at igmp_fasttimo+0x881
#6 0xffffffff8069df8b at pffasttimo+0x2b
#7 0xffffffff80655a63 at softclock+0x343
#8 0xffffffff806195a4 at intr_event_execute_handlers+0x104
#9 0xffffffff8061ac35 at ithread_loop+0x95
#10 0xffffffff806167bf at fork_exit+0x11f
#11 0xffffffff809b278e at fork_trampoline+0xe

The pid 2047 is ospfd from quagga-0.99.22. With ospfd running and configured, it uses multicast to listen for OSPF hello packets. Restarting the network with this command triggers the kernel panic:

# /etc/rc.d/netif restart && /etc/rc.d/routing restart
Catching the panic in ddb shows this bit of detail about the locks:

db> show allchains
chain 1:
thread 100015 (pid 12, swi4: clock) blocked on lock 0xffffffff80e4eca0 (sleep mutex) "in_multi_mtx"
thread 100233 (pid 2047, ospfd) inhibited

Looking at the places where this lock is acquired, we see several suspicious error paths that can leave the lock acquired in netinet/in_mcast.c. Here is an example from CURRENT:

static int
inp_block_unblock_source(struct inpcb *inp, struct sockopt *sopt)
{

	/*
	 * Begin state merge transaction at IGMP layer.
	 */
	IN_MULTI_LOCK();

	CTR1(KTR_IGMPV3, "%s: merge inm state", __func__);
	error = inm_merge(inm, imf);
	if (error) {
		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
		goto out_imf_rollback;
	}

	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
	error = igmp_change_state(inm);
	if (error)
		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);

	IN_MULTI_UNLOCK();

out_imf_rollback:
	if (error)
		imf_rollback(imf);
	else
		imf_commit(imf);

	imf_reap(imf);

}

Thus when there is an error in inm_merge() or igmp_change_state(), this lock remains acquired. There are other similar code segments such as  inp_join_group(), inp_set_source_filters() and inp_leave_group().

The panic was produced in FreeBSD-8.4, although I have also verified that the case happens with both stable/10  at r259575 and head at the same revision. I have tested a patch that ensures IN_MULTI_UNLOCK() is called after any of these error conditions and added KTR output to the particular path that had triggered this panic.

With even this patch in place, we have further found a subsequent race condition that so far weve only reproduced when compiling with KTR, INVARIANTS, and DDB flags, although I suspect the race condition can still occur. Although I dont have a patch to fix that race condition, I am interested in hearing from others how we should handle this case.

The race condition can happen when the userspace application adds a subscription to a multicast address while at the same time it is being removed. The steps to cause the race condition are exactly the same as cited at the beginning of this PR (running quagga ospfd and doing /etc/rc.d/netif restart), however it doesnt seem to actually trigger without INVARIANTS and DDB in our test environment.

The race condition happens in two threads  as seen with the KTR output below, although we have added a little more detail in our version to help debug this case:

509 (0xffffff00473ff490:cpu1): in_getmulti: join 224.0.0.6 on 0xffffff0031a93000(eth0.100))
510 (0xffffff00473ff490:cpu1): in_getmulti: join 224.0.0.6 family 2 len 16 on 0xffffff0031a93000(eth0.100))
520 (0xffffff00473ff490:cpu1): ether_resolvemulti: family 2 len 16 on 0xffffff0031a93000(eth0.100))
521 (0xffffff00473ff490:cpu1): ether_resolvemulti: join 224.0.0.6 family 2 len 16 on 0xffffff0031a93000(eth0.100))
523 (0xffffff00473ff490:cpu1): if_addmulti: ifma allocate (0xffffff00473d6780)

In this thread, ifma allocate is whats happening when [in sys/netinet/in_mcast.c] inp_join_group () will add a new address calling in_join_group_locked(), calling  in_getmulti() and add the address. 

At the same time, the interface is being removed in this path:

537 (0xffffff00474a1920:cpu9): mld_ifdetach: called for ifp 0xffffff0031a93000(eth0.100)
545 (0xffffff00474a1920:cpu9): if_purgemaddrs: will free ifma (0xffffff00473d6780)
565 (0xffffff00474a1920:cpu9): if_freemulti: free ifma (0xffffff00473d6780)

Here the interface ifp is removed via [in sys/if/if.c] if_pur gemaddrs() which will if_delmulti_locked() and then call if_freemulti() which triggers this KASSERT because a new ifma is being added, as above:

	KASSERT(ifma->ifma_protospec == NULL,
	    ("if_freemulti: protospec not NULL"));


Interestingly, this comment seems to hint at this being a known issue: 

/*
 * Detach an interface, removing it from the list of "active" interfaces.
 * If vmove flag is set on entry to if_detach_internal(), perform only a
 * limited subset of cleanup tasks, given that we are moving an ifnet from
 * one vnet to another, where it must be fully operational.
 *
 * XXXRW: There are some significant questions about event ordering, and
 * how to prevent things from starting to use the interface during detach.
 */

For this particular race condition, we continue to think about a fix, but would appreciate input from others as well.

Fix: 

See attached patch.
How-To-Repeat: See description.
Comment 1 dfilter service freebsd_committer 2014-01-16 22:15:01 UTC
Author: gnn
Date: Thu Jan 16 22:14:54 2014
New Revision: 260796
URL: http://svnweb.freebsd.org/changeset/base/260796

Log:
  Fix various places where we don't properly release a lock
  
  PR:		185043
  Submitted by:	Michael Bentkofsky
  MFC after:	2 weeks

Modified:
  head/sys/netinet/in_mcast.c

Modified: head/sys/netinet/in_mcast.c
==============================================================================
--- head/sys/netinet/in_mcast.c	Thu Jan 16 21:56:05 2014	(r260795)
+++ head/sys/netinet/in_mcast.c	Thu Jan 16 22:14:54 2014	(r260796)
@@ -1496,7 +1496,7 @@ inp_block_unblock_source(struct inpcb *i
 	error = inm_merge(inm, imf);
 	if (error) {
 		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
-		goto out_imf_rollback;
+		goto out_in_multi_locked;
 	}
 
 	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -1504,6 +1504,8 @@ inp_block_unblock_source(struct inpcb *i
 	if (error)
 		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
 out_imf_rollback:
@@ -2172,8 +2174,12 @@ inp_join_group(struct inpcb *inp, struct
 	if (is_new) {
 		error = in_joingroup_locked(ifp, &gsa->sin.sin_addr, imf,
 		    &inm);
-		if (error)
+		if (error) {
+                        CTR1(KTR_IGMPV3, "%s: in_joingroup_locked failed", 
+                            __func__);
+                        IN_MULTI_UNLOCK();
 			goto out_imo_free;
+                }
 		imo->imo_membership[idx] = inm;
 	} else {
 		CTR1(KTR_IGMPV3, "%s: merge inm state", __func__);
@@ -2181,20 +2187,21 @@ inp_join_group(struct inpcb *inp, struct
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed to merge inm state",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 		CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
 		error = igmp_change_state(inm);
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed igmp downcall",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 	}
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
-out_imf_rollback:
 	INP_WLOCK_ASSERT(inp);
 	if (error) {
 		imf_rollback(imf);
@@ -2398,7 +2405,7 @@ inp_leave_group(struct inpcb *inp, struc
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed to merge inm state",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 
 		CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -2409,9 +2416,10 @@ inp_leave_group(struct inpcb *inp, struc
 		}
 	}
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
-out_imf_rollback:
 	if (error)
 		imf_rollback(imf);
 	else
@@ -2645,7 +2653,7 @@ inp_set_source_filters(struct inpcb *inp
 	error = inm_merge(inm, imf);
 	if (error) {
 		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
-		goto out_imf_rollback;
+		goto out_in_multi_locked;
 	}
 
 	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -2653,6 +2661,8 @@ inp_set_source_filters(struct inpcb *inp
 	if (error)
 		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
 out_imf_rollback:
_______________________________________________
svn-src-all@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/svn-src-all
To unsubscribe, send any mail to "svn-src-all-unsubscribe@freebsd.org"
Comment 2 John-Mark Gurney freebsd_committer 2014-01-28 18:18:18 UTC
State Changed
From-To: open->patched

gnn has committed the fix, but still needs to be MFC'd... 


Comment 3 John-Mark Gurney freebsd_committer 2014-01-28 18:18:18 UTC
Responsible Changed
From-To: freebsd-bugs->gnn

gnn has committed the fix, but still needs to be MFC'd...
Comment 4 dfilter service freebsd_committer 2014-02-03 03:31:42 UTC
Author: gnn
Date: Mon Feb  3 03:31:35 2014
New Revision: 261425
URL: http://svnweb.freebsd.org/changeset/base/261425

Log:
  MFC 260796
  
  Fix various places where we don't properly release a lock
  
  PR:		185043
  Submitted by:	Michael Bentkofsky

Modified:
  stable/10/sys/netinet/in_mcast.c
Directory Properties:
  stable/10/   (props changed)

Modified: stable/10/sys/netinet/in_mcast.c
==============================================================================
--- stable/10/sys/netinet/in_mcast.c	Mon Feb  3 02:56:23 2014	(r261424)
+++ stable/10/sys/netinet/in_mcast.c	Mon Feb  3 03:31:35 2014	(r261425)
@@ -1452,7 +1452,7 @@ inp_block_unblock_source(struct inpcb *i
 	error = inm_merge(inm, imf);
 	if (error) {
 		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
-		goto out_imf_rollback;
+		goto out_in_multi_locked;
 	}
 
 	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -1460,6 +1460,8 @@ inp_block_unblock_source(struct inpcb *i
 	if (error)
 		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
 out_imf_rollback:
@@ -2128,8 +2130,12 @@ inp_join_group(struct inpcb *inp, struct
 	if (is_new) {
 		error = in_joingroup_locked(ifp, &gsa->sin.sin_addr, imf,
 		    &inm);
-		if (error)
+		if (error) {
+                        CTR1(KTR_IGMPV3, "%s: in_joingroup_locked failed", 
+                            __func__);
+                        IN_MULTI_UNLOCK();
 			goto out_imo_free;
+                }
 		imo->imo_membership[idx] = inm;
 	} else {
 		CTR1(KTR_IGMPV3, "%s: merge inm state", __func__);
@@ -2137,20 +2143,21 @@ inp_join_group(struct inpcb *inp, struct
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed to merge inm state",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 		CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
 		error = igmp_change_state(inm);
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed igmp downcall",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 	}
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
-out_imf_rollback:
 	INP_WLOCK_ASSERT(inp);
 	if (error) {
 		imf_rollback(imf);
@@ -2354,7 +2361,7 @@ inp_leave_group(struct inpcb *inp, struc
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed to merge inm state",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 
 		CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -2365,9 +2372,10 @@ inp_leave_group(struct inpcb *inp, struc
 		}
 	}
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
-out_imf_rollback:
 	if (error)
 		imf_rollback(imf);
 	else
@@ -2601,7 +2609,7 @@ inp_set_source_filters(struct inpcb *inp
 	error = inm_merge(inm, imf);
 	if (error) {
 		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
-		goto out_imf_rollback;
+		goto out_in_multi_locked;
 	}
 
 	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -2609,6 +2617,8 @@ inp_set_source_filters(struct inpcb *inp
 	if (error)
 		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
 out_imf_rollback:
_______________________________________________
svn-src-all@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/svn-src-all
To unsubscribe, send any mail to "svn-src-all-unsubscribe@freebsd.org"
Comment 5 dfilter service freebsd_committer 2014-02-09 21:48:22 UTC
Author: gnn
Date: Sun Feb  9 21:48:14 2014
New Revision: 261694
URL: http://svnweb.freebsd.org/changeset/base/261694

Log:
  MFC: 260796
  
  Fix various places where we don't properly release a lock.
  
  PR:		185043
  Submitted by:	Michael Bentkofsky

Modified:
  stable/9/sys/netinet/in_mcast.c
Directory Properties:
  stable/9/sys/   (props changed)

Modified: stable/9/sys/netinet/in_mcast.c
==============================================================================
--- stable/9/sys/netinet/in_mcast.c	Sun Feb  9 21:47:46 2014	(r261693)
+++ stable/9/sys/netinet/in_mcast.c	Sun Feb  9 21:48:14 2014	(r261694)
@@ -1446,7 +1446,7 @@ inp_block_unblock_source(struct inpcb *i
 	error = inm_merge(inm, imf);
 	if (error) {
 		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
-		goto out_imf_rollback;
+		goto out_in_multi_locked;
 	}
 
 	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -1454,6 +1454,8 @@ inp_block_unblock_source(struct inpcb *i
 	if (error)
 		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
 out_imf_rollback:
@@ -2094,8 +2096,12 @@ inp_join_group(struct inpcb *inp, struct
 	if (is_new) {
 		error = in_joingroup_locked(ifp, &gsa->sin.sin_addr, imf,
 		    &inm);
-		if (error)
+		if (error) {
+                        CTR1(KTR_IGMPV3, "%s: in_joingroup_locked failed", 
+                            __func__);
+                        IN_MULTI_UNLOCK();
 			goto out_imo_free;
+                }
 		imo->imo_membership[idx] = inm;
 	} else {
 		CTR1(KTR_IGMPV3, "%s: merge inm state", __func__);
@@ -2103,20 +2109,21 @@ inp_join_group(struct inpcb *inp, struct
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed to merge inm state",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 		CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
 		error = igmp_change_state(inm);
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed igmp downcall",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 	}
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
-out_imf_rollback:
 	INP_WLOCK_ASSERT(inp);
 	if (error) {
 		imf_rollback(imf);
@@ -2320,7 +2327,7 @@ inp_leave_group(struct inpcb *inp, struc
 		if (error) {
 			CTR1(KTR_IGMPV3, "%s: failed to merge inm state",
 			    __func__);
-			goto out_imf_rollback;
+			goto out_in_multi_locked;
 		}
 
 		CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -2331,9 +2338,10 @@ inp_leave_group(struct inpcb *inp, struc
 		}
 	}
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
-out_imf_rollback:
 	if (error)
 		imf_rollback(imf);
 	else
@@ -2567,7 +2575,7 @@ inp_set_source_filters(struct inpcb *inp
 	error = inm_merge(inm, imf);
 	if (error) {
 		CTR1(KTR_IGMPV3, "%s: failed to merge inm state", __func__);
-		goto out_imf_rollback;
+		goto out_in_multi_locked;
 	}
 
 	CTR1(KTR_IGMPV3, "%s: doing igmp downcall", __func__);
@@ -2575,6 +2583,8 @@ inp_set_source_filters(struct inpcb *inp
 	if (error)
 		CTR1(KTR_IGMPV3, "%s: failed igmp downcall", __func__);
 
+out_in_multi_locked:
+
 	IN_MULTI_UNLOCK();
 
 out_imf_rollback:
_______________________________________________
svn-src-all@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/svn-src-all
To unsubscribe, send any mail to "svn-src-all-unsubscribe@freebsd.org"