From owner-freebsd-bugs@FreeBSD.ORG Thu Aug 10 12:00:38 2006 Return-Path: X-Original-To: freebsd-bugs@hub.freebsd.org Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 49B6D16A533 for ; Thu, 10 Aug 2006 12:00:38 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id 1B9D743D58 for ; Thu, 10 Aug 2006 12:00:35 +0000 (GMT) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.13.4/8.13.4) with ESMTP id k7AC0YAW042431 for ; Thu, 10 Aug 2006 12:00:34 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.13.4/8.13.4/Submit) id k7AC0Y6G042412; Thu, 10 Aug 2006 12:00:34 GMT (envelope-from gnats) Resent-Date: Thu, 10 Aug 2006 12:00:34 GMT Resent-Message-Id: <200608101200.k7AC0Y6G042412@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, Jim Segrave Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 13D0016A4DA for ; Thu, 10 Aug 2006 11:59:07 +0000 (UTC) (envelope-from jes@jes-2.demon.nl) Received: from post-24.mail.nl.demon.net (post-24.mail.nl.demon.net [194.159.73.194]) by mx1.FreeBSD.org (Postfix) with ESMTP id 8776E43D49 for ; Thu, 10 Aug 2006 11:59:06 +0000 (GMT) (envelope-from jes@jes-2.demon.nl) Received: from jes-1.demon.nl ([83.160.144.201]:21001 helo=jes-2.demon.nl) by post-24.mail.nl.demon.net with esmtp (Exim 4.51) id 1GB9Bp-0006zn-1y for FreeBSD-gnats-submit@freebsd.org; Thu, 10 Aug 2006 11:59:05 +0000 Received: from jes by jes-2.demon.nl with local (Exim 4.34 (FreeBSD)) id 1GB9Bo-000AKi-Nk for FreeBSD-gnats-submit@freebsd.org; Thu, 10 Aug 2006 13:59:04 +0200 Message-Id: Date: Thu, 10 Aug 2006 13:59:04 +0200 From: Jim Segrave To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 Cc: Subject: kern/101752: 6.1-RELEASE kernel panic on usb device insertion X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Jim Segrave List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 10 Aug 2006 12:00:38 -0000 >Number: 101752 >Category: kern >Synopsis: 6.1-RELEASE kernel panic on usb device insertion >Confidential: no >Severity: serious >Priority: medium >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Thu Aug 10 12:00:34 GMT 2006 >Closed-Date: >Last-Modified: >Originator: Jim Segrave >Release: FreeBSD 6.1-STABLE i386 >Organization: >Environment: System: FreeBSD jes-2.demon.nl 6.1-STABLE FreeBSD 6.1-STABLE #1: Wed Aug 9 15:48:15 CEST 2006 root@jes-2.demon.nl:/usr/obj/usr/src/sys/SONY-VAIO-ZX1 i386 Source cvsupped on Aug 9 11:53 UTC Hardware: Sony VAIO PCG-Z1SP laptop running 6.1-STABLE FreeBSD, Intel 82801DB uhci USB controller, Standard Centrino based laptop with IDE hard disc and two USB ports. 512Mb Ram, running X with fvwm2, using ndis with internal wireless The offending USB device: Casio EX-Z1000 digital camera with 2GB memory card >Description: This looks more or less identical to PR usb/84326, although this is a later version of FreeBSD (that report is for 5.4). I'd upgraded to 6.1 for exactly this problem. Enabling the usb connector from the camera causes an immediate kernel panic. (The camera connects via a small docking station and you have to press a button on the docking station to enable the USB connection, simply plugging in the cable does not have any effect and it is not visible as a USB device). I first encountered this with my system running FreeBSD 5.4 Release from Sep 5 2005. Rather than spend a lot of time pursuing it, I decided to upgrade to 6.1-release. The symptoms remain unchanged. Activating the usb cable causes the system to panic instantly. The last log message (*.* is directed to /var/log/messages) was, in its entirety: Aug 10 02:18:53 jes-2 kernel: umass1: CASIO COMPUTER CASIO QV DIGITAL, rev 2.00/10.00, addr 2 Examining the core file with kgdb: Unread portion of the kernel message buffer: Fatal trap 18: integer divide fault while in kernel mode instruction pointer = 0x20:0xc06667df stack pointer = 0x28:0xd445a7b4 frame pointer = 0x28:0xd445a83c code segment = base 0x0, limit 0xfffff, type 0x1b = DPL 0, pres 1, def32 1, gran 1 processor eflags = interrupt enabled, resume, IOPL = 0 current process = 17 (swi2: cambio) trap number = 18 panic: integer divide fault (kgdb) bt #0 doadump () at pcpu.h:165 #1 0xc0542cac in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:409 #2 0xc0542f57 in panic (fmt=0xc0682eae "%s") at /usr/src/sys/kern/kern_shutdown.c:565 #3 0xc065dfa6 in trap_fatal (frame=0xd445a774, eva=0) at /usr/src/sys/i386/i386/trap.c:836 #4 0xc065db0c in trap (frame= {tf_fs = 8, tf_es = 40, tf_ds = -1066401752, tf_edi = 1, tf_esi = 0, tf_e\ bp = -733632452, tf_isp = -733632608, tf_ebx = -557797921, tf_edx = 0, tf_ecx =\ 0, tf_eax = 1, tf_trapno = 18, tf_err = 0, tf_eip = -1067030561, tf_cs = 32, t\ f_eflags = 66118, tf_esp = -1066353280, tf_ss = 0}) at /usr/src/sys/i386/i386/trap.c:631 #5 0xc065021a in calltrap () at /usr/src/sys/i386/i386/exception.s:139 #6 0xc06667df in __qdivrem (uq=Unhandled dwarf expression opcode 0x93 ) at /usr/src/sys/libkern/qdivrem.c:97 #7 0xc0666c2a in __udivdi3 (a=3737169375, b=0) at /usr/src/sys/libkern/udivdi3.c:47 #8 0xc04333a2 in cam_calc_geometry (ccg=0xd445a8e4, extended=1) at /usr/src/sys/cam/cam.c:376 #9 0xc04eccfa in umass_cam_action (sim=0xc4123980, ccb=0xd445a8e4) at /usr/src/sys/dev/usb/umass.c:2629 #10 0xc0437602 in xpt_action (start_ccb=0xd445a8e4) at /usr/src/sys/cam/cam_xpt.c:3137 #11 0xc0442ac5 in dasetgeom (periph=0x0, block_len=1, maxsector=3737169374) at /usr/src/sys/cam/scsi/scsi_da.c:1868 #12 0xc04423d6 in dadone (periph=0xc4116c00, done_ccb=0xc35ee800) at /usr/src/sys/cam/scsi/scsi_da.c:1522 #13 0xc043b1f5 in camisr (V_queue=0xc35ee800) at /usr/src/sys/cam/cam_xpt.c:7277 #14 0xc053057e in ithread_execute_handlers (p=0xc32b8a3c, ie=0xc32b1480) at /usr/src/sys/kern/kern_intr.c:682 #15 0xc05306a2 in ithread_loop (arg=0xc3322550) at /usr/src/sys/kern/kern_intr.c:765 #16 0xc052f7ec in fork_exit (callout=0xc053063c , arg=0xc3322550, frame=0xd445ad38) at /usr/src/sys/kern/kern_fork.c:805 #17 0xc065027c in fork_trampoline () at /usr/src/sys/i386/i386/exception.s:208 Going to cam_calc_geometry to have a look, I find: (kgdb) f 8 #8 0xc04333a2 in cam_calc_geometry (ccg=0xd445a8e4, extended=1) at /usr/src/sys/cam/cam.c:376 376 size_mb = ccg->volume_size / ((1024L * 1024L) / ccg->block_size\ ); (kgdb) l 371 void 372 cam_calc_geometry(struct ccb_calc_geometry *ccg, int extended) 373 { 374 uint32_t size_mb, secs_per_cylinder; 375 376 size_mb = ccg->volume_size / ((1024L * 1024L) / ccg->block_size\ ); 377 if (size_mb > 1024 && extended) { 378 ccg->heads = 255; 379 ccg->secs_per_track = 63; 380 } else { And examining ccg gives: (kgdb) p *ccg $1 = {ccb_h = {pinfo = {priority = 1, generation = 15, index = -1}, xpt_links = {le = {le_next = 0xc4123940, le_prev = 0x246}, sle = { sle_next = 0xc4123940}, tqe = {tqe_next = 0xc4123940, tqe_prev = 0x246}, stqe = {stqe_next = 0xc4123940}}, sim_links = { le = {le_next = 0xc06e3324, le_prev = 0xc104eb48}, sle = { sle_next = 0xc06e3324}, tqe = {tqe_next = 0xc06e3324, tqe_prev = 0xc104eb48}, stqe = {stqe_next = 0xc06e3324}}, periph_links = {le = {le_next = 0x8e5, le_prev = 0x4}, sle = { sle_next = 0x8e5}, tqe = {tqe_next = 0x8e5, tqe_prev = 0x4}, stqe = { stqe_next = 0x8e5}}, retry_count = 4294967295, cbfcnp = 0xc35ee800, func_code = XPT_CALC_GEOMETRY, status = 0, path = 0xc4039a20, path_id = 4, target_id = 0, target_lun = 0, flags = 0, periph_priv = {entries = {{ ptr = 0x0, field = 0, bytes = "\000\000\000"}, {ptr = 0x0, field = 0, bytes = "\000\000\000"}}, bytes = "\000\000\000\000\000\000\000"}, sim_priv = {entries = {{ ptr = 0xc411e000, field = 3289505792, bytes = "\000021}, { ptr = 0x3, field = 3, bytes = "\003\000\000"}}, bytes = "\000021003\000\000"}, timeout = 3277776896, timeout_ch = { callout = 0xc3500c00}}, block_size = 3737169374, volume_size = 3737169375, cylinders = 0, heads = 0 '\0', secs_per_track = 0 '\0'} As noted in the earlier PR, the volume and block size look like they come from unitialised memory: (kgdb) printf "%x\n%x\n", ccg->block_size, ccg->volume_size dec0adde dec0addf Interesting that 'deadc0de' has been incremented in ccg->volume_size, though probably not very useful. Going back to frame 13, camisr(), I get (kgdb) f 13 #13 0xc043b1f5 in camisr (V_queue=0xc35ee800) at /usr/src/sys/cam/cam_xpt.c:7277 7277 (*ccb_h->cbfcnp)(ccb_h->path->periph, (union ccb *)ccb_\ h); (kgdb) l 7267 if ((ccb_h->flags & CAM_DEV_QFRZDIS) 7268 && (ccb_h->status & CAM_DEV_QFRZN)) { 7269 xpt_release_devq(ccb_h->path, /*count*/1, 7270 /*run_queue*/TRUE); 7271 ccb_h->status &= ~CAM_DEV_QFRZN; 7272 } else if (runq) { 7273 xpt_run_dev_sendq(ccb_h->path->bus); 7274 } 7275 7276 /* Call the peripheral driver's callback */ 7277 (*ccb_h->cbfcnp)(ccb_h->path->periph, (union ccb *)ccb_\ h); 7278 7279 /* Raise IPL for while test */ 7280 s = splcam(); (kgdb) p *ccb_h $4 = {pinfo = {priority = 5, generation = 13, index = -1}, xpt_links = {le = { le_next = 0x0, le_prev = 0xc411e068}, sle = {sle_next = 0x0}, tqe = { tqe_next = 0x0, tqe_prev = 0xc411e068}, stqe = {stqe_next = 0x0}}, sim_links = {le = {le_next = 0x0, le_prev = 0xd445acc0}, sle = { sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xd445acc0}, stqe = { stqe_next = 0x0}}, periph_links = {le = {le_next = 0x0, le_prev = 0xdeadc0de}, sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, tqe_prev = 0xdeadc0de}, stqe = {stqe_next = 0x0}}, retry_count = 3, cbfcnp = 0xc0442010 , func_code = XPT_SCSI_IO, status = 1, path = 0xc4039a20, path_id = 4, target_id = 0, target_lun = 0, flags = 64, periph_priv = {entries = {{ptr = 0x1, field = 1, bytes = "\001\000\000"}, { ptr = 0x0, field = 0, bytes = "\000\000\000"}}, bytes = "\001\000\000\000\000\000\000"}, sim_priv = {entries = {{ ptr = 0xdeadc0de, field = 3735929054, bytes = "}, { ptr = 0xdeadc0de, field = 3735929054, bytes = "}}, bytes = "}, timeout = 5000, timeout_ch = {callout = 0x0}} ccb_h->flags is: CAM_DIR_IN = 0x00000040,/* Data direction (01:DATA IN) */ I can either provide further details from the core dump if needed or I am willing to create a kernel with CAMDEBUG and its suboptions set. Assuming the hard disc doesn't go through the cam subsystem, I can safely simply enable debugging of all busses and luns, as there are no other active USB devices on this machine. I gather that CAMDEBUG writes to the system console rather than logging to files. The Sony does not have a serial port, so I do not know how successful I will be at manually transcribing debugging output. I may be able to capture this output by ssh'ing in from another machine using script to capture the xterm on the remote machine, but I don't know if the console output will be visible there. >How-To-Repeat: Inserting the usb cable from the camera and making it active is 100% fatal (10 times out of 10, 6 under FreeBSD 5.4, 4 under FreeBSD 6.1). Another digital camera (Sony Cybershot DSC100 with a smaller memory card) works without incident. >Fix: >Release-Note: >Audit-Trail: >Unformatted: