Re: CURRENT + amd64 + user-ppp = panic

From: Victor Snezhko <snezhko_at_indorsoft.ru>
Date: Wed, 09 Nov 2005 02:52:39 +0600
Victor Snezhko <snezhko_at_indorsoft.ru> writes:

>> Tomorrow I'll try to trace all callout-related operations in nd6
>> and/or the whole netinet6. 
>
> Hmmm... trace shows that the callout_stop/callout_drain call
> always receives a pointer that has not been initialized via
> callout_init, at least not in /usr/src/sys/netinet6/*

Sorry, I lied here. Details below.

> I'll debug this further and report the results.

Hmm, debugging was not so fast...

So, here is what I have for the moment:

1) I was dead wrong about stop called on a pointer that was not
initialized(there was a typo in one of my printf's). 
Call trace shows the following:
At first, nd6_rtrequest(RTM_ADD) is called, it calls callout_init on
the timer and then callout_stop (through nd6_llinfo_settimer).

Then nd6_rtrequest(RTM_DELETE) is called, and it calls callout_stop
without callout_init.

This seemed to be one of the possible cause of the problem, but when
I commented out the last call to nd6_llinfo_settimer(ln, -1), nothing
changed.


2) I tried to trace where corruption occurs. In order to do this I
inserted slow checks into all the code in kern_timeout.c that could
modify the callwheel. No success - first 0xdeadc0de's were
detected by softclock(), not by any other call.

Here is the corresponding patch:



pointer comparisons are probably not 64bit-clean, correct me please if
those pointer->int casts are bad.

If the backtrace is needed I can provide it, just ask.
My check triggers panic when called from a softclock().


3) Recently, thanks to Mark Tinguely, I have found out that I could do
additional checks in trash_dtor() in uma_dbg.c

No results again.

I inserted the following check:



(Again not quite 64bit-ready, the same nasty pointer casts)

Here is the backtrace:


/var/crash # kgdb /usr/obj/usr/src/sys/VVS/kernel vmcore.24
[... skipped ...]
Unread portion of the kernel message buffer:
KDB: enter: trash_dtor: uma_junk found in a callwheel element
panic: from debugger
cpuid = 0
Uptime: 4m2s
Dumping 63 MB (3 chunks)
  chunk 0: 1MB (159 pages) ... ok
  chunk 1: 62MB (15856 pages) 46 30 14 ... ok
  chunk 2: 1MB (256 pages)

#0  doadump () at pcpu.h:165
165	pcpu.h: No such file or directory.
	in pcpu.h
(kgdb) bt
#0  doadump () at pcpu.h:165
#1  0xc0660824 in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:399
#2  0xc0660b39 in panic (fmt=0xc0856fa0 "from debugger")
    at /usr/src/sys/kern/kern_shutdown.c:555
#3  0xc046cee1 in db_panic (addr=-1066954485, have_addr=0, count=-1, 
    modif=0xc60ac934 "") at /usr/src/sys/ddb/db_command.c:434
#4  0xc046ce78 in db_command (last_cmdp=0xc0947a84, cmd_table=0x0, 
    aux_cmd_tablep=0xc08bda78, aux_cmd_tablep_end=0xc08bda94)
    at /usr/src/sys/ddb/db_command.c:403
#5  0xc046cf40 in db_command_loop () at /usr/src/sys/ddb/db_command.c:454
#6  0xc046eb59 in db_trap (type=3, code=0) at /usr/src/sys/ddb/db_main.c:221
#7  0xc06793a4 in kdb_trap (type=3, code=0, tf=0xc60acacc)
    at /usr/src/sys/kern/subr_kdb.c:473
#8  0xc0821630 in trap (frame=
      {tf_fs = 8, tf_es = 40, tf_ds = 40, tf_edi = -1053265664, tf_esi = -1053265920, tf_ebp = -972371188, tf_isp = -972371208, tf_ebx = -559038242, tf_edx = 0, tf_ecx = -1056755712, tf_eax = 62, tf_trapno = 3, tf_err = 0, tf_eip = -1066954485, tf_cs = 32, tf_eflags = 646, tf_esp = -972371156, tf_ss = -1065665882}) at /usr/src/sys/i386/i386/trap.c:610
#9  0xc080ecba in calltrap () at /usr/src/sys/i386/i386/exception.s:139
#10 0xc067910b in kdb_enter (msg=0x3e <Address 0x3e out of bounds>)
---Type <return> to continue, or q <return> to quit---
    at cpufunc.h:60
#11 0xc07b3aa6 in trash_dtor (mem=0xc1387000, size=256, arg=0x0)
    at /usr/src/sys/vm/uma_dbg.c:104
#12 0xc0657dd8 in mb_dtor_mbuf (mem=0xc1387000, size=256, arg=0x0)
    at /usr/src/sys/kern/kern_mbuf.c:245
#13 0xc07b23e4 in uma_zfree_arg (zone=0xc1042960, item=0xc1387000, udata=0x0)
    at /usr/src/sys/vm/uma_core.c:2270
#14 0xc069b9ba in soreceive (so=0xc143d9bc, psa=0xc60acbe8, uio=0xc60acbf4, 
    mp0=0x0, controlp=0x0, flagsp=0xc60acc74) at uma.h:303
#15 0xc06a08c7 in kern_recvit (td=0xc12f3320, s=5, mp=0xc60acc5c, 
    namelenp=0xbfbfdacc, segflg=62) at /usr/src/sys/kern/uipc_syscalls.c:986
#16 0xc06a0af6 in recvit (td=0xc12f3320, s=5, mp=0xc60acc5c, 
    namelenp=0xbfbfdacc) at /usr/src/sys/kern/uipc_syscalls.c:1094
#17 0xc06a0b64 in recvfrom (td=0xc12f3320, uap=0xc60acd04)
    at /usr/src/sys/kern/uipc_syscalls.c:1131
#18 0xc0821e96 in syscall (frame=
      {tf_fs = 59, tf_es = 59, tf_ds = 59, tf_edi = 134570084, tf_esi = 134570080, tf_ebp = -1077940616, tf_isp = -972370588, tf_ebx = 134546020, tf_edx = -1077940864, tf_ecx = 5, tf_eax = 29, tf_trapno = 32, tf_err = 2, tf_eip = 672166495, tf_cs = 51, tf_eflags = 66198, tf_esp = -1077945812, tf_ss = 59})
    at /usr/src/sys/i386/i386/trap.c:1001
---Type <return> to continue, or q <return> to quit---
#19 0xc080ed0f in Xint0x80_syscall ()
    at /usr/src/sys/i386/i386/exception.s:200
#20 0x00000033 in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) up 11
#11 0xc07b3aa6 in trash_dtor (mem=0xc1387000, size=256, arg=0x0)
    at /usr/src/sys/vm/uma_dbg.c:104
104					kdb_enter("trash_dtor: uma_junk found in a "\
(kgdb) list
99			for (c = TAILQ_FIRST(bucket); c != NULL;
100			     c = TAILQ_NEXT(c, c_links.tqe)) {
101				int c2 = (int)c;
102                             int mem2 = (int)mem;
103				if ((u_int32_t)c == uma_junk) {
104					kdb_enter("trash_dtor: uma_junk found in a "\
105						  "callwheel element");
106					break;
107				}
108				if (c2 >= mem2 && c2 < mem2 + size) {
(kgdb) up 1
#12 0xc0657dd8 in mb_dtor_mbuf (mem=0xc1387000, size=256, arg=0x0)
    at /usr/src/sys/kern/kern_mbuf.c:245
245		trash_dtor(mem, size, arg);
(kgdb) list
240	
241		m = (struct mbuf *)mem;
242		if ((m->m_flags & M_PKTHDR) != 0)
243			m_tag_delete_chain(m, NULL);
244	#ifdef INVARIANTS
245		trash_dtor(mem, size, arg);
246	#endif
247	}
248	
249	/* XXX Only because of stats */
(kgdb) up 1
#13 0xc07b23e4 in uma_zfree_arg (zone=0xc1042960, item=0xc1387000, udata=0x0)
    at /usr/src/sys/vm/uma_core.c:2270
2270			zone->uz_dtor(item, keg->uk_size, udata);
(kgdb) list
2265	#endif
2266		CTR2(KTR_UMA, "uma_zfree_arg thread %x zone %s", curthread,
2267		    zone->uz_name);
2268	
2269		if (zone->uz_dtor)
2270			zone->uz_dtor(item, keg->uk_size, udata);
2271	#ifdef INVARIANTS
2272		ZONE_LOCK(zone);
2273		if (keg->uk_flags & UMA_ZONE_MALLOC)
2274			uma_dbg_free(zone, udata, item);
(kgdb) up 1
#14 0xc069b9ba in soreceive (so=0xc143d9bc, psa=0xc60acbe8, uio=0xc60acbf4, 
    mp0=0x0, controlp=0x0, flagsp=0xc60acc74) at uma.h:303
303		uma_zfree_arg(zone, item, NULL);
(kgdb) list
298	static __inline void uma_zfree(uma_zone_t zone, void *item);
299	
300	static __inline void
301	uma_zfree(uma_zone_t zone, void *item)
302	{
303		uma_zfree_arg(zone, item, NULL);
304	}
305	
306	/*
307	 * XXX The rest of the prototypes in this header are h0h0 magic for the VM.
(kgdb) up 1
#15 0xc06a08c7 in kern_recvit (td=0xc12f3320, s=5, mp=0xc60acc5c, 
    namelenp=0xbfbfdacc, segflg=62) at /usr/src/sys/kern/uipc_syscalls.c:986
986		error = so->so_proto->pr_usrreqs->pru_soreceive(so, &fromsa, &auio,
(kgdb) list
981	#ifdef KTRACE
982		if (KTRPOINT(td, KTR_GENIO))
983			ktruio = cloneuio(&auio);
984	#endif
985		len = auio.uio_resid;
986		error = so->so_proto->pr_usrreqs->pru_soreceive(so, &fromsa, &auio,
987		    (struct mbuf **)0, mp->msg_control ? &control : (struct mbuf **)0,
988		    &mp->msg_flags);
989		if (error) {
990			if (auio.uio_resid != (int)len && (error == ERESTART ||
(kgdb) print *(so->so_proto->pr_usrreqs)
$5 = {__Break_the_struct_layout_for_now = 0, 
  pru_abort = 0xc06a24ec <uipc_abort>, pru_accept = 0xc06a2600 <uipc_accept>, 
  pru_attach = 0xc06a26b4 <uipc_attach>, pru_bind = 0xc06a26d0 <uipc_bind>, 
  pru_connect = 0xc06a2740 <uipc_connect>, 
  pru_connect2 = 0xc06a27c8 <uipc_connect2>, 
  pru_control = 0xc069f300 <pru_control_notsupp>, 
  pru_detach = 0xc06a2838 <uipc_detach>, 
  pru_disconnect = 0xc06a28a0 <uipc_disconnect>, 
  pru_listen = 0xc06a2908 <uipc_listen>, 
  pru_peeraddr = 0xc06a2980 <uipc_peeraddr>, 
  pru_rcvd = 0xc06a2a34 <uipc_rcvd>, 
  pru_rcvoob = 0xc069f348 <pru_rcvoob_notsupp>, 
  pru_send = 0xc06a2bc4 <uipc_send>, pru_sense = 0xc06a3024 <uipc_sense>, 
  pru_shutdown = 0xc06a30f0 <uipc_shutdown>, 
  pru_sockaddr = 0xc06a3168 <uipc_sockaddr>, 
  pru_sosend = 0xc069ad84 <sosend>, pru_soreceive = 0xc069b5b0 <soreceive>, 
  pru_sopoll = 0xc069d090 <sopoll>, 
  pru_sosetlabel = 0xc069f3b8 <pru_sosetlabel_null>}
(kgdb) up 1
#16 0xc06a0af6 in recvit (td=0xc12f3320, s=5, mp=0xc60acc5c, 
    namelenp=0xbfbfdacc) at /usr/src/sys/kern/uipc_syscalls.c:1094
1094		return (kern_recvit(td, s, mp, namelenp, UIO_USERSPACE));
(kgdb) list
1089		int s;
1090		struct msghdr *mp;
1091		void *namelenp;
1092	{
1093	
1094		return (kern_recvit(td, s, mp, namelenp, UIO_USERSPACE));
1095	}
1096	
1097	/*
1098	 * MPSAFE


The thing I want to note is that callwheel corruptions after applying
this patch stop to be reproducible. They may occur, may not.

4) I inserted a kdb_enter() call in the beginning of
nd6_llinfo_settimer(). Then tried to step some functions up the
stack. Pressed "n" a couple of times, then exit via "c". Panic didn't
occur! (It would certainly occur if I exited the kdb immediately after
kdb_enter).

Don't know what to think about the last. Improper locking? Freeing a
callwheel entry and then it's slow removal? Strange...

P.S.: Perharps I should file a PR about all this as the problem turned
out to be not so easy. To what degree should I include the details
above?

-- 
WBR, Victor V. Snezhko
EMail: snezhko_at_indorsoft.ru

Received on Tue Nov 08 2005 - 19:52:52 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:38:47 UTC