kern/127561: panic at closing uvisor.

[KOIE Hidetaka]

>Number:         127561
>Category:       kern
>Synopsis:       panic at closing uvisor.
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Tue Sep 23 09:30:04 UTC 2008
>Closed-Date:
>Last-Modified:
>Originator:     KOIE Hidetaka
>Release:        8.0-CURRENT
>Organization:
SURIGIKEN
>Environment:
FreeBSD guriandgura 8.0-CURRENT FreeBSD 8.0-CURRENT #1: Tue Sep 23 17:45:26 JST 2008     koie at guriandgura:/usr/obj/usr/src/sys/GURIANDGURA  amd64
>Description:
I'm using pilot-xfer(/usr/ports/palm/pilot-link) via uvisor(4) to hotsync, and
/usr/sbin/ppp via /dev/cuaU0 to connect network.
Since change new TTY layer, at end of hotsync and closing ppp session, kernel panics:
guriandgura# kgdb /boot/kernel/kernel.symbols vmcore.0
GNU gdb 6.1.1 [FreeBSD]
..
Unread portion of the kernel message buffer:
ucom0: at uhub0 port 5 (addr 2) disconnected
ucom0: detached


Fatal trap 12: page fault while in kernel mode
cpuid = 2; apic id = 02
fault virtual address   = 0x134
fault code              = supervisor read data, page not present
instruction pointer     = 0x8:0xffffffff80304522
stack pointer           = 0x10:0xffffffff7fe4f890
frame pointer           = 0x10:0xffffffff7fe4f8c0
code segment            = base 0x0, limit 0xfffff, type 0x1b
                        = DPL 0, pres 1, long 1, def32 0, gran 1
processor eflags        = interrupt enabled, resume, IOPL = 0
current process         = 1808 (ppp)
..
(kgdb) bt
#0  doadump () at pcpu.h:196
#1  0xffffffff801b450c in db_fncall (dummy1=Variable "dummy1" is not available.
)
    at /usr/src/sys/ddb/db_command.c:549
#2  0xffffffff801b4a61 in db_command (last_cmdp=0xffffffff807f7d60, cmd_table=Variable "cmd_table" is not available.

) at /usr/src/sys/ddb/db_command.c:446
#3  0xffffffff801b4cb0 in db_command_loop ()
    at /usr/src/sys/ddb/db_command.c:499
#4  0xffffffff801b6a19 in db_trap (type=Variable "type" is not available.
) at /usr/src/sys/ddb/db_main.c:228
#5  0xffffffff8036a465 in kdb_trap (type=12, code=0, tf=0xffffffff7fe4f7e0)
    at /usr/src/sys/kern/subr_kdb.c:534
#6  0xffffffff8059dd2d in trap_fatal (frame=0xffffffff7fe4f7e0, eva=Variable "eva" is not available.
)
    at /usr/src/sys/amd64/amd64/trap.c:754
#7  0xffffffff8059e104 in trap_pfault (frame=0xffffffff7fe4f7e0, usermode=0)
    at /usr/src/sys/amd64/amd64/trap.c:675
#8  0xffffffff8059ea69 in trap (frame=0xffffffff7fe4f7e0)
    at /usr/src/sys/amd64/amd64/trap.c:444
#9  0xffffffff8058174e in calltrap ()
    at /usr/src/sys/amd64/amd64/exception.S:217
#10 0xffffffff80304522 in destroy_dev_sched_cb (dev=0x0,
    cb=0xffffffff80386a00 <tty_dealloc>, arg=0xffffff0004e22c00)
    at /usr/src/sys/kern/kern_conf.c:1136
#11 0xffffffff80387eec in ttydev_close (dev=Variable "dev" is not available.
) at /usr/src/sys/kern/tty.c:312
#12 0xffffffff802c67b4 in devfs_close (ap=0xffffffff7fe4f960)
    at /usr/src/sys/fs/devfs/devfs_vnops.c:458
#13 0xffffffff803cfd5d in vn_close (vp=0xffffff00b787e000, flags=3,
    file_cred=0xffffff000ff0aa00, td=0xffffff000f4bc000) at vnode_if.h:225
#14 0xffffffff803cfdf9 in vn_closefile (fp=0xffffff00054b6370,
    td=0xffffff000f4bc000) at /usr/src/sys/kern/vfs_vnops.c:920
#15 0xffffffff802c62ea in devfs_close_f (fp=Variable "fp" is not available.
)
    at /usr/src/sys/fs/devfs/devfs_vnops.c:471
#16 0xffffffff8030b1e3 in _fdrop (fp=0xffffff00054b6370, td=Variable "td" is not available.
) at file.h:293
#17 0xffffffff8030c34b in closef (fp=0xffffff00054b6370,
    td=0xffffff000f4bc000) at /usr/src/sys/kern/kern_descrip.c:2003
#18 0xffffffff8030cb26 in kern_close (td=0xffffff000f4bc000, fd=Variable "fd" is not available.
)
    at /usr/src/sys/kern/kern_descrip.c:1105
#19 0xffffffff8059e376 in syscall (frame=0xffffffff7fe4fc90)
    at /usr/src/sys/amd64/amd64/trap.c:898
#20 0xffffffff8058195b in Xfast_syscall ()
    at /usr/src/sys/amd64/amd64/exception.S:338
#21 0x0000000801278a5c in ?? ()
Previous frame inner to this frame (corrupt stack?)



>How-To-Repeat:

>Fix:
I'm patching the follwing:
RCS file: /museum/freebsd/repo/usr/src/sys/kern/tty.c,v
retrieving revision 1.290
diff -u -p -r1.290 tty.c
--- kern/tty.c  22 Sep 2008 19:25:14 -0000      1.290
+++ kern/tty.c  23 Sep 2008 08:45:20 -0000
@@ -936,6 +936,17 @@ tty_rel_free(struct tty *tp)
        tp->t_dev = NULL;
        tty_unlock(tp);

+#if 1 /*KOIE*/
+       printf("%s: pid=%ld tp=%p t_dev=%p\n",
+               __func__,
+               (curproc ? (long)curproc->p_pid : 0L),
+               tp,
+               dev);
+       if (dev == NULL) {
+           printf("dev is already destroyed; skip\n");
+           return;
+       }
+#endif
        destroy_dev_sched_cb(dev, tty_dealloc, tp);
 }

The follwing message is gotten to run hotsync:
ucom0: <Palm. Inc. Palm Handheld, class 0/0, rev 1.10/1.00, addr 2> on uhub0
ucom0: at uhub0 port 5 (addr 2) disconnected
tty_rel_free: pid=14 tp=0xffffff0005284000 t_dev=0xffffff00921b1800
ucom0: detached
tty_rel_free: pid=1815 tp=0xffffff0005284000 t_dev=0
dev is already destroyed; skip

pid 14 is usb0 (that is a kernen process).
pid 1815 is pilot-xfer.

It seems that destroy_dev_sched_cb() is called twice.

>Release-Note:
>Audit-Trail:
>Unformatted: