NetBSD Problem Report #46826

From campbell@mumble.net  Wed Aug 22 21:09:31 2012
Return-Path: <campbell@mumble.net>
Received: from mail.netbsd.org (mail.netbsd.org [149.20.53.66])
	by www.NetBSD.org (Postfix) with ESMTP id 1FA4963B85F
	for <gnats-bugs@gnats.NetBSD.org>; Wed, 22 Aug 2012 21:09:31 +0000 (UTC)
Message-Id: <20120822210929.7639698026@pluto.mumble.net>
Date: Wed, 22 Aug 2012 21:09:29 +0000 (UTC)
From: Taylor R Campbell <campbell+netbsd@mumble.net>
Reply-To: Taylor R Campbell <campbell+netbsd@mumble.net>
To: gnats-bugs@gnats.NetBSD.org
Subject: C-A-ESC to enter ddb with ukbd triggers uhci mutex_owned kassert
X-Send-Pr-Version: 3.95

>Number:         46826
>Category:       kern
>Synopsis:       C-A-ESC to enter ddb with ukbd triggers uhci mutex_owned kassert
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    mrg
>State:          closed
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Wed Aug 22 21:10:00 +0000 2012
>Closed-Date:    Thu Aug 18 07:37:09 +0000 2016
>Last-Modified:  Thu Aug 18 07:37:09 +0000 2016
>Originator:     Taylor R Campbell <campbell+netbsd@mumble.net>
>Release:        NetBSD 6.99.10
>Organization:
>Environment:
System: NetBSD oberon.local 6.99.10 NetBSD 6.99.10 (RIAKERN) #0: Wed Aug 22 14:53:56 UTC 2012  root@oberon.local:/home/riastradh/netbsd/current/obj.i386/sys/arch/i386/compile/RIAKERN i386
Architecture: i386
Machine: i386
>Description:

	I booted my MacBook1,1 into a kernel from a day or two ago and
	typed C-A-ESC to make sure ddb works, only to be confronted by
	(ten-fingered copy pasta error alert):

fatal breakpoint trap in supervisor mode
trap type 1 code 0 eip c026c5f4 cs 8 eflags 292 cr2 0 ilevel 6 esp daacdbd0
curlwp 0xc31ec540 pid 0 lid 5 lowest kstack 0xdaacb000
Stopped in pid 0.5 (system) at  netbsd:breakpoint+0x4:  popl    %ebp
db{0}> panic: kernel diagnostic assertion "mutex_owned(&sc->sc_lock)" failed: file "/home/riastradh/netbsd/current/src/sys/dev/usb/uhci.c", line 1508
fatal breakpoint trap in supervisor mode
trap type 1 code 0 eip c026c5f4 cs 8 eflags 292 cr2 0 ilevel 8 esp daacd6d4
curlwp 0xc31ec540 pid 0 lid 5 lowest kstack 0xdaacb000
Stopped in pid 0.5 (system) at  netbsd:breakpoint+0x4:  popl    %ebp
db{0}> bt
breakpoint(c0c6a983,c0da46e0,c0bba7ec,daacd700,c0dae060,18,5,3e,2,0) at netbsd:breakpoint+0x4
vpanic(c0bba7ec,daacd700,5,6,1,1,daacd754,c089bbc5,c0bba7ec,c0bba99d) at netbsd:vpanic+0x1e2
kern_assert(c0bba7ec,c0bba99d,c0bdc0fa,c0c5f57c,5e4,0,daacd744,c0597c62,c31e9b80,1) at netbsd:kern_assert+0x23
uhci_idone(c34e630c,16e4,4,a,3e,0,d,c06a8e63,c0c91e00,c0eea000) at netbsd:uhci_idone+0x242
uhci_softintr(c36c8004,20a0,2,1,3,daacd824,c36c8000,20a2,0,1) at netbsd:uhci_softintr+0x1ba
uhci_intr1(c36825c,20a0,2,20,3,1,c0eea000,c0c91e00,c37e1600,daacd888) at netbsd:uhci_intr1+0x13b
uhci_poll(c36c8004,8,daacd864,c094bc02,c0c91e00,c0eea000,daacd888,0,0,4) at netbsd:uhci_poll+0x7f
ukbd_cngetc(c37e1600,daacd888,daacd884,c0bd5dfc,daacd8c0,6,daacd8b4,c028f8ed,c0d06060,daacd988) at netbsd:ukbd_cngetc+0x6e
wskbd_cngetc(2f00,0,daacd8d4,c0d06060,daacd998,0,daacd924,c028dd28,c0bd5dfc,0) at netbsd:wskbd_cngetc+0xb0
cngetc(c0bd5dfc,0,daacd8f4,c026c5f4,c026c5f5,c026c5f5,daacd974,c028c835,c06a983,c0bd5d49) at netbsd:cngetc+0x1f
db_readline(c0d06060,78,c026c5f0,c0c24c68,daacd980,0,daacd994,c028bdd1,daacd970,10) at netbsd:db_readline+0x4e
db_read_line(daacd970,10,0,33fd0d91,daacd980,0,daacd994,0,0,0) at netbsd:db_read_line+0x1a
db_command_loop(c026c5f4,0,5,c0cecd1d,c37e1600,1,1,b9d2dc,daacdb30,6) at netbsd:db_command_loop+0xb6
db_trap(1,0,0,7,0,a,0,daacd9f4,c0da47e6,2) at netbsd:db_trap+0xe0
kdb_trap(1,0,daacdb30,5,daacb000,292,0,6,daacdbd0,10000000) at netbsd:kdb_trap+0x1a
trap() at netbsd:trap+0x2d4
--- trap (number 1) ---
breakpoint(c37e1600,d,c377fea0,c059726b,c3107f80,c365ba00,c377fea0,c0597c62,c3107f80,2) at netbsd:breakpoint+0x4
wskbd_translate(c37e2400,1,daacdbf0,c058da6b,c365a2c0,c0c92680,daacdc30,c095bb14,c365a2c0,0) at netbsd:wskbd_translate+0xb57
wskbd_input(c37e2400,2,29,c3107f80,0,0,c36c8cc0,c3751408,5,2) at netbsd:wskbd_input+0xb8
ukbd_decode(c37e1600,0,0,0,0,0,0,0,c08bb877,c0d72b24) at netbsd:ukbd_decode+0x292
callout_softclock(0,c058af14,daac3074,c0100310,ec9000,ed2000,0,c0100307,0,0) at netbsd:callout_softclock+0x346
softint_dispatch(c31ecd20,2,0,0,0,0,daacdd90,daacdd28,c31ec540,0) at netbsd:softint_dispatch+0xba
fatal page fault in supervisor mode
trap type 6 code 0 eip c028f6a6 cs 8 eflags 10246 cr2 36 ilevel 8 esp daacce28
curlwp 0xc31ec540 pid 0 lid 5 lowest kstack 0xdaacb000
kernel: supervisor trap page fault, code=0
Faulted in DDB; continuting...
db{0}>

>How-To-Repeat:

	Enter ddb with C-A-ESC on a ukbd, perhaps.

>Fix:

	Yes, please!  mrg provisionally approved the following patch to
	sys/dev/usb/uhci.c, which I shall commit if it works when I
	test it later, but he said there's a deeper problem to address:

Index: uhci.c
===================================================================
RCS file: /cvsroot/src/sys/dev/usb/uhci.c,v
retrieving revision 1.249
diff -p -u -r1.249 uhci.c
--- uhci.c	24 Jun 2012 10:06:34 -0000	1.249
+++ uhci.c	22 Aug 2012 21:07:12 -0000
@@ -1505,7 +1505,7 @@ uhci_idone(uhci_intr_info_t *ii)
 	u_int32_t status = 0, nstatus;
 	int actlen;

-	KASSERT(mutex_owned(&sc->sc_lock));
+	KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock));

 	DPRINTFN(12, ("uhci_idone: ii=%p\n", ii));
 #ifdef DIAGNOSTIC

>Release-Note:

>Audit-Trail:

Responsible-Changed-From-To: kern-bug-people->mrg
Responsible-Changed-By: mrg@NetBSD.org
Responsible-Changed-When: Thu, 23 Aug 2012 07:04:07 +0000
Responsible-Changed-Why:
i'll own this.  the reason i told Taylor this is a little more comple
than normal is that one of the call-paths into here comes via the
hardware interrupt, which hs sc_intr_lock held, not sc_lock.  this
looks to be a relatively evil bug in usbmp.


From: David Holland <dholland-bugs@netbsd.org>
To: gnats-bugs@netbsd.org
Cc: 
Subject: Re: kern/46826: C-A-ESC to enter ddb with ukbd triggers uhci
 mutex_owned kassert
Date: Sun, 6 Jan 2013 23:25:41 +0000

 (sent to the wrong address)

    ------

 From: Christos Zoulas <christos@astron.com>
 To: gnats@netbsd.org
 Subject: PR/46826
 Date: Sun,  6 Jan 2013 18:02:44 +0000 (UTC)


 The following patch avoids the KASSERTS, but the keyboard is unresponsive.

 christos

 Index: uhci.c
 ===================================================================
 RCS file: /cvsroot/src/sys/dev/usb/uhci.c,v
 retrieving revision 1.251
 diff -u -p -u -r1.251 uhci.c
 --- uhci.c	5 Jan 2013 23:34:18 -0000	1.251
 +++ uhci.c	6 Jan 2013 17:50:30 -0000
 @@ -1503,14 +1503,14 @@ uhci_idone(uhci_intr_info_t *ii)
  	u_int32_t status = 0, nstatus;
  	int actlen;

 -	KASSERT(mutex_owned(&sc->sc_lock));
 +	KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock));

  	DPRINTFN(12, ("uhci_idone: ii=%p\n", ii));
  #ifdef DIAGNOSTIC
  	{
  		/* XXX SMP? */
  		int s = splhigh();
 -		if (ii->isdone) {
 +		if (!sc->sc_bus.use_polling && ii->isdone) {
  			splx(s);
  #ifdef UHCI_DEBUG
  			printf("uhci_idone: ii is done!\n   ");
 @@ -1624,7 +1624,7 @@ uhci_idone(uhci_intr_info_t *ii)

   end:
  	usb_transfer_complete(xfer);
 -	KASSERT(mutex_owned(&sc->sc_lock));
 +	KASSERT(sc->sc_bus.use_polling || mutex_owned(&sc->sc_lock));
  	DPRINTFN(12, ("uhci_idone: ii=%p done\n", ii));
  }

 @@ -3007,6 +3007,8 @@ uhci_device_intr_done(usbd_xfer_handle x

  	DPRINTFN(5, ("uhci_device_intr_done: length=%d\n", xfer->actlen));

 +	if (sc->sc_bus.use_polling)
 +		return;
  	KASSERT(mutex_owned(&sc->sc_lock));

  	npoll = upipe->u.intr.npoll;
 Index: usbdi.c
 ===================================================================
 RCS file: /cvsroot/src/sys/dev/usb/usbdi.c,v
 retrieving revision 1.142
 diff -u -p -u -r1.142 usbdi.c
 --- usbdi.c	5 Jan 2013 23:34:20 -0000	1.142
 +++ usbdi.c	6 Jan 2013 17:50:30 -0000
 @@ -787,12 +787,11 @@ usb_transfer_complete(usbd_xfer_handle x
  	int erred = xfer->status == USBD_CANCELLED ||
  	    xfer->status == USBD_TIMEOUT;
  	int repeat, polling;
 +	kmutex_t *lock;

  	DPRINTFN(5, ("usb_transfer_complete: pipe=%p xfer=%p status=%d "
  		     "actlen=%d\n", pipe, xfer, xfer->status, xfer->actlen));

 -	KASSERT(pipe->device->bus->lock == NULL || mutex_owned(pipe->device->bus->lock));
 -
  #ifdef DIAGNOSTIC
  	if (xfer->busy_free != XFER_ONQU) {
  		printf("usb_transfer_complete: xfer=%p not busy 0x%08x\n",
 @@ -806,11 +805,17 @@ usb_transfer_complete(usbd_xfer_handle x
  		return;
  	}
  #endif
 -	repeat = pipe->repeat;
  	polling = pipe->device->bus->use_polling;
  	/* XXXX */
 -	if (polling)
 +	if (polling) {
  		pipe->running = 0;
 +		lock = pipe->device->bus->lock;
 +		pipe->device->bus->lock = NULL;
 +	} else
 +		lock = NULL;
 +
 +	KASSERT(pipe->device->bus->lock == NULL || mutex_owned(pipe->device->bus->lock));
 +	repeat = pipe->repeat;

  	if (!(xfer->flags & USBD_NO_COPY) && xfer->actlen != 0 &&
  	    usbd_xfer_isread(xfer)) {
 @@ -892,6 +897,8 @@ usb_transfer_complete(usbd_xfer_handle x
  		else
  			usbd_start_next(pipe);
  	}
 +	if (lock)
 +		pipe->device->bus->lock = lock;
  }

  /* Called with USB lock held. */

State-Changed-From-To: open->feedback
State-Changed-By: skrll@NetBSD.org
State-Changed-When: Sun, 08 Sep 2013 06:45:18 +0000
State-Changed-Why:
Is this fixed now?


From: "Nick Hudson" <skrll@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/46826 CVS commit: src/sys/dev/usb
Date: Sun, 8 Sep 2013 06:37:23 +0000

 Module Name:	src
 Committed By:	skrll
 Date:		Sun Sep  8 06:37:23 UTC 2013

 Modified Files:
 	src/sys/dev/usb: uhci.c

 Log Message:
 Add sc->sc_bus.use_polling || to a couple of KASSERTs

 PR/46826


 To generate a diff of this commit:
 cvs rdiff -u -r1.258 -r1.259 src/sys/dev/usb/uhci.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

State-Changed-From-To: feedback->closed
State-Changed-By: skrll@NetBSD.org
State-Changed-When: Thu, 18 Aug 2016 07:37:09 +0000
State-Changed-Why:
Taylor is happy to close.


>Unformatted:

Home	PR Database Search