From owner-freebsd-bugs@FreeBSD.ORG Wed Feb 25 18:20:14 2004 Return-Path: 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 A72DE16A4CF for ; Wed, 25 Feb 2004 18:20:14 -0800 (PST) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id 9F08A43D2F for ; Wed, 25 Feb 2004 18:20:14 -0800 (PST) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) i1Q2KEbv011693 for ; Wed, 25 Feb 2004 18:20:14 -0800 (PST) (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.12.10/8.12.10/Submit) id i1Q2KE4W011692; Wed, 25 Feb 2004 18:20:14 -0800 (PST) (envelope-from gnats) Resent-Date: Wed, 25 Feb 2004 18:20:14 -0800 (PST) Resent-Message-Id: <200402260220.i1Q2KE4W011692@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, Toni Andjelkovic Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 87EC216A4CE for ; Wed, 25 Feb 2004 18:12:30 -0800 (PST) Received: from shaft.soth.at (door.soth.at [80.110.102.19]) by mx1.FreeBSD.org (Postfix) with ESMTP id 7B22C43D39 for ; Wed, 25 Feb 2004 18:12:29 -0800 (PST) (envelope-from toni@shaft.soth.at) Received: from shaft.soth.at (localhost [127.0.0.1]) by shaft.soth.at (8.12.10/8.12.10) with ESMTP id i1Q2BqvW001149; Thu, 26 Feb 2004 03:11:52 +0100 (CET) (envelope-from toni@shaft.soth.at) Received: (from toni@localhost) by shaft.soth.at (8.12.10/8.12.10/Submit) id i1Q2BqZr001148; Thu, 26 Feb 2004 03:11:52 +0100 (CET) (envelope-from toni) Message-Id: <200402260211.i1Q2BqZr001148@shaft.soth.at> Date: Thu, 26 Feb 2004 03:11:52 +0100 (CET) From: Toni Andjelkovic To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 Subject: kern/63375: Unplugging USB devices panics RELENG_5_2 via devfs vnops X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 26 Feb 2004 02:20:14 -0000 >Number: 63375 >Category: kern >Synopsis: Unplugging USB devices panics RELENG_5_2 via devfs vnops >Confidential: no >Severity: critical >Priority: high >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Wed Feb 25 18:20:14 PST 2004 >Closed-Date: >Last-Modified: >Originator: Toni Andjelkovic >Release: FreeBSD 5.2.1-RELEASE i386 >Organization: >Environment: System: FreeBSD shaft.soth.at 5.2.1-RELEASE FreeBSD 5.2.1-RELEASE #0: Thu Feb 26 01:18:13 CET 2004 toni@kiste.soth.at:/usr/src/sys/i386/compile/GENERIC i386 >Description: Several devfs vnode functions (devfs_getattr, devfs_setattr, devfs_access, possibly others) may cause panics by dereferencing NULL pointers produced by devfs_populate. >How-To-Repeat: 1. Plug in a USB device. I tested with ugen (smartcard reader, webcam) and ums (mouse). 2. Run the following script: #!/usr/local/bin/python import os, time fd = os.open("/dev/ugen0", os.O_RDONLY) while 1: print os.fstat(fd) time.sleep(1) 3. Unplug the USB device. 4. From another window, enter "ls `tty`" or do anything else that invokes devfs_lookup or devfs_readdir - log in with ssh, ... 5. Fatal trap 12: page fault while in kernel mode. in >Fix: Maybe the devfs vnop functions should return ENXIO if ap->a_vp->v_data is NULL. The error would be returned to the user process, where it can be handled appropriately. When the user process closes the descriptor for ugen0, vp->v_usecount becomes 0 and the vnode goes to the vnode_free_list via devfs_reclaim. Index: fs/devfs/devfs_vnops.c =================================================================== RCS file: /home/ncvs/src/sys/fs/devfs/devfs_vnops.c,v retrieving revision 1.67 diff -u -r1.67 devfs_vnops.c --- fs/devfs/devfs_vnops.c 20 Oct 2003 15:08:10 -0000 1.67 +++ fs/devfs/devfs_vnops.c 25 Feb 2004 23:43:42 -0000 @@ -183,6 +183,8 @@ int error; de = vp->v_data; + if (!de) + return (ENXIO); if (vp->v_type == VDIR) de = de->de_dir; @@ -216,6 +218,8 @@ dev_t dev; de = vp->v_data; + if (!de) + return (ENXIO); if (vp->v_type == VDIR) de = de->de_dir; bzero((caddr_t) vap, sizeof(*vap)); @@ -747,6 +751,8 @@ } de = vp->v_data; + if (!de) + return (ENXIO); if (vp->v_type == VDIR) de = de->de_dir; Analysis: When a USB device is removed, the corresponding USB_DETACH driver function is called. This function calls destroy_dev, which calls devfs_destroy, which nulls out the device's dev_t in the array devfs_inot: # --- (gdb) break devfs_destroy Breakpoint 1 at 0xc05effff: file ../../../fs/devfs/devfs_devs.c, line 434. (gdb) c Continuing. # unplug the USB device Breakpoint 1, devfs_destroy (dev=0xc2083600) at ../../../fs/devfs/devfs_devs.c:434 434 ino = dev->si_inode; (gdb) bt #0 devfs_destroy (dev=0xc2083600) at ../../../fs/devfs/devfs_devs.c:434 #1 0xc061ba0a in destroy_dev (dev=0xc2083600) at ../../../kern/kern_conf.c:464 #2 0xc05cea4f in ugen_detach (self=0xc2083600) at ../../../dev/usb/ugen.c:908 #3 0xc0655df6 in device_detach (dev=0xc20f8f00) at device_if.h:48 #4 0xc0655145 in device_delete_child (dev=0xc2083600, child=0xc20f8f00) at ../../../kern/subr_bus.c:1037 #5 0xc05df644 in usb_disconnect_port (up=0xc20473b0, parent=0xc2083600) at ../../../dev/usb/usb_subr.c:1374 #6 0xc05d4cb3 in uhub_explore (dev=0xc2047500) at ../../../dev/usb/uhub.c:428 #7 0xc05dce45 in usb_discover (v=0xc2019700) at ../../../dev/usb/usb.c:716 #8 0xc05dc848 in usb_event_thread (arg=0xc2019700) at ../../../dev/usb/usb.c:409 #9 0xc0628a84 in fork_exit (callout=0xc05dc7e0 , arg=0xc2083600, frame=0xc2083600) at ../../../kern/kern_fork.c:793 (gdb) p dev->si_name $1 = 0xc2083690 "ugen0" (gdb) p dev->si_usecount $2 = 1 (gdb) p devfs_inot[dev->si_inode] $3 = 0xc2083600 (gdb) p dev->si_inode $4 = 91 (gdb) break ../../../fs/devfs/devfs_devs.c:442 Breakpoint 2 at 0xc05f0049: file ../../../fs/devfs/devfs_devs.c, line 442. (gdb) c Continuing. Breakpoint 2, devfs_destroy (dev=0xc2083600) at ../../../fs/devfs/devfs_devs.c:442 442 if (ino < i) (gdb) p devfs_inot[dev->si_inode] $5 = 0x0 (gdb) del br 2 (gdb) c Continuing. Breakpoint 1, devfs_destroy (dev=0xc20d3300) at ../../../fs/devfs/devfs_devs.c:434 434 ino = dev->si_inode; (gdb) p dev->si_name $6 = 0xc20d3390 "ugen0.2" (gdb) p dev->si_usecount $7 = 0 (gdb) p dev->si_inode $8 = 88 (gdb) c Continuing. Breakpoint 1, devfs_destroy (dev=0xc20d3100) at ../../../fs/devfs/devfs_devs.c:434 434 ino = dev->si_inode; (gdb) p dev->si_name $9 = 0xc20d3190 "ugen0.4" (gdb) p dev->si_usecount $10 = 0 (gdb) p dev->si_inode $11 = 89 # --- In the trace above, devfs_destroy is being called three times, once for each devfs file. ugen devices usually create several devfs files - one for the control endpoint (ugen0) and one for each device endpoint (ugen0.2 and ugen0.4). All of these are destroyed on detach of the driver. Now that the devices are destroyed, the corresponding dev_t entries in devfs_inot contain NULL. This is an important detail because devfs_populate makes a decision based on it: # --- (gdb) del br 1 (gdb) br ../../../fs/devfs/devfs_devs.c:314 Breakpoint 3 at 0xc05efc82: file ../../../fs/devfs/devfs_devs.c, line 314. (gdb) c Continuing. # An unrelated stat() call on /dev/ad0s1a Breakpoint 3, devfs_populate (dm=0xc20ae680) at ../../../fs/devfs/devfs_devs.c:314 314 de->de_vnode->v_data = NULL; (gdb) bt #0 devfs_populate (dm=0xc20ae680) at ../../../fs/devfs/devfs_devs.c:314 #1 0xc05f1b1e in devfs_lookupx (ap=0xc20fd180) at ../../../fs/devfs/devfs_vnops.c:356 #2 0xc05f1feb in devfs_lookup (ap=0xc95adb90) at ../../../fs/devfs/devfs_vnops.c:450 #3 0xc0692632 in lookup (ndp=0xc95adc28) at vnode_if.h:52 #4 0xc069201e in namei (ndp=0xc95adc28) at ../../../kern/vfs_lookup.c:183 #5 0xc069f8d2 in stat (td=0xc2029c80, uap=0xc95add14) at ../../../kern/vfs_syscalls.c:1994 #6 0xc07f8cd0 in syscall (frame= {tf_fs = 47, tf_es = 47, tf_ds = 47, tf_edi = 672328506, tf_esi = 672398144, tf_ebp = -1077942936, tf_isp = -916791948, tf_ebx = 672383264, tf_edx = -1077943232, tf_ecx = 672398152, tf_eax = 188, tf_trapno = 12, tf_err = 2, tf_eip = 671876239, tf_cs = 31, tf_eflags = 582, tf_esp = -1077943556, tf_ss = 47}) at ../../../i386/i386/trap.c:1010 #7 0xc07e3d3d in Xint0x80_syscall () at {standard input}:136 #8 0x280bb332 in ?? () #9 0x280bb61b in ?? () #10 0x0804a565 in ?? () #11 0x08049085 in ?? () #12 0x08048e22 in ?? () (gdb) p 0xc95add14 $12 = 3378175252 (gdb) pt 0xc95add14 type = unsigned int (gdb) frame 5 #5 0xc069f8d2 in stat (td=0xc2029c80, uap=0xc95add14) at ../../../kern/vfs_syscalls.c:1994 1994 if ((error = namei(&nd)) != 0) (gdb) p *uap $13 = {path_l_ = 0xc95add14 "@û\023(ðä¿¿\003", path = 0x2813fb40 "/dev/ad0s1a", path_r_ = 0xc95add18 "ðä¿¿\003", ub_l_ = 0xc95add18 "ðä¿¿\003", ub = 0xbfbfe4f0, ub_r_ = 0xc95add1c "\003"} (gdb) frame 0 #0 devfs_populate (dm=0xc20ae680) at ../../../fs/devfs/devfs_devs.c:314 314 de->de_vnode->v_data = NULL; (gdb) list *$eip 0xc05efc82 is in devfs_populate (../../../fs/devfs/devfs_devs.c:314). 309 if (dev == NULL && de != NULL) { 310 dd = de->de_dir; 311 *dep = NULL; 312 TAILQ_REMOVE(&dd->de_dlist, de, de_list); 313 if (de->de_vnode) 314 de->de_vnode->v_data = NULL; 315 FREE(de, M_DEVFS); 316 devfs_dropref(i); 317 continue; 318 } (gdb) p *de->de_vnode->v_un->vu_spec->vu_cdev $16 = {si_flags = 0, si_atime = {tv_sec = 1077744672, tv_nsec = 132892000}, si_ctime = {tv_sec = 1077744672, tv_nsec = 132892000}, si_mtime = { tv_sec = 1077744672, tv_nsec = 132892000}, si_udev = 29184, si_hash = { le_next = 0x0, le_prev = 0xc091c72c}, si_hlist = {slh_first = 0xc2258d34}, si_children = {lh_first = 0x0}, si_siblings = {le_next = 0x0, le_prev = 0x0}, si_parent = 0x0, si_inode = 0, si_name = 0xc2083690 "ugen0", si_drv1 = 0x0, si_drv2 = 0x0, si_devsw = 0x0, si_iosize_max = 65536, si_stripesize = 0, si_stripeoffset = 0, si_uid = 0, si_gid = 5, si_mode = 420, si_usecount = 1, __si_u = {__si_tty = { __sit_tty = 0x0}, __si_disk = {__sid_mountpoint = 0x0, __sid_bsize_phys = 0, __sid_bsize_best = 0, __sid_snapshots = { tqh_first = 0x0, tqh_last = 0x0}, __sid_snaplistsize = 0, __sid_snapblklist = 0x0, __sid_copyonwrite = 0}}, __si_namebuf = "ugen0", '\0' } (gdb) p de->de_vnode->v_usecount $17 = 1 (gdb) p de->de_vnode $18 = (struct vnode *) 0xc2258d34 (gdb) p de->de_vnode->v_data $19 = (void *) 0xc20f9100 (gdb) p &de->de_vnode->v_data $20 = (void **) 0xc2258ddc # --- In the dump above, devfs_populate gets called due to an unrelated lookup in devfs (here: "/dev/ad0s1a"). devfs_populate iterates over all entries in devfs_inot and checks if the dev_t is NULL. If yes, the corresponding devfs_dirent * is also cleared (devfs_devs.c:311). However, in devfs_devs.c:314, the v_data member of the dirent vnode gets overwritten with NULL, although the vnode is in use by the python process, which continuously calls fstat() on the file descriptor. This is followed by a panic in the next step: # --- (gdb) c Continuing. Program received signal SIGSEGV, Segmentation fault. devfs_getattr (ap=0xc95b0ba8) at ../../../fs/devfs/devfs_vnops.c:223 223 vap->va_uid = de->de_uid; (gdb) bt #0 devfs_getattr (ap=0xc95b0ba8) at ../../../fs/devfs/devfs_vnops.c:223 #1 0xc06a5204 in vn_stat (vp=0xc2258d34, sb=0xc95b0c78, active_cred=0xc95b0ba8, file_cred=0xc21dbc00, td=0xc2029dc0) at vnode_if.h:330 #2 0xc06a516d in vn_statfile (fp=0xc20f7cc0, sb=0xc95b0ba8, active_cred=0xc95b0ba8, td=0xc2029dc0) at ../../../kern/vfs_vnops.c:616 #3 0xc061dd19 in fstat (td=0xc2029dc0, uap=0xc20f7cc0) at ../../../sys/file.h:283 #4 0xc07f8cd0 in syscall (frame= {tf_fs = 47, tf_es = 47, tf_ds = 47, tf_edi = 5, tf_esi = 0, tf_ebp = -1077942216, tf_isp = -916779660, tf_ebx = 672356020, tf_edx = 5, tf_ecx = -1077942236, tf_eax = 189, tf_trapno = 22, tf_err = 2, tf_eip = 673621103, tf_cs = 31, tf_eflags = 582, tf_esp = -1077942260, tf_ss = 47}) at ../../../i386/i386/trap.c:1010 #5 0xc07e3d3d in Xint0x80_syscall () at {standard input}:136 #6 0x080c5d2e in ?? () #7 0x080d9d72 in ?? () #8 0x080a1345 in ?? () #9 0x0809f31f in ?? () #10 0x080a028f in ?? () #11 0x0809ccd7 in ?? () #12 0x080bc16e in ?? () #13 0x080bc116 in ?? () ---Type to continue, or q to quit--- #14 0x080bc0ce in ?? () #15 0x080bb238 in ?? () #16 0x080babdb in ?? () #17 0x08054841 in ?? () #18 0x080540e9 in ?? () #19 0x08053fe2 in ?? () (gdb) list *$eip 0xc05f16b8 is in devfs_getattr (../../../fs/devfs/devfs_vnops.c:223). 218 de = vp->v_data; 219 if (vp->v_type == VDIR) 220 de = de->de_dir; 221 bzero((caddr_t) vap, sizeof(*vap)); 222 vattr_null(vap); 223 vap->va_uid = de->de_uid; 224 vap->va_gid = de->de_gid; 225 vap->va_mode = de->de_mode; 226 if (vp->v_type == VLNK) 227 vap->va_size = de->de_dirent->d_namlen; (gdb) x/i $eip 0xc05f16b8 : mov 0x28(%edi),%eax (gdb) info reg eax 0xc95b0ba8 -916780120 ecx 0x0 0 edx 0xc206a600 -1039751680 ebx 0xc95b0ba8 -916780120 esp 0xc95b0b64 0xc95b0b64 ebp 0xc95b0b78 0xc95b0b78 esi 0xc2258d34 -1037726412 edi 0x0 0 eip 0xc05f16b8 0xc05f16b8 eflags 0x10246 66118 cs 0x8 8 ss 0x10 16 ds 0xc0850010 -1065025520 es 0xc0660010 -1067057136 fs 0x0 0 gs 0x0 0 fctrl 0x0 0 fstat 0x0 0 ftag 0x0 0 fiseg 0x0 0 fioff 0x0 0 foseg 0x0 0 fooff 0x0 0 ---Type to continue, or q to quit--- fop 0x0 0 (gdb) p vp $28 = (struct vnode *) 0xc2258d34 (gdb) p vp->v_data $29 = (void *) 0x0 (gdb) p &vp->v_data $30 = (void **) 0xc2258ddc (gdb) p vp->v_usecount $31 = 1 (gdb) p ((struct proc *) 0xc21af000)->p_fd->fd_ofiles[5]->f_vnode $32 = (struct vnode *) 0xc2258d34 # --- Since the v_data member of the devfs dirent vnode has been overwritten in the previous step, it contains NULL. However, devfs_getattr() assumes that this pointer is always valid and tries to dereference it, which results in a page fault. Several devfs vnop functions are affected by this bug, at least devfs_getattr, devfs_setattr and devfs_access. >Release-Note: >Audit-Trail: >Unformatted: