From owner-freebsd-current@FreeBSD.ORG Tue Oct 16 16:31:25 2007 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 932ED16A41B; Tue, 16 Oct 2007 16:31:25 +0000 (UTC) (envelope-from dan@dan.emsphone.com) Received: from dan.emsphone.com (dan.emsphone.com [199.67.51.101]) by mx1.freebsd.org (Postfix) with ESMTP id 1A58713C478; Tue, 16 Oct 2007 16:31:24 +0000 (UTC) (envelope-from dan@dan.emsphone.com) Received: (from dan@localhost) by dan.emsphone.com (8.14.1/8.14.1) id l9GGVNeF076570; Tue, 16 Oct 2007 11:31:23 -0500 (CDT) (envelope-from dan) Date: Tue, 16 Oct 2007 11:31:23 -0500 From: Dan Nelson To: Kris Kennaway Message-ID: <20071016163123.GA22599@dan.emsphone.com> References: <20070912172752.GA13960@dan.emsphone.com> <200710101615.48760.jhb@freebsd.org> <20071012143800.GA76105@dan.emsphone.com> <470F9211.8010604@FreeBSD.org> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="fUYQa+Pmc3FrFX/N" Content-Disposition: inline In-Reply-To: <470F9211.8010604@FreeBSD.org> X-OS: FreeBSD 7.0-PRERELEASE User-Agent: Mutt/1.5.16 (2007-06-09) Cc: freebsd-net@freebsd.org, freebsd-current@freebsd.org, Ivan Voras Subject: Re: Panic in arpresolve->rt_check? X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 16 Oct 2007 16:31:25 -0000 --fUYQa+Pmc3FrFX/N Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In the last episode (Oct 12), Kris Kennaway said: > Dan Nelson wrote: >> In the last episode (Oct 10), John Baldwin said: >>> On Wednesday 12 September 2007 02:50:37 pm Ivan Voras wrote: >>>> Dan Nelson wrote: >>>>> The same panic was also reported for 6.2 via PR 107865 and PR >>>>> 112490. 112490 included a workaround patch (I haven't tried it; >>>>> just found it). >>>> >>>> The proposed patch in kern/112490 looks trivial but someone who >>>> knows more about net locking should check it out. Unfortunately it >>>> lacks context and I don't know the code in question to apply it >>>> safely on a production machine :( >>> >>> I also get panics with what appears to be a double free of >>> rt_gwroute in rtexpunge(), so I think while this PR may help some >>> with figuring out the problem, I'm not sure it solves the root bug. >>> >>> Hmm, possibly try this patch: >> >> This makes the panics more frequent on my machine, actually :) > > Since you can reproduce this frequently the best thing might be to > instrument all the route handling with KTR so that you can do > post-mortem and try to figure out where the double-free or missing > reference happened. I've added some KTR debugging (why are the macros named CTR* instead of KTR* ? ) and I think I've got the problem nailed down, but I don't know anything about networking so I don't know what the solution is. I've attached a KTR dump and the debugging patches I made (done to preserve line numbering at the expense of style). It looks like two threads are entering rt_check at the same time. In the ktrdump, lrt0 is 0xc674d000 and lrt0->rt_gwroute is 0xc674ae88 for both threads. The thread on CPU1 locks lrt0 at line :1287 (ktr index 641), then locks lrt0->rt_gwroute at :1303 (k642). It frees lrt0->rt_gwroute at :1305 (k643), then unlocks lrt0 at :1308 (k651) before calling rtalloc1(). Meanwhile, the thread on CPU0 has entered the rt_check function and is spinning on the lrt0 lock at line :1287 (k649). When CPU1 unlocks ltr0 (k651 above), lrt0->rt_gwroute is still pointing to the freed rtentry. CPU0 then attempts to lock the now-freed lrt0->rt_gwroute and crashes. So, the problem is that ltr0->rt_gwroute is being left in an inconsistent state while ltr0 is unlocked. What's the solution? Zero out rt_gwroute before unlocking lrt0, then do some extra checks after re-locking to handle the case where another thread has called rtalloc1 before us, or something else? Or is there some other locking problem higher up that's allowing rt_check to be called in parellel on the same rtentry in the first place? -- Dan Nelson dnelson@allantgroup.com --fUYQa+Pmc3FrFX/N Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="ktrdump.150" index cpu timestamp file and line trace ------ --- ---------------- ---------------------------------------- ----- 658 1 55794610845896 net/route.c:1316 0xcd38caa0 lock 0xc674d000 in rt_check 657 1 55794610828094 net/route.c:175 0xcd38caa0 lock 0xc7a49168 in rtalloc1 656 1 55794610826764 net/route.c:911 0xcd38caa0 unlock 0xc7a49168 in rtrequest1 655 1 55794610826184 net/route.c:909 0xcd38caa0 addref 0xc7a49168 1->2 in rtrequest1 654 1 55794610824041 netinet/if_ether.c:224 0xcd38caa0 addref 0xc7a49168 0->1 in arp_rtrequest 653 1 55794610811998 net/route.c:788 0xcd38caa0 lock 0xc7a49168 in rtrequest1 652 0 55794610803227 net/route.c:1303 0xcb107000 lock 0xc674ae88 in rt_check 651 1 55794610799304 net/route.c:1308 0xcd38caa0 unlock 0xc674d000 in rt_check 650 1 55794610797886 net/route.c:302 0xcd38caa0rt_check 0xc674d000 646 0 55794610791936 netinet/if_ether.c:365 0xcb107000>arpresolve 0xc674d000 645 1 55794610786793 net/route.c:245 0xcd38caa0 remref 0xc674ae88 1->0 in rtfree 644 1 55794610786128 net/route.c:238 0xcd38caa0>rtfree 0xc674ae88 643 1 55794610783781 net/route.c:1305 0xcd38caa0 free 0xc674ae88 642 1 55794610782649 net/route.c:1303 0xcd38caa0 lock 0xc674ae88 in rt_check 641 1 55794610780584 net/route.c:1287 0xcd38caa0 lock 0xc674d000 in rt_check 640 1 55794610779823 net/route.c:1285 0xcd38caa0>rt_check 0xc674d000 639 1 55794610777390 netinet/if_ether.c:365 0xcd38caa0>arpresolve 0xc674d000 638 0 55794610752772 net/route.c:119 0xcb107000 unlock 0xc674d000 in rtalloc_ign 637 0 55794610751654 net/route.c:198 0xcb107000 addref 0xc674d000 1->2 in rtalloc1 636 0 55794610750193 net/route.c:197 0xcb107000 lock 0xc674d000 in rtalloc1 635 1 55794610736882 net/route.c:119 0xcd38caa0 unlock 0xc674d000 in rtalloc_ign 634 1 55794610735429 net/route.c:198 0xcd38caa0 addref 0xc674d000 0->1 in rtalloc1 633 1 55794610733358 net/route.c:197 0xcd38caa0 lock 0xc674d000 in rtalloc1 --fUYQa+Pmc3FrFX/N Content-Type: text/x-diff; charset=us-ascii Content-Disposition: attachment; filename="ktr.diff" Index: net/route.c =================================================================== RCS file: /home/ncvs/src/sys/net/route.c,v retrieving revision 1.120 diff -u -r1.120 route.c --- net/route.c 11 Jun 2007 12:19:34 -0000 1.120 +++ net/route.c 16 Oct 2007 03:01:18 -0000 @@ -40,7 +40,7 @@ #include #include #include - +#include #include #include @@ -235,7 +235,7 @@ KASSERT(rt != NULL,("%s: NULL rt", __func__)); rnh = rt_tables[rt_key(rt)->sa_family]; KASSERT(rnh != NULL,("%s: NULL rnh", __func__)); - + CTR2(KTR_NET, "%p>rtfree %p",curthread, rt); RT_LOCK_ASSERT(rt); /* @@ -299,13 +299,13 @@ */ RT_LOCK_DESTROY(rt); uma_zfree(rtzone, rt); - return; + CTR2(KTR_NET, "%prt_check %p", curthread, rt); /* NB: the locking here is tortuous... */ RT_LOCK(rt); if ((rt->rt_flags & RTF_UP) == 0) { RT_UNLOCK(rt); - rt = rtalloc1(dst, 1, 0UL); + CTR2(KTR_NET, "%p discard %p in rt_check", curthread, rt); rt = rtalloc1(dst, 1, 0UL); if (rt != NULL) { RT_REMREF(rt); /* XXX what about if change? */ - } else - return (EHOSTUNREACH); + } else { + CTR1(KTR_NET, "%psa_family != AF_NS */ + } /* XXX BSD/OS checks dst->sa_family != AF_NS */ if (rt->rt_flags & RTF_GATEWAY) { if (rt->rt_gwroute == NULL) goto lookup; rt = rt->rt_gwroute; RT_LOCK(rt); /* NB: gwroute */ if ((rt->rt_flags & RTF_UP) == 0) { - RTFREE_LOCKED(rt); /* unlock gwroute */ + CTR2(KTR_NET, "%p free %p", curthread, rt); RTFREE_LOCKED(rt); /* unlock gwroute */ rt = rt0; lookup: RT_UNLOCK(rt0); @@ -1311,13 +1311,13 @@ rt0->rt_gwroute = NULL; RT_REMREF(rt0); RT_UNLOCK(rt0); - return (ENETUNREACH); + CTR1(KTR_NET, "%prt_gwroute = rt; if (rt == NULL) { RT_UNLOCK(rt0); - return (EHOSTUNREACH); + CTR1(KTR_NET, "%prt_rmx.rmx_expire); if (error) { RT_UNLOCK(rt); - return (rt == rt0 ? EHOSTDOWN : EHOSTUNREACH); + CTR1(KTR_NET, "%prt_mtx, "rtentry", NULL, MTX_DEF | MTX_DUPOK) -#define RT_LOCK(_rt) mtx_lock(&(_rt)->rt_mtx) -#define RT_UNLOCK(_rt) mtx_unlock(&(_rt)->rt_mtx) -#define RT_LOCK_DESTROY(_rt) mtx_destroy(&(_rt)->rt_mtx) +#define RT_LOCK(_rt) do { CTR3(KTR_NET,"%p lock %p in %s", curthread,_rt,__func__); mtx_lock(&(_rt)->rt_mtx); } while(0) +#define RT_UNLOCK(_rt) do { CTR3(KTR_NET,"%p unlock %p in %s", curthread,_rt,__func__); mtx_unlock(&(_rt)->rt_mtx); } while(0) +#define RT_LOCK_DESTROY(_rt) do { CTR3(KTR_NET,"%p destroy %p in %s", curthread,_rt,__func__); mtx_destroy(&(_rt)->rt_mtx); } while(0) #define RT_LOCK_ASSERT(_rt) mtx_assert(&(_rt)->rt_mtx, MA_OWNED) #define RT_ADDREF(_rt) do { \ RT_LOCK_ASSERT(_rt); \ KASSERT((_rt)->rt_refcnt >= 0, \ ("negative refcnt %ld", (_rt)->rt_refcnt)); \ + CTR5(KTR_NET,"%p addref %p %d->%d in %s", curthread, _rt, \ + (_rt)->rt_refcnt, (_rt)->rt_refcnt+1, \ + __func__); \ (_rt)->rt_refcnt++; \ } while (0) #define RT_REMREF(_rt) do { \ RT_LOCK_ASSERT(_rt); \ KASSERT((_rt)->rt_refcnt > 0, \ ("bogus refcnt %ld", (_rt)->rt_refcnt)); \ + CTR5(KTR_NET,"%p remref %p %d->%d in %s", curthread, _rt, \ + (_rt)->rt_refcnt, (_rt)->rt_refcnt-1, \ + __func__); \ (_rt)->rt_refcnt--; \ } while (0) Index: netinet/if_ether.c =================================================================== RCS file: /home/ncvs/src/sys/netinet/if_ether.c,v retrieving revision 1.162 diff -u -r1.162 if_ether.c --- netinet/if_ether.c 7 Oct 2007 20:44:22 -0000 1.162 +++ netinet/if_ether.c 15 Oct 2007 21:02:46 -0000 @@ -362,20 +362,20 @@ struct sockaddr_dl *sdl; int error; - if (m->m_flags & M_BCAST) { /* broadcast */ + CTR2(KTR_NET,"%p>arpresolve %p", curthread,rt0); if (m->m_flags & M_BCAST) { /* broadcast */ (void)memcpy(desten, ifp->if_broadcastaddr, ifp->if_addrlen); - return (0); + CTR1(KTR_NET,"%pm_flags & M_MCAST && ifp->if_type != IFT_ARCNET) {/* multicast */ ETHER_MAP_IP_MULTICAST(&SIN(dst)->sin_addr, desten); - return (0); + CTR1(KTR_NET,"%prt_llinfo; if (la == NULL) @@ -392,7 +392,7 @@ "arpresolve: can't allocate route for %s\n", inet_ntoa(SIN(dst)->sin_addr)); m_freem(m); - return (EINVAL); /* XXX */ + CTR1(KTR_NET,"%prt_llinfo; if (la == NULL) { @@ -401,7 +401,7 @@ "arpresolve: can't allocate llinfo for %s\n", inet_ntoa(SIN(dst)->sin_addr)); m_freem(m); - return (EINVAL); /* XXX */ + CTR1(KTR_NET,"%prt_gateway); @@ -427,11 +427,11 @@ RT_UNLOCK(rt); arprequest(ifp, &sin, &SIN(dst)->sin_addr, IF_LLADDR(ifp)); - return (0); + CTR1(KTR_NET,"%pif_flags & (IFF_NOARP | IFF_STATICARP)) { RT_UNLOCK(rt); m_freem(m); - return (EINVAL); + CTR1(KTR_NET,"%p