NetBSD Problem Report #48588

From alnsn@NetBSD.org  Mon Feb 10 20:49:20 2014
Return-Path: <alnsn@NetBSD.org>
Received: by mollari.NetBSD.org (Postfix, from userid 1459)
	id 4F192A64AE; Mon, 10 Feb 2014 20:49:20 +0000 (UTC)
Message-Id: <20140210204920.4F192A64AE@mollari.NetBSD.org>
Date: Mon, 10 Feb 2014 20:49:20 +0000 (UTC)
From: alnsn@NetBSD.org
Reply-To: alnsn@NetBSD.org
To: gnats-bugs@NetBSD.org
Subject: one time crash in usb_allocmem_flags
X-Send-Pr-Version: 3.95

>Number:         48588
>Category:       kern
>Synopsis:       one time crash in usb_allocmem_flags
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Mon Feb 10 20:50:00 +0000 2014
>Last-Modified:  Thu Jun 12 18:50:00 +0000 2014
>Originator:     Alexander Nasonov
>Release:        NetBSD 6.99.28
>Organization:
	home sweet home
>Environment:
	$ ident /netbsd | grep usb
	$NetBSD: if_athn_usb.c,v 1.6 2013/10/16 18:23:39 christos Exp $
	$NetBSD: usb.c,v 1.148 2013/11/09 07:52:22 skrll Exp $
	$NetBSD: usb_mem.c,v 1.64 2013/12/22 18:29:25 mlelstv Exp $
	$NetBSD: usb_pci.c,v 1.7 2008/04/28 20:23:55 martin Exp $
	$NetBSD: usb_quirks.c,v 1.80 2013/11/14 16:33:20 nonaka Exp $
	$NetBSD: usb_subr.c,v 1.195 2013/10/03 07:35:37 skrll Exp $
	$NetBSD: usbdi.c,v 1.160 2013/11/30 12:16:14 skrll Exp $
	$NetBSD: usbdi_util.c,v 1.62 2013/09/26 07:25:31 skrll Exp $
System: NetBSD neva 6.99.28 NetBSD 6.99.28 (GENERIC) #0: Sun Jan 12 00:07:53 GMT 2014  alnsn@neva:/home/alnsn/netbsd-current/src/sys/arch/amd64/compile/obj/GENERIC amd64
Architecture: x86_64
Machine: amd64
>Description:
I was running current amd64 when I got a random crash shortly
after switching to X mode. If my analysis is correct, it crashed
in usb_allocmem_flags inside this loop:

        LIST_FOREACH(f, &usb_frag_freelist, next) {
                KDASSERTMSG(usb_valid_block_p(f->block, &usb_blk_fraglist),
                    "%s: usb frag %p: unknown block pointer %p",
                     __func__, f, f->block);
                if (f->block->tag == tag)
                        break;
        }

It couldn't access f->block->tag. I wasn't actively using any of
the usb devices at that time.

The kernel is not vanilla GENERIC. I enabled UHID_DEBUG, set
urtwn_debug to DBG_ALL and changed uts.c (touchscreen driver)
to ignore z dimension when it's not available. The full diff
is available on web site at ~alnsn/usb_allocmem_flags.diff.

crash> dmesg
...
fatal protection fault in supervisor mode
trap type 4 code 0 rip ffffffff808515e2 cs 8 rflags 13282 cr2
7f7ff5773020 ilevel 0 rsp fffffe80ca6f16c0
curlwp 0xfffffe811a8aaba0 pid 475.1 lowest kstack 0xfffffe80ca6ee000
panic: trap
cpu2: Begin traceback...
vpanic() at netbsd:vpanic+0x13e
printf_nolog() at netbsd:printf_nolog
startlwp() at netbsd:startlwp
alltraps() at netbsd:alltraps+0x9e
ehci_allocm() at netbsd:ehci_allocm+0x2c
usbd_transfer() at netbsd:usbd_transfer+0x5f
usbd_open_pipe_intr() at netbsd:usbd_open_pipe_intr+0xcb
uhidev_open() at netbsd:uhidev_open+0xb3
wsmouseopen() at netbsd:wsmouseopen+0xf3
cdev_open() at netbsd:cdev_open+0x87
spec_open() at netbsd:spec_open+0x183
VOP_OPEN() at netbsd:VOP_OPEN+0x33
vn_open() at netbsd:vn_open+0x1b0
do_open() at netbsd:do_open+0x102
do_sys_openat() at netbsd:do_sys_openat+0x68
sys_open() at netbsd:sys_open+0x24
syscall() at netbsd:syscall+0x9a
--- syscall (number 5) ---
7f7ff403af3a:
cpu2: End traceback...
rebooting in 10 9 8 7 6 5 4 3 2 1 0

crash> dmesg|grep usb
usb0 at xhci0: USB revision 2.0
usb1 at ehci0: USB revision 2.0
uhub0 at usb0: NetBSD xHCI Root Hub, class 9/0, rev 2.00/1.00, addr 0
uhub1 at usb1: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00,
addr 1
usbd_transfer() at netbsd:usbd_transfer+0x5f
usbd_open_pipe_intr() at netbsd:usbd_open_pipe_intr+0xcb

crash> x 0xffffffff808515e2
usb_allocmem_flags+0xfd:        751a3948


$ objdump -d /netbsd
...
ffffffff8085158b:       48 c7 c7 60 15 f8 80    mov    $0xffffffff80f81560,%rdi
ffffffff80851592:       e8 69 42 d3 ff          callq  ffffffff80585800 <mutex_enter>
ffffffff80851597:       48 8b 05 c2 bf 69 00    mov    0x69bfc2(%rip),%rax        # ffffffff80eed560 <usb_frag_freelist>
ffffffff8085159e:       48 85 c0                test   %rax,%rax
ffffffff808515a1:       75 3c                   jne    ffffffff808515df <usb_allocmem_flags+0xfa>

/* You don't need to look at this block */
ffffffff808515a3:       48 8d 4d c8             lea    -0x38(%rbp),%rcx
ffffffff808515a7:       45 31 c0                xor    %r8d,%r8d
ffffffff808515aa:       ba 40 00 00 00          mov    $0x40,%edx
ffffffff808515af:       be 00 10 00 00          mov    $0x1000,%esi
ffffffff808515b4:       48 89 df                mov    %rbx,%rdi
ffffffff808515b7:       e8 f4 fb ff ff          callq  ffffffff808511b0 <usb_block_allocmem>
ffffffff808515bc:       89 c3                   mov    %eax,%ebx
ffffffff808515be:       85 c0                   test   %eax,%eax
ffffffff808515c0:       75 ac                   jne    ffffffff8085156e <usb_allocmem_flags+0x89>
ffffffff808515c2:       48 8b 4d c8             mov    -0x38(%rbp),%rcx
ffffffff808515c6:       c7 41 38 00 00 00 00    movl   $0x0,0x38(%rcx)
ffffffff808515cd:       bb 40 00 00 00          mov    $0x40,%ebx
ffffffff808515d2:       31 d2                   xor    %edx,%edx
ffffffff808515d4:       eb 57                   jmp    ffffffff8085162d <usb_allocmem_flags+0x148>
/* end of block. */

/*  LIST_FOREACH(f, &usb_frag_freelist, next) { */
ffffffff808515d6:       48 8b 40 10             mov    0x10(%rax),%rax
ffffffff808515da:       48 85 c0                test   %rax,%rax
ffffffff808515dd:       74 c4                   je     ffffffff808515a3 <usb_allocmem_flags+0xbe>
ffffffff808515df:       48 8b 10                mov    (%rax),%rdx
ffffffff808515e2:       48 39 1a                cmp    %rbx,(%rdx)
ffffffff808515e5:       75 ef                   jne    ffffffff808515d6 <usb_allocmem_flags+0xf1>


crash> ps
PID    LID S CPU     FLAGS       STRUCT LWP *               NAME WAIT
475  >   1 7   2         0   fffffe811a8aaba0               Xorg
72       1 2   3   9020000   fffffe811a709b80              xinit
43       1 2   3   8020000   fffffe811a709760                 sh
437      1 2   3   8020000   fffffe811d311720                ksh
420      1 2   2   8020000   fffffe811e2b6240              getty
435      1 2   0   8020000   fffffe811e2b6a80              getty
429      1 2   3   8020000   fffffe811e2b6660              login
412      1 2   0   8020000   fffffe811e4c1220              getty
390      1 2   0   8020000   fffffe8119a90b60               cron
407      1 2   0   8020000   fffffe811d767b00              inetd
342      1 2   3   8020000   fffffe811d311300            privoxy
357      1 2   3   8020000   fffffe811c3b9b20               sshd
332  >   1 7   0   8020000   fffffe811d7812a0                tor
319      1 3   1   8020080   fffffe811d7676e0             powerd kqueue
176  >   1 7   3   8020000   fffffe811e28fac0            syslogd
126      1 3   1   8020080   fffffe811e28f280             dhcpcd select
1        1 3   1   8020080   fffffe8107acda40               init wait
0       65 3   2       200   fffffe811e28f6a0            physiod physiod
0       64 3   2       200   fffffe811e4c1640           aiodoned aiodoned
0       63 2   2       200   fffffe81074185c0            ioflush
0       62 3   2       200   fffffe811e4c1a60           pgdaemon pgdaemon
0       58 3   2       200   fffffe81074189e0               usb1 usbevt
0       57 3   2       200   fffffe8107acd200               usb0 usbevt
0       56 3   2       200   fffffe8107409a00          coretemp1 coretemp1
0       55 3   2       200   fffffe81074095e0          coretemp0 coretemp0
0       54 3   2       200   fffffe81074091c0            acpitz0 acpitz0
0       53 3   2       200   fffffe810740ba20           acpibat1 acpibat1
0       52 3   2       200   fffffe81074181a0           acpibat0 acpibat0
0       51 3   2       200   fffffe8107acd620          cryptoret crypto_w
0       50 3   2       200   fffffe810740b1e0              unpgc unpgc
0       49 3   0       200   fffffe810740b600        vmem_rehash vmem_rehash
0       40 3   0       200   fffffe81072e6180               iic0 iicintr
0       39 3   0       200   fffffe81072e65a0            atabus0 atath
0       38 3   0       200   fffffe81072e69c0         usbtask-dr usbtsk
0       37 3   0       200   fffffe81071f7160         usbtask-hc usbtsk
0       36 3   0       200   fffffe81071f7580               pms0 pmsreset
0       35 3   0       200   fffffe81071f79a0    acpiec sci thre ecsci
0       34 3   3       200   fffffe81071e5140            xcall/3 xcall
0       33 1   3       200   fffffe81071e5560          softser/3
0       32 1   3       200   fffffe81071e5980          softclk/3
0       31 1   3       200   fffffe81071e9120          softbio/3
0       30 1   3       200   fffffe81071e9540          softnet/3
0       29 1   3       201   fffffe81071e9960             idle/3
0       28 3   2       200   fffffe81071d1100            xcall/2 xcall
0       27 1   2       200   fffffe81071d1520          softser/2
0       26 1   2       200   fffffe81071d1940          softclk/2
0       25 1   2       200   fffffe81071d70e0          softbio/2
0       24 1   2       200   fffffe81071d7500          softnet/2
0       23 1   2       201   fffffe81071d7920             idle/2
0       22 3   1       200   fffffe81071bf0c0            xcall/1 xcall
0       21 1   1       200   fffffe81071bf4e0          softser/1
0       20 1   1       200   fffffe81071bf900          softclk/1
0       19 1   1       200   fffffe81071b80a0          softbio/1
0       18 1   1       200   fffffe81071b84c0          softnet/1
0    >  17 7   1       201   fffffe81071b88e0             idle/1
0       16 3   0       200   fffffe811e616080             sysmon smtaskq
0       15 3   1       200   fffffe811e6164a0         pmfsuspend pmfsuspend
0       14 3   0       200   fffffe811e6168c0           pmfevent pmfevent
0       13 3   0       200   fffffe811f527060         sopendfree sopendfr
0       12 3   3       200   fffffe811f527480           nfssilly nfssilly
0       11 3   0       200   fffffe811f5278a0            cachegc cachegc
0       10 3   0       200   fffffe811f92d040              vrele vrele
0        9 3   0       200   fffffe811f92d460             vdrain vdrain
0        8 3   0       200   fffffe811f92d880          modunload mod_unld
0        7 3   0       200   fffffe811f939020            xcall/0 xcall
0        6 1   0       200   fffffe811f939440          softser/0
0    >   5 7   0       200   fffffe811f939860          softclk/0
0        4 1   0       200   fffffe811f940000          softbio/0
0        3 1   0       200   fffffe811f940420          softnet/0
0        2 1   0       201   fffffe811f940840             idle/0
0        1 2   2       200   ffffffff80ed6800            swapper

>How-To-Repeat:
	Not repeatable.
>Fix:
	Not known.

>Audit-Trail:
From: Alexander Nasonov <alnsn@yandex.ru>
To: gnats-bugs@NetBSD.org
Cc: kern-bug-people@netbsd.org, gnats-admin@netbsd.org,
	netbsd-bugs@netbsd.org
Subject: Re: kern/48588: one time crash in usb_allocmem_flags
Date: Thu, 12 Jun 2014 19:48:01 +0100

 New data point after one more X11 lockup:

 $ crash -M netbsd.5.core  -N netbsd.5
 Crash version 6.99.43, image version 6.99.43.
 System panicked: kernel debugging assertion "usb_valid_block_p(f->block, &usb_blk_fraglist)" failed: file "/home/alnsn/netbsd-current/src/sys/dev/usb/usb_mem.c", line 318 usb_allocmem_flags: usb frag 0xffff800047770a80: unknown block pointer 0xe5d04c000010106
 Backtrace from time of crash is available.
 crash> dmesg 440
 50cb8
 panic: kernel debugging assertion "usb_valid_block_p(f->block, &usb_blk_fraglist)" failed: file "/home/alnsn/netbsd-cur
 rent/src/sys/dev/usb/usb_mem.c", line 318 usb_allocmem_flags: usb frag 0xffff800047770a80: unknown block pointer 0xe5d0
 4c000010106
 cpu3: Begin traceback...
 vpanic() at netbsd:vpanic+0x13c
 kern_assert() at netbsd:kern_assert+0x4f
 usb_allocmem_flags() at netbsd:usb_allocmem_flags+0x27c
 ehci_allocm() at netbsd:ehci_allocm+0x2a
 usbd_transfer() at netbsd:usbd_transfer+0x16b
 usbd_open_pipe_intr() at netbsd:usbd_open_pipe_intr+0xd4
 uhidev_open() at netbsd:uhidev_open+0xd9
 wsmux_do_open() at netbsd:wsmux_do_open+0x7d
 wsmuxopen() at netbsd:wsmuxopen+0xd6
 cdev_open() at netbsd:cdev_open+0xb2
 spec_open() at netbsd:spec_open+0x25d
 VOP_OPEN() at netbsd:VOP_OPEN+0x33
 vn_open() at netbsd:vn_open+0x1fe
 do_open() at netbsd:do_open+0x111
 do_sys_openat() at netbsd:do_sys_openat+0x68
 sys_open() at netbsd:sys_open+0x24
 syscall() at netbsd:syscall+0x9a
 --- syscall (number 5) ---
 7f7ff403be6a:
 cpu3: End traceback...

 dumping to dev 0,1 (offset=191719, size=1024733):
 dump

>Unformatted:
 	Source last checked out about a month ago.

NetBSD Home
NetBSD PR Database Search

(Contact us) $NetBSD: query-full-pr,v 1.39 2013/11/01 18:47:49 spz Exp $
$NetBSD: gnats_config.sh,v 1.8 2006/05/07 09:23:38 tsutsui Exp $
Copyright © 1994-2007 The NetBSD Foundation, Inc. ALL RIGHTS RESERVED.