Skip site navigation (1)Skip section navigation (2)
Date:      Mon, 23 Mar 1998 07:45:08 +1100 (EST)
From:      peter.jeremyp@alcatel.com.au
To:        FreeBSD-gnats-submit@FreeBSD.ORG
Subject:   kern/6099: LPIP to slow machine causes hang
Message-ID:  <199803222045.HAA16588@gsms01.alcatel.com.au>

next in thread | raw e-mail | index | archive | help

>Number:         6099
>Category:       kern
>Synopsis:       LPIP to slow machine causes hang
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    freebsd-bugs
>State:          open
>Quarter:
>Keywords:
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Sun Mar 22 12:50:05 PST 1998
>Last-Modified:
>Originator:     Peter Jeremy
>Organization:
N/A
>Release:        FreeBSD 2.2.5-RELEASE i386
>Environment:

Main machine (with problem):
Mar 22 17:57:46 vk2pj /kernel: Copyright (c) 1992-1997 FreeBSD Inc.
Mar 22 17:57:46 vk2pj /kernel: Copyright (c) 1982, 1986, 1989, 1991, 1993
Mar 22 17:57:46 vk2pj /kernel: 	The Regents of the University of California.  All rights reserved.
Mar 22 17:57:46 vk2pj /kernel: 
Mar 22 17:57:46 vk2pj /kernel: FreeBSD 2.2.5-RELEASE #11: Sun Mar 22 15:14:49 EST 1998
Mar 22 17:57:46 vk2pj /kernel:     root@vk2pj.alcatel.com.au:/home/src/2.2.5/sys/compile/pj_dbg
Mar 22 17:57:46 vk2pj /kernel: CPU: i486DX (486-class CPU)
Mar 22 17:57:46 vk2pj /kernel: real memory  = 20971520 (20480K bytes)
Mar 22 17:57:46 vk2pj /kernel: avail memory = 18444288 (18012K bytes)
Mar 22 17:57:46 vk2pj /kernel: Probing for devices on the ISA bus:
Mar 22 17:57:46 vk2pj /kernel: sc0 at 0x60-0x6f irq 1 on motherboard
Mar 22 17:57:46 vk2pj /kernel: sc0: VGA color <16 virtual consoles, flags=0x0>
Mar 22 17:57:46 vk2pj /kernel: sio0 at 0x3f8-0x3ff irq 4 on isa
Mar 22 17:57:46 vk2pj /kernel: sio0: type 16450
Mar 22 17:57:46 vk2pj /kernel: sio1 at 0x2f8-0x2ff irq 9 on isa
Mar 22 17:57:46 vk2pj /kernel: sio1: type 16550A
Mar 22 17:57:46 vk2pj /kernel: sio2 at 0x3e8-0x3ef irq 3 flags 0x10 on isa
Mar 22 17:57:46 vk2pj /kernel: sio2: type 16450: ticking @ 989
Mar 22 17:57:46 vk2pj /kernel: lpt0 at 0x378-0x37f irq 7 on isa
Mar 22 17:57:46 vk2pj /kernel: lpt0: Interrupt-driven port
Mar 22 17:57:47 vk2pj /kernel: lp0: TCP/IP capable interface
Mar 22 17:57:47 vk2pj /kernel: lpt1 at 0x278-0x27f irq 5 on isa
Mar 22 17:57:47 vk2pj /kernel: lpt1: Interrupt-driven port
Mar 22 17:57:47 vk2pj /kernel: lp1: TCP/IP capable interface
Mar 22 17:57:47 vk2pj /kernel: pca0 on motherboard
Mar 22 17:57:47 vk2pj /kernel: pca0: PC speaker audio driver
Mar 22 17:57:47 vk2pj /kernel: fdc0 at 0x3f0-0x3f7 irq 6 drq 2 on isa
Mar 22 17:57:47 vk2pj /kernel: fd0: 1.44MB 3.5in
Mar 22 17:57:47 vk2pj /kernel: wdc0 at 0x1f0-0x1f7 irq 14 on isa
Mar 22 17:57:47 vk2pj /kernel: wdc0: unit 0 (wd0): <Conner Peripherals 420MB - CFS420A>, 32-bit, multi-block-16
Mar 22 17:57:47 vk2pj /kernel: wd0: 406MB (832608 sectors), 826 cyls, 16 heads, 63 S/T, 512 B/S
Mar 22 17:57:47 vk2pj /kernel: wdc0: unit 1 (wd1): <Maxtor 72004 AP>, 32-bit, multi-block-16
Mar 22 17:57:47 vk2pj /kernel: wd1: 1916MB (3924144 sectors), 3893 cyls, 16 heads, 63 S/T, 512 B/S
Mar 22 17:57:47 vk2pj /kernel: aha0 at 0x334-0x337 irq 11 drq 6 on isa
Mar 22 17:57:47 vk2pj /kernel: (aha0:6:0): "ARCHIVE VIPER 150  21247 -005" type 1 removable SCSI 1
Mar 22 17:57:47 vk2pj /kernel: st0(aha0:6:0): Sequential-Access density code 0x0,  drive empty
Mar 22 17:57:47 vk2pj /kernel: matcd - Matsushita (Panasonic) CD-ROM Driver by FDIV, Version  1(26) 18-Oct-95
Mar 22 17:57:47 vk2pj /kernel: matcdc0 at 0x230-0x233 on isa
Mar 22 17:57:47 vk2pj /kernel: matcdc0 Host interface type 0
Mar 22 17:57:47 vk2pj /kernel: matcd0: [CR-5630.75]  
Mar 22 17:57:47 vk2pj /kernel: npx0 on motherboard
Mar 22 17:57:47 vk2pj /kernel: npx0: INT 16 interface
Mar 22 17:57:47 vk2pj /kernel: sb0 at 0x220 irq 10 drq 1 on isa
Mar 22 17:57:47 vk2pj /kernel: sb0: <SoundBlaster 16 4.11>
Mar 22 17:57:47 vk2pj /kernel: sbxvi0 at 0x0 drq 5 on isa
Mar 22 17:57:47 vk2pj /kernel: sbxvi0: <SoundBlaster 16 4.11>
Mar 22 17:57:47 vk2pj /kernel: sbmidi0 at 0x330 on isa
Mar 22 17:57:47 vk2pj /kernel:  <SoundBlaster MPU-401>
Mar 22 17:57:48 vk2pj /kernel: opl0 at 0x388 on isa
Mar 22 17:57:48 vk2pj /kernel: opl0: <Yamaha OPL-3 FM>
Mar 22 17:57:48 vk2pj /kernel: joy0 at 0x201 on isa
Mar 22 17:57:48 vk2pj /kernel: joy0: joystick

`slow machine'
Mar 14 08:41:13 pc0640 /kernel: Copyright (c) 1992-1996 FreeBSD Inc.
Mar 14 08:41:13 pc0640 /kernel: Copyright (c) 1982, 1986, 1989, 1991, 1993
Mar 14 08:41:13 pc0640 /kernel: 	The Regents of the University of California.  All rights reserved.
Mar 14 08:41:13 pc0640 /kernel: 
Mar 14 08:41:13 pc0640 /kernel: FreeBSD 2.2.1-RELEASE #2: Sun Jun 29 16:40:20 EST 1997
Mar 14 08:41:13 pc0640 /kernel:     root@vk2pj.alcatel.com.au:/usr/src/sys/compile/pc0640
Mar 14 08:41:13 pc0640 /kernel: CPU: i386DX (386-class CPU)
Mar 14 08:41:13 pc0640 /kernel: real memory  = 8781824 (8576K bytes)
Mar 14 08:41:13 pc0640 /kernel: avail memory = 7168000 (7000K bytes)
Mar 14 08:41:14 pc0640 /kernel: Probing for devices on the ISA bus:
Mar 14 08:41:14 pc0640 /kernel: sc0 at 0x60-0x6f irq 1 on motherboard
Mar 14 08:41:14 pc0640 /kernel: sc0: VGA color <10 virtual consoles, flags=0x0>
Mar 14 08:41:14 pc0640 /kernel: sio0 at 0x3f8-0x3ff irq 4 on isa
Mar 14 08:41:14 pc0640 /kernel: sio0: type 16450
Mar 14 08:41:14 pc0640 /kernel: lpt0 at 0x378-0x37f irq 7 on isa
Mar 14 08:41:14 pc0640 /kernel: lpt0: Interrupt-driven port
Mar 14 08:41:14 pc0640 /kernel: lp0: TCP/IP capable interface
Mar 14 08:41:14 pc0640 /kernel: psm0 not found at 0x60
Mar 14 08:41:14 pc0640 /kernel: fdc0 at 0x3f0-0x3f7 irq 6 drq 2 on isa
Mar 14 08:41:14 pc0640 /kernel: fdc0: NEC 765
Mar 14 08:41:14 pc0640 /kernel: fd0: 1.44MB 3.5in
Mar 14 08:41:14 pc0640 /kernel: wdc0 at 0x1f0-0x1f7 irq 14 on isa
Mar 14 08:41:14 pc0640 /kernel: wdc0: unit 0 (wd0): <Conner Peripherals 84MB - CP2084>
Mar 14 08:41:14 pc0640 /kernel: wd0: 81MB (166592 sectors), 548 cyls, 8 heads, 38 S/T, 512 B/S
Mar 14 08:41:15 pc0640 /kernel: npx0 at 0xf0-0xff irq 13 on motherboard

The two machines are joined via a Laplink cable on lp0 on both machines.

>Description:

The problem initially manifested itself as an occasional machine hang
(of the i486 machine - vk2pj) when transferring data between the two
machines.  The problem occurred more frequently when there was disk
activity.  The 386 machine has never been affected.  Enabling DDB
revealed that the problem was caused by an mbuf being chained onto
itself, which leads to an infinite loop in sbcompress().  This implied
that an mbuf was being used after it was freed.

Code was added to the mbuf allocation/free routines in order to mark
freed mbuf's (so that continued used would cause a panic as soon as
possible) and record allocations/frees together with (see below).
With this code in place, the failures are commonly `Allocating used
mbuf' or `page fault in kernel mode' panics.

My suspicion is that something is allowing interrupts unexpectedly.
Unfortunately, I have not yet had a chance to work through how the
`soft' priority level (in cpl) is mapped onto the `hard' priority
level (in the i8259's).

The following are partial, annotated gdb traces showing two different
occurrences of the problem:

panic: Allocating used mbuf
...
>How-To-Repeat:

The problem appears to be related to an interrupt window associated
with the LPIP code.  I have not found a short command sequence that is
guaranteed to trigger the bug, but the following script run on the
i486 system (vk2pj) seems to cause it to occur within a minute or two:
---
#!/bin/sh
#
# run a series of commands designed to kill the system
cd /
while true; do tar cf /dev/null usr ; done &
while true; do tar cf /dev/null home ; done &
while rm -f /var/tmp/n2620.pdf ; do scp -p pc0640:n2620.pdf /var/tmp; done &
while ssh pc0640 rm -f kernel; do scp -p /kernel pc0640:. ; done &
vmstat 5
---

Context diffs of debugging code added (the changes to mbuf.h are particularly
kludgy but are not intended to stay):
--- /cdrom/sys/kern/uipc_mbuf.c	Sat Jan 18 06:28:31 1997
+++ kern/uipc_mbuf.c	Sat Mar 21 07:58:41 1998
@@ -103,6 +103,7 @@
 	register int i;
 	int nbytes;
 
+	MBUF_ASSERT(!(1 + (cpl | (~net_imask))), "m_mballoc");
 	/* Once we run out of map space, it will be impossible to get
 	 * any more (nothing is ever freed back to the map) (XXX which
 	 * is dumb). (however you are not dead as m_reclaim might
@@ -124,6 +125,12 @@
 	for (i = 0; i < nmb; i++) {
 		((struct mbuf *)p)->m_next = mmbfree;
 		mmbfree = (struct mbuf *)p;
+#ifdef DIAGNOSTIC
+		/* this will be checked when the buffer is allocated */
+		mmbfree->m_type = MT_FREE;
+		mmbfree->m_nextpkt = (struct mbuf *)(mmbfree->m_data =
+						     (caddr_t)0x76543210);
+#endif
 		p += MSIZE;
 	}
 	mbstat.m_mbufs += nmb;
@@ -308,6 +315,7 @@
 {
 	struct mbuf *mn;
 
+	MBUF_ASSERT(m && m->m_type != MT_FREE, "m_prepend");
 	MGET(mn, how, m->m_type);
 	if (mn == (struct mbuf *)NULL) {
 		m_freem(m);
@@ -350,6 +358,7 @@
 	while (off > 0) {
 		if (m == 0)
 			panic("m_copym");
+		MBUF_ASSERT(m->m_type != MT_FREE, "m_copym 2");
 		if (off < m->m_len)
 			break;
 		off -= m->m_len;
@@ -476,6 +485,7 @@
 	while (off > 0) {
 		if (m == 0)
 			panic("m_copydata");
+		MBUF_ASSERT(m->m_type != MT_FREE, "m_copydata 2");
 		if (off < m->m_len)
 			break;
 		off -= m->m_len;
@@ -502,9 +512,13 @@
 m_cat(m, n)
 	register struct mbuf *m, *n;
 {
-	while (m->m_next)
+	MBUF_ASSERT(m && m->m_type != MT_FREE, "m_cat 1");
+	while (m->m_next) {
+		MBUF_ASSERT(m->m_type == m->m_next->m_type, "m_cat 2");
 		m = m->m_next;
+	}
 	while (n) {
+		MBUF_ASSERT(m->m_type == n->m_type, "m_cat 2");
 		if (m->m_flags & M_EXT ||
 		    m->m_data + m->m_len + n->m_len >= &m->m_dat[MLEN]) {
 			/* just join the two chains */
@@ -852,3 +866,6 @@
 out:	if (((m = m0)->m_flags & M_PKTHDR) && (m->m_pkthdr.len < totlen))
 		m->m_pkthdr.len = totlen;
 }
+
+struct mb_frees mb_frees[256];
+int		mb_freep;		/* byte address within mb_frees */
--- /cdrom/sys/kern/uipc_socket2.c	Fri Jun 27 05:53:47 1997
+++ kern/uipc_socket2.c	Sun Mar 15 20:06:13 1998
@@ -469,8 +469,11 @@
 		return;
 	n = sb->sb_mb;
 	if (n) {
-		while (n->m_nextpkt)
+		MBUF_ASSERT(m != n, "sbappend: mbuf loop detected");
+		while (n->m_nextpkt) {
 			n = n->m_nextpkt;
+			MBUF_ASSERT(m != n, "sbappend: mbuf loop detected");
+		}
 		do {
 			if (n->m_flags & M_EOR) {
 				sbappendrecord(sb, m); /* XXXXXX!!!! */
@@ -519,9 +522,13 @@
 	if (m0 == 0)
 		return;
 	m = sb->sb_mb;
-	if (m)
-		while (m->m_nextpkt)
+	if (m) {
+		MBUF_ASSERT(m != m0, "sbappendrecord: mbuf loop detected");
+		while (m->m_nextpkt) {
 			m = m->m_nextpkt;
+			MBUF_ASSERT(m != m0, "sbappendrecord: mbuf loop detected");
+		}
+	}
 	/*
 	 * Put the first mbuf on the queue.
 	 * Note this permits zero length records.
@@ -683,6 +690,7 @@
 	register struct mbuf *o;
 
 	while (m) {
+		MBUF_ASSERT(m != n, "sbcompress: mbuf loop detected");
 		eor |= m->m_flags & M_EOR;
 		if (m->m_len == 0 &&
 		    (eor == 0 ||
--- /cdrom/sys/sys/mbuf.h	Tue Aug 20 04:30:15 1996
+++ sys/mbuf.h	Sun Mar 22 15:08:17 1998
@@ -163,12 +163,88 @@
 	char	mcl_buf[MCLBYTES];
 };
 
+#ifdef DIAGNOSTIC
+/* circular chain of freed mbuf's */
+extern struct mb_frees {
+	struct mbuf	*mf_mbuf;	/* address of freed mbuf */
+	void		*mf_eip;	/* EIP where mbuf freed */
+	void		*mf_retn;	/* return address for function */
+	void		*mf_ret2;	/* return address for calling fn */
+	void		*mf_ret3;	/* return address for calling fn */
+	void		*mf_ret4;	/* return address for calling fn */
+	void		*mf_ret5;	/* return address for calling fn */
+	void		*mf_ret6;	/* return address for calling fn */
+}	mb_frees[256];
+extern int	mb_freep;		/* byte address within mb_frees */
+
+extern char	kstack[];
+#define	MBUF_SAVE(m, x) do {	void	*tmp, *tmp2, *tmp3; \
+	__asm volatile ("pushf; cli\n\
+	movl	_mb_freep,%0\n\t" x \
+"	movl	%0,%1
+	addl	%4,%1\n\
+	andl	%5,%1\n\
+	movl	%1,_mb_freep\n\
+	addl	$_mb_frees,%0
+	movl	%3,(%0)\n\
+	call	1f\n\
+1:	popl	%1\n\
+	movl	%1,4(%0)\n\
+	movl	4(%%ebp),%1\n\
+	movl	%1,8(%0)\n\
+	movl	(%%ebp),%1\n\
+	cmpl	%1,%%esp\n\
+	jae	2f\n\
+	cmpl	%6,%1\n\
+	jae	2f\n\
+	movl	4(%1),%2\n\
+	movl	%2,12(%0)\n\
+	movl	(%1),%1\n\
+	cmpl	%1,%%esp\n\
+	jae	2f\n\
+	cmpl	%6,%1\n\
+	jae	2f\n\
+	movl	4(%1),%2\n\
+	movl	%2,16(%0)\n\
+	movl	(%1),%1\n\
+	cmpl	%1,%%esp\n\
+	jae	2f\n\
+	cmpl	%6,%1\n\
+	jae	2f\n\
+	movl	4(%1),%2\n\
+	movl	%2,20(%0)\n\
+	movl	(%1),%1\n\
+	cmpl	%1,%%esp\n\
+	jae	2f\n\
+	cmpl	%6,%1\n\
+	jae	2f\n\
+	movl	4(%1),%2\n\
+	movl	%2,24(%0)\n\
+	movl	(%1),%1\n\
+	cmpl	%1,%%esp\n\
+	jae	2f\n\
+	cmpl	%6,%1\n\
+	jae	2f\n\
+	movl	4(%1),%2\n\
+	movl	%2,28(%0)\n\
+2:	popf"		: "&=r" (tmp2), "&=r" (tmp), "&=r" (tmp3) \
+			: "r" (m), "n" (sizeof(mb_frees[0])), \
+			  "n" (sizeof(mb_frees) - 1), \
+			  "i" (kstack + UPAGES * PAGE_SIZE)); \
+	} while (0)
+#else
+#define	MBUF_SAVE(m, x)
+#endif
+
 /*
  * mbuf utility macros:
  *
  *	MBUFLOCK(code)
  * prevents a section of code from from being interrupted by network
  * drivers.
+ *
+ *	MBUF_ASSERT(condition, message)
+ * if DIAGNOSTIC defined, panics with message unless condition is true
  */
 #define	MBUFLOCK(code) \
 	{ int ms = splimp(); \
@@ -176,6 +252,14 @@
 	  splx(ms); \
 	}
 
+#ifdef DIAGNOSTIC
+#define	MBUF_ASSERT(cond, msg) do { if (!(cond)) panic(msg); } while (0)
+#define	MBUF_DIAG(x)	x
+#else
+#define	MBUF_ASSERT(cond, msg)
+#define	MBUF_DIAG(x)
+#endif
+
 /*
  * mbuf allocation/deallocation macros:
  *
@@ -191,6 +275,8 @@
 	  if (mmbfree == 0) \
 		(void)m_mballoc(1, (how)); \
 	  if (((m) = mmbfree) != 0) { \
+		MBUF_ASSERT((m)->m_type == MT_FREE, "Allocating used mbuf"); \
+		MBUF_SAVE(m, ""); \
 		mmbfree = (m)->m_next; \
 		mbstat.m_mtypes[MT_FREE]--; \
 		(m)->m_type = (type); \
@@ -211,6 +297,8 @@
 	  if (mmbfree == 0) \
 		(void)m_mballoc(1, (how)); \
 	  if (((m) = mmbfree) != 0) { \
+		MBUF_ASSERT((m)->m_type == MT_FREE, "Allocating used mbuf"); \
+		MBUF_SAVE(m, ""); \
 		mmbfree = (m)->m_next; \
 		mbstat.m_mtypes[MT_FREE]--; \
 		(m)->m_type = (type); \
@@ -246,7 +334,8 @@
 	)
 
 #define	MCLGET(m, how) \
-	{ MCLALLOC((m)->m_ext.ext_buf, (how)); \
+	{ MBUF_ASSERT((m) && (m)->m_type != MT_FREE, "MCLGET"); \
+	  MCLALLOC((m)->m_ext.ext_buf, (how)); \
 	  if ((m)->m_ext.ext_buf != NULL) { \
 		(m)->m_data = (m)->m_ext.ext_buf; \
 		(m)->m_flags |= M_EXT; \
@@ -272,6 +361,10 @@
  */
 #define	MFREE(m, n) \
 	MBUFLOCK(  \
+	  MBUF_ASSERT((m) && (m)->m_type > MT_FREE && (m)->m_type <= MT_OOBDATA,\
+		      "Freeing illegal mbuf"); \
+	  MBUF_SAVE(m, "movl %0,%1; shl $11,%1; orl $0x70000000,%1\n\
+	movl %1,4(%3); movl %1,8(%3)\n"); \
 	  mbstat.m_mtypes[(m)->m_type]--; \
 	  if ((m)->m_flags & M_EXT) { \
 		if ((m)->m_ext.ext_free) \
@@ -298,6 +391,7 @@
  * from must have M_PKTHDR set, and to must be empty.
  */
 #define	M_COPY_PKTHDR(to, from) { \
+	MBUF_ASSERT((to) && (from) && (from)->m_type != MT_FREE, "M_COPY_PKTHDR"); \
 	(to)->m_pkthdr = (from)->m_pkthdr; \
 	(to)->m_flags = (from)->m_flags & M_COPYFLAGS; \
 	(to)->m_data = (to)->m_pktdat; \
-----
Note that the lpip code contains the following patches to allow it to
work with tcpdump (there are associated patches to tcpdump and libpcap):
--- /cdrom/sys/i386/isa/lpt.c	Tue Nov 12 20:08:38 1996
+++ i386/isa/lpt.c	Sat Jan 17 19:26:14 1998
@@ -743,7 +743,7 @@
 		}
 		/* check to see if we must do a polled write */
 		if(!(sc->sc_irq & LP_USE_IRQ) && (sc->sc_xfercnt)) {
-			lprintf("p");
+			lprintf("P");
 			if((err = pushbytes(sc)))
 				return(err);
 		}
@@ -880,7 +880,7 @@
 	printf("lp%d: TCP/IP capable interface\n", unit);
 
 #if NBPFILTER > 0
-	bpfattach(ifp, DLT_NULL, LPIPHDRLEN);
+	bpfattach(ifp, DLT_LPIP, LPIPHDRLEN);
 #endif
 }
 /*
@@ -1148,6 +1148,7 @@
 	    }
 #if NBPFILTER > 0
 	    if (sc->sc_if.if_bpf) {
+		lprintf("r");
 		bpf_tap(&sc->sc_if, sc->sc_ifbuf, len);
 	    }
 #endif
@@ -1317,7 +1318,8 @@
     mm = m;
     do {
         cp = mtod(mm,u_char *);
-        while (mm->m_len--)
+        i = mm->m_len;
+        while (i--)
 	    if (lpoutbyte(*cp++, LPMAXSPIN2, lpt_data_port, lpt_stat_port))
 	        goto end;
     } while ((mm = mm->m_next));
@@ -1350,6 +1352,7 @@
 	    m0.m_len = 2;
 	    m0.m_data = (char *)&hdr;
 
+	    lprintf("t");
 	    bpf_mtap(ifp, &m0);
 	}
 #endif
--- /cdrom/sys/net/bpf.c	Sat Oct  4 09:57:03 1997
+++ net/bpf.c	Sat Jan 17 19:26:16 1998
@@ -170,7 +170,9 @@
 	 */
 	switch (linktype) {
 
+	case DLT_NULL:
 	case DLT_SLIP:
+	case DLT_LPIP:
 		sockp->sa_family = AF_INET;
 		hlen = 0;
 		break;
@@ -190,11 +192,6 @@
 		/* XXX 4(FORMAC)+6(dst)+6(src)+3(LLC)+5(SNAP) */
 		hlen = 24;
 #endif
-		break;
-
-	case DLT_NULL:
-		sockp->sa_family = AF_UNSPEC;
-		hlen = 0;
 		break;
 
 	default:
--- /cdrom/sys/net/bpf.h	Tue Aug 20 06:28:25 1996
+++ net/bpf.h	Sat Jan 17 19:26:17 1998
@@ -146,6 +146,7 @@
 #define DLT_PPP		9	/* Point-to-point Protocol */
 #define DLT_FDDI	10	/* FDDI */
 #define DLT_ATM_RFC1483	11	/* LLC/SNAP encapsulated atm */
+#define DLT_LPIP	12	/* Parallel port TCP/IP */
 
 /*
  * The instruction encodings.
---

>Fix:
	
No solution known at this time.
--
Peter Jeremy (VK2PJ)                    peter.jeremy@alcatel.com.au
Alcatel Australia Limited
41 Mandible St                          Phone: +61 2 9690 5019
ALEXANDRIA  NSW  2015                   Fax:   +61 2 9690 5247
>Audit-Trail:
>Unformatted:
>>Partial backtrace:
#9  0xf0111f0a in panic (fmt=0xf0153cef "Allocating used mbuf")
    at ../../kern/kern_shutdown.c:388
#10 0xf0154591 in tcp_output (tp=0xf05e1600) at ../../netinet/tcp_output.c:524
#11 0xf0155e49 in tcp_usr_rcvd (so=0xf05e1700, flags=0)
    at ../../netinet/tcp_usrreq.c:328
#12 0xf012b10f in soreceive (so=0xf05e1700, paddr=0x0, uio=0xefbfff30, 
    mp0=0x0, controlp=0x0, flagsp=0x0) at ../../kern/uipc_socket.c:794
#13 0xf011d48b in soo_read (fp=0xf05da0c0, uio=0xefbfff30, cred=0xf05e0c80)
    at ../../kern/sys_socket.c:70
#14 0xf011a681 in read (p=0xf04e5600, uap=0xefbfff94, retval=0xefbfff84)
    at ../../kern/sys_generic.c:116
#15 0xf018d916 in syscall (frame={tf_es = 39, tf_ds = -272695257, 
      tf_edi = -272641176, tf_esi = -272649484, tf_ebp = -272641292, 
      tf_isp = -272629788, tf_ebx = 3, tf_edx = 0, tf_ecx = 3, tf_eax = 3, 
      tf_trapno = 0, tf_err = 7, tf_eip = 134956065, tf_cs = 31, 
      tf_eflags = 514, tf_esp = -272649524, tf_ss = 39})
    at ../../i386/i386/trap.c:890
...
(kgdb) p mb_freep/32
$1 = 152

>>`up'ing to the panic shows:
#10 0xf0154591 in tcp_output (tp=0xf05e1600) at ../../netinet/tcp_output.c:524
(kgdb) p m
$2 = (struct mbuf *) 0xf0344800

>>Looking back through the saved mbuf handling shows that it was allocated
>>in mb_frees[149] and there has been no intervening free:
(kgdb) p mb_frees[151]
$3 = {mf_mbuf = 0xf0344900, mf_eip = 0xf0128f26, mf_retn = 0xf019d59c, 
  mf_ret2 = 0xf019cae0, mf_ret3 = 0xf018478e, mf_ret4 = 0xf01040ca, 
  mf_ret5 = 0xf010419a, mf_ret6 = 0xf0101ecf}
(kgdb) p mb_frees[150]
$4 = {mf_mbuf = 0xf0344a00, mf_eip = 0xf0128f26, mf_retn = 0xf019d59c, 
  mf_ret2 = 0xf019cae0, mf_ret3 = 0xf018478e, mf_ret4 = 0xf01040ca, 
  mf_ret5 = 0xf010419a, mf_ret6 = 0xf0101ecf}
(kgdb) p mb_frees[149]
$5 = {mf_mbuf = 0xf0344800, mf_eip = 0xf0128f26, mf_retn = 0xf019d59c, 
  mf_ret2 = 0xf019cae0, mf_ret3 = 0xf018478e, mf_ret4 = 0xf0155e49, 
  mf_ret5 = 0xf012b10f, mf_ret6 = 0xf011d48b}

Entry 149
$6 = {
  mf_mbuf = 0xf0344800, 
  mf_eip = 0xf0128f26 is in m_devget (../../kern/uipc_mbuf.c:769).
769	MGETHDR(m, M_DONTWAIT, MT_DATA);
  mf_retn = 0xf019d59c is in lpintr (../../i386/isa/lpt.c:1158).
1158	top = m_devget(sc->sc_ifbuf + LPIPHDRLEN, len, 0, &sc->sc_if, 0);
  mf_ret2 = 0xf019cae0 is in lptintr (../../i386/isa/lpt.c:771).
770	lpintr(unit);

  mf_ret3 = 0xf018478e is in Xresume7
  mf_ret4 = 0xf0155e49 is in tcp_usr_rcvd (../../netinet/tcp_usrreq.c:328).
328	tcp_output(tp);
  mf_ret5 = 0xf012b10f is in soreceive (../../kern/uipc_socket.c:794).
794	(*pr->pr_usrreqs->pru_rcvd)(so, flags);
  mf_ret6 = 0xf011d48b is in soo_read (../../kern/sys_socket.c:72).
70	return (soreceive((struct socket *)fp->f_data, (struct mbuf **)0,
}

I'm uncertain how the above problem comes about.

The `page fault in kernel mode' panic is caused by the deliberately
corrupted mbuf.m_data field.  The panic was reported as a reference to
0x700a0000, indicating mb_frees[10] contained the relevant mbuf_free.

>> Partial backtrace:
#16 0xf018d0f9 in trap_pfault (frame=0xefbffe24, usermode=0)
    at ../../i386/i386/trap.c:653
#17 0xf018cd1b in trap (frame={tf_es = 16, tf_ds = 16, tf_edi = 440, 
      tf_esi = 0, tf_ebp = -272630152, tf_isp = -272630196, 
      tf_ebx = -265008896, tf_edx = 1073610751, tf_ecx = -265008896, 
      tf_eax = 1879703552, tf_trapno = 12, tf_err = -262537216, 
      tf_eip = -267068138, tf_cs = -1476395000, tf_eflags = 66050, 
      tf_esp = -265008896, tf_ss = 0}) at ../../i386/i386/trap.c:311
#18 0xf014dd16 in ip_input (m=0xf0344900) at ../../netinet/ip_input.c:260
#19 0xf014e2d6 in ipintr () at ../../netinet/ip_input.c:585
#20 0xf0184db9 in swi_net_next ()
#21 0xf011d48b in soo_read (fp=0xf05a7740, uio=0xefbfff30, cred=0xf05a4280)
    at ../../kern/sys_socket.c:70
#22 0xf011a681 in read (p=0xf04df600, uap=0xefbfff94, retval=0xefbfff84)
    at ../../kern/sys_generic.c:116
#23 0xf018d916 in syscall (frame={tf_es = -272695257, tf_ds = -272695257, 
      tf_edi = -272641164, tf_esi = -272649472, tf_ebp = -272641280, 
      tf_isp = -272629788, tf_ebx = 3, tf_edx = 0, tf_ecx = 3, tf_eax = 3, 
      tf_trapno = 7, tf_err = 7, tf_eip = 134956065, tf_cs = 31, 
      tf_eflags = 514, tf_esp = -272649512, tf_ss = 39})
    at ../../i386/i386/trap.c:890

Entry 10
$1 = {
  mf_mbuf = 0xf0344900, 
  mf_eip = 0xf0127957 is in m_freem (../../kern/uipc_mbuf.c:297).
297	MFREE(m, n);
  mf_retn = 0xf019dd5d is in lpoutput (../../i386/isa/lpt.c:1361).
1361	m_freem(m);
  mf_ret2 = 0xf014fa70 is in ip_output (../../netinet/ip_output.c:386).
386	error = (*ifp->if_output)(ifp, m,
  mf_ret3 = 0xf01549ac is in tcp_output (../../netinet/tcp_output.c:697).
694	error = ip_output(m, tp->t_inpcb->inp_options, &tp->t_inpcb->inp_route,
  mf_ret4 = 0xf0155e49 is in tcp_usr_rcvd (../../netinet/tcp_usrreq.c:328).
328	tcp_output(tp);
  mf_ret5 = 0xf012b10f is in soreceive (../../kern/uipc_socket.c:794).
794	(*pr->pr_usrreqs->pru_rcvd)(so, flags);
  mf_ret6 = 0xf011d48b is in soo_read (../../kern/sys_socket.c:72).
70	return (soreceive((struct socket *)fp->f_data, (struct mbuf **)0,
}

Entry 11
$2 = {
  mf_mbuf = 0xf0344900, 
  mf_eip = 0xf0128f26 is in m_devget (../../kern/uipc_mbuf.c:769).
769	MGETHDR(m, M_DONTWAIT, MT_DATA);
  mf_retn = 0xf019d59c is in lpintr (../../i386/isa/lpt.c:1158).
1158	top = m_devget(sc->sc_ifbuf + LPIPHDRLEN, len, 0, &sc->sc_if, 0);
  mf_ret2 = 0xf019cae0 is in lptintr (../../i386/isa/lpt.c:771).
770	lpintr(unit);
  mf_ret3 = 0xf018478e is in Xresume7
  mf_ret4 = 0xf01b651c is in sccnputc (../../i386/isa/syscons.c:1692).
1692	kernel_console = scp->term;
  mf_ret5 = 0xf017eee0 is in cnputc (../../i386/i386/cons.c:422).
420	(*cn_tab->cn_putc)(cn_tab->cn_dev, c);
  mf_ret6 = 0xf01190b3 is in putchar (../../kern/subr_prf.c:300).
299	(*v_putc)(c);
}

Entry 10 shows that the mbuf in question was correctly freed after the
contents were written in lpoutput().  A quick check back up the
calling sequence shows no obvious bugs.  Entry 11 shows that the same
mbuf was re-allocated by lpintr() when receiving a packet.  Since
MGETHDR() correctly initialises the mbuf.m_data field, the problem is
not obvious.


To Unsubscribe: send mail to majordomo@FreeBSD.org
with "unsubscribe freebsd-bugs" in the body of the message



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?199803222045.HAA16588>