Re: ATF tests still failing to complete within 2 hours on amd64

[Nicolas Joly <njoly%pasteur.fr@localhost>]

On Thu, Dec 01, 2011 at 11:44:56AM -0500, Thor Lancelot Simon wrote:
> On Thu, Dec 01, 2011 at 06:15:43PM +0200, Andreas Gustafsson wrote:
> > Thor Lancelot Simon wrote:
> > > I guess the question at this point is, how do we debug this?  I'm willing
> > > to accept that my rnd/entropy changes may have somehow triggered the
> > > problem, but since I've come as close as I can to simply isolating rump
> > > from the entropy subsystem and the problem persists -- I don't really know
> > > where to look.
> > 
> > I think the general principle would be to choose a test that is
> > failing consistently when run in isolation, and then poke it with a
> > debugger to it to see why it is failing.
> > 
> > For example, if I do the following on i386:
> > 
> >   cd /usr/tests/lib/librumphijack
> >   ./t_tcpip http
> > 
> > I get a core file, and gdb tells me:
> 
> Thanks!
> 
> I will set up an i386 VM and try to see what's wrong with the mutex
> handling in question.  Or whether the cprng_strong is corrupt.  Or
> whether I'm stumped again.

If this helps, this looks like an uninitialised lock, according to
following backtrace (MKDEBUG=yes, RUMP_LOCKDEBUG=yes) on amd64 :

#0  0x00007f7ff64ebd5a in _lwp_kill () from /usr/lib/libc.so.12
#1  0x00007f7ff64eb692 in abort () at 
/local/src/NetBSD/src/lib/libc/stdlib/abort.c:74
#2  0x00007f7ff740983c in rumpuser_exit (rv=55) at 
/local/src/NetBSD/src/lib/librumpuser/rumpuser.c:541
#3  0x00007f7ff7885540 in cpu_reboot (howto=<optimized out>,bootstr=<optimized 
out>) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/librump/rumpkern/rump.c:569
#4  0x00007f7ff785de7e in vpanic (fmt=0x7f7ff788e280 "lockdebug_lookup: 
uninitialized lock (lock=%p,from=%08lx)",ap=0x7f7fe7fff4f0)
    at /local/src/NetBSD/src/lib/librump/../../sys/rump/../kern/subr_prf.c:308
#5  0x00007f7ff785df83 in panic (fmt=0x37 <Address 0x37 out of bounds>) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/../kern/subr_prf.c:205
#6  0x00007f7ff784c57f in lockdebug_lookup (where=140187590484806,lock=0x0) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/../kern/subr_lockdebug.c:195
#7  lockdebug_wantlock 
(lock=0x0,where=140187590484806,shared=false,trylock=false) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/../kern/subr_lockdebug.c:430
#8  0x00007f7ff7881cae in mutex_enter (mtx=0x0) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/librump/rumpkern/locks.c:112
#9  0x00007f7ff7886346 in cprng_strong (c=0x0,p=0x7f7ff5e97220,len=16) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/librump/rumpkern/cprng_stub.c:81
#10 0x00007f7ff5c2692f in tcp_new_iss1 
(laddr=0x7f7ff7b9cedc,faddr=0x7f7ff7b9cee0,lport=65535,fport=20480,addrsz=4,addin=0)
    at 
/local/src/NetBSD/src/sys/rump/net/lib/libnet/../../../../netinet/tcp_subr.c:2222
#11 0x00007f7ff5c22eec in tcp_usrreq (so=<optimized 
out>,req=4,m=0x0,nam=0x7f7ff7b3ee00,control=0x0,l=<optimized out>)
    at 
/local/src/NetBSD/src/sys/rump/net/lib/libnet/../../../../netinet/tcp_usrreq.c:442
#12 0x00007f7ff5c6137b in tcp_usrreq_wrapper 
(a=0x7f7ff7b70920,b=4,c=0x0,d=0x7f7ff7b3ee00,e=<optimized out>,f=<optimized 
out>)
    at 
/local/src/NetBSD/src/sys/rump/net/lib/libnet/../../../../netinet/in_proto.c:164
#13 0x00007f7ff600a590 in do_sys_connect (l=0x7ffb8808,fd=0,nam=0x7f7ff7b3ee00) 
at 
/local/src/NetBSD/src/lib/librumpnet/../../sys/rump/../kern/uipc_syscalls.c:367
#14 0x00007f7ff600be37 in sys_connect 
(l=0x7ffb8808,uap=0x7f7ff5b03060,retval=<optimized out>)
    at 
/local/src/NetBSD/src/lib/librumpnet/../../sys/rump/../kern/uipc_syscalls.c:346
#15 0x00007f7ff788511d in sy_call 
(rval=0x7f7fe7fff880,uap=0x7f7ff5b03060,l=0x7ffb8808,sy=0x7f7ff7ab90a0)
    at /local/src/NetBSD/src/lib/librump/../../sys/rump/../sys/syscallvar.h:61
#16 rump_proxy_syscall (num=<optimized 
out>,arg=0x7f7ff5b03060,retval=0x7f7fe7fff880) at 
/local/src/NetBSD/src/lib/librump/../../sys/rump/librump/rumpkern/rump.c:752
#17 0x00007f7ff7406b01 in rumpsyscall 
(retval=0x7f7fe7fff880,data=0x7f7ff5b03060,sysnum=98) at 
/local/src/NetBSD/src/lib/librumpuser/rumpuser_sp.c:223
#18 serv_handlesyscall (data=0x7f7ff5b03060 
"",spc=0x7f7ff760c9a8,rhdr=<optimized out>) at 
/local/src/NetBSD/src/lib/librumpuser/rumpuser_sp.c:635
#19 serv_workbouncer (arg=<optimized out>) at 
/local/src/NetBSD/src/lib/librumpuser/rumpuser_sp.c:717
#20 0x00007f7ff7009cd5 in pthread__create_tramp (cookie=0x7f7fe7c00000) at 
/local/src/NetBSD/src/lib/libpthread/pthread.c:492
#21 0x00007f7ff6476420 in ___lwp_park50 () from /usr/lib/libc.so.12
#22 0x00007f7fe8000000 in ?? ()
#23 0x00007f7ff7fe1ec0 in ?? ()
#24 0x0000000111110001 in ?? ()
#25 0x0000000033330003 in ?? ()
#26 0x0000000000000000 in ?? ()


-- 
Nicolas Joly

Projects and Developments in Bioinformatics
Institut Pasteur, Paris.