Bug #2100

devfs related panic

Added by sepherosa about 3 years ago. Updated about 3 years ago.

Status:FeedbackStart date:
Priority:NormalDue date:
Assignee:alexh% Done:

0%

Category:-
Target version:-

Description

Hi all,

#12 0xffffffff802e8a1f in dssetmask (dev=0xffffffe085418f50,
mode=<value optimized out>, flags=<value optimized out>,
sspp=<value optimized out>, info=<value optimized out>) at
/usr/src/sys/sys/diskslice.h:349
#13 dsopen (dev=0xffffffe085418f50, mode=<value optimized out>,
flags=<value optimized out>, sspp=<value optimized out>,
info=<value optimized out>) at /usr/src/sys/kern/subr_diskslice.c:741
#14 0xffffffff802e45ff in diskopen (ap=0xffffffe0ba9c3798) at
/usr/src/sys/kern/subr_disk.c:956
#15 0xffffffff802a3e1c in dev_dopen (dev=0xffffffe085418f50,
oflags=8192, devtype=195, cred=0x1f) at
/usr/src/sys/kern/kern_device.c:151
#16 0xffffffff803e9c02 in devfs_spec_open (ap=0xffffffe0ba9c3838) at
/usr/src/sys/vfs/devfs/devfs_vnops.c:919
#17 0xffffffff8033c61c in vop_open (ops=0xffffffe0ad0d2e00,
vp=0xffffffe0bb1d6c48, mode=1, cred=0xffffffe0ae317868,
fp=0xffffffe08518ad58)
at /usr/src/sys/kern/vfs_vopops.c:289
#18 0xffffffff80339ec6 in vn_open (nd=0xffffffe0ba9c3a98, fp=<value
optimized out>, fmode=1, cmode=<value optimized out>)
at /usr/src/sys/kern/vfs_vnops.c:284
#19 0xffffffff80336c5d in kern_open (nd=0xffffffe0ba9c3a98,
oflags=<value optimized out>, mode=<value optimized out>,
res=<value optimized out>) at /usr/src/sys/kern/vfs_syscalls.c:1836
#20 0xffffffff80336eb6 in sys_open (uap=0xffffffe0ba9c3b58) at
/usr/src/sys/kern/vfs_syscalls.c:1946
#21 0xffffffff8048f652 in syscall2 (frame=0xffffffe0ba9c3c08) at
/usr/src/sys/platform/pc64/x86_64/trap.c:1188
#22 0xffffffff80487c1f in Xfast_syscall () at
/usr/src/sys/platform/pc64/x86_64/exception.S:320

core dump is uploaded to sephe@leaf:crash/vmcore0.tbz

It happened after following stuffs were done by my friend:
- a sata disk was plugged into the esata port, and the disk was detected as da1
- dd if=/dev/zero of=/dev/da1, something like that
- unplug the sata disk
- after a short while, another sata disk was plugged in the same esata port
- this time no message showed about anything related to /dev/da1
- run the above dd command again, panic

Best Regards,
sephe

History

#1 Updated by alexh about 3 years ago

Hi,

I've recently made some rather potentially unstable changes to devfs
(the change of subname to -> related removal functions). Could you
please enable devfs debug to 7 and get the output when the disk is
unplugged?

I'll have a look into the crash on the weekend, thanks for the report.

Cheers,
Alex

On 08/07/11 06:00, Sepherosa Ziehau wrote:
> Hi all,
>
> #12 0xffffffff802e8a1f in dssetmask (dev=0xffffffe085418f50,
> mode=<value optimized out>, flags=<value optimized out>,
> sspp=<value optimized out>, info=<value optimized out>) at
> /usr/src/sys/sys/diskslice.h:349
> #13 dsopen (dev=0xffffffe085418f50, mode=<value optimized out>,
> flags=<value optimized out>, sspp=<value optimized out>,
> info=<value optimized out>) at /usr/src/sys/kern/subr_diskslice.c:741
> #14 0xffffffff802e45ff in diskopen (ap=0xffffffe0ba9c3798) at
> /usr/src/sys/kern/subr_disk.c:956
> #15 0xffffffff802a3e1c in dev_dopen (dev=0xffffffe085418f50,
> oflags=8192, devtype=195, cred=0x1f) at
> /usr/src/sys/kern/kern_device.c:151
> #16 0xffffffff803e9c02 in devfs_spec_open (ap=0xffffffe0ba9c3838) at
> /usr/src/sys/vfs/devfs/devfs_vnops.c:919
> #17 0xffffffff8033c61c in vop_open (ops=0xffffffe0ad0d2e00,
> vp=0xffffffe0bb1d6c48, mode=1, cred=0xffffffe0ae317868,
> fp=0xffffffe08518ad58)
> at /usr/src/sys/kern/vfs_vopops.c:289
> #18 0xffffffff80339ec6 in vn_open (nd=0xffffffe0ba9c3a98, fp=<value
> optimized out>, fmode=1, cmode=<value optimized out>)
> at /usr/src/sys/kern/vfs_vnops.c:284
> #19 0xffffffff80336c5d in kern_open (nd=0xffffffe0ba9c3a98,
> oflags=<value optimized out>, mode=<value optimized out>,
> res=<value optimized out>) at /usr/src/sys/kern/vfs_syscalls.c:1836
> #20 0xffffffff80336eb6 in sys_open (uap=0xffffffe0ba9c3b58) at
> /usr/src/sys/kern/vfs_syscalls.c:1946
> #21 0xffffffff8048f652 in syscall2 (frame=0xffffffe0ba9c3c08) at
> /usr/src/sys/platform/pc64/x86_64/trap.c:1188
> #22 0xffffffff80487c1f in Xfast_syscall () at
> /usr/src/sys/platform/pc64/x86_64/exception.S:320
>
> core dump is uploaded to sephe@leaf:crash/vmcore0.tbz
>
> It happened after following stuffs were done by my friend:
> - a sata disk was plugged into the esata port, and the disk was detected as da1
> - dd if=/dev/zero of=/dev/da1, something like that
> - unplug the sata disk
> - after a short while, another sata disk was plugged in the same esata port
> - this time no message showed about anything related to /dev/da1
> - run the above dd command again, panic
>
> Best Regards,
> sephe
>

#2 Updated by alexh about 3 years ago

Hrm, actually this doesn't even have the new changes, so it's not that.

#3 Updated by alexh about 3 years ago

What would be useful is knowing which disk driver attached. scsi_da, ahci?

#4 Updated by alexh about 3 years ago

Nevermind, I'm being a bit too verbose, I see it's ahci.

Thanks,
Alex

#5 Updated by alexh about 3 years ago

From the short look I've had so far, it seems AHCI is the problem here. The
ahci_cam_changed() function needs to be revisited; from what I can tell, it
doesn't properly remove the device, and the condition of found ==
CAM_TARGET_WILDCARD also is, the very least, confusing, since it is indirectly
comparing to -1. No clue why CAM_TARGET_WILDCARD was used instead of just -1, as
described in the comment above the function.

Matt needs to take a look at this as I'm not familiar with the whole CAM story.

Cheers,
Alex

#6 Updated by alexh about 3 years ago

I can't reproduce this so I can't really fix it. Can you please try to do it
again with:
sysctl kern.disk_debug=7

That should give some insight into the ahci -- cam --> subr_disk interactions.
Attached is the dmesg of me pulling the disk in and out a few times and dd'ing
wildly around:

ahci0.5: Transient Errors: 40<PCS> (7)
ahci0.5: HOTPLUG - Device inserted
ahci0.5: Waiting 10 seconds on insertion
ahci0.5: PMPROBE(2) No Port Multiplier was found.
ahci0.5: PMPROBE(2) No Port Multiplier was found.
ahci0.5: Found DISK "WDC WD3200BEVT-22ZCT0 11.01A11" serial="WD-WXE308K75174"
ahci0.5: tags=32/32 satacap=0702 satafea=004c NCQ=YES capacity=305245.33MB
ahci0.5: f85=7469 f86=bc09 f87=6163 WC=enabled RA=enabled SEC=freezing
disk scheduler: set policy of da2 to noop
da2 at ahci0 bus 5 target 0 lun 0
da2: <SATA WDC WD3200BEVT-2 11.0> Fixed Direct Access SCSI-4 device
da2: Serial Number WD-WXE308K75174
da2: 150.000MB/s transfers
da2: 305245MB (625142448 512 byte sectors: 255H 63S/T 38913C)
ahci0.5: Transient Errors: 400040<PRCS,PCS> (4)
ahci0.5: HOTPLUG - Device removed
(da2:ahci0:5:0:0): lost device
(da2:ahci0:5:0:0): removing device entry
DISK_DISK_DESTROY: da2
ahci0.5: Transient Errors: 40<PCS> (7)
ahci0.5: HOTPLUG - Device inserted
ahci0.5: Waiting 10 seconds on insertion
ahci0.5: PMPROBE(2) No Port Multiplier was found.
ahci0.5: PMPROBE(2) No Port Multiplier was found.
ahci0.5: Found DISK "WDC WD3200BEVT-22ZCT0 11.01A11" serial="WD-WXE308K75174"
ahci0.5: tags=32/32 satacap=0702 satafea=004c NCQ=YES capacity=305245.33MB
ahci0.5: f85=7469 f86=bc09 f87=6163 WC=enabled RA=enabled SEC=freezing
disk_create (begin): (null)2
disk scheduler: set policy of da2 to noop
disk_create (end): da2
_setdiskinfo: da2
disk_setdiskinfo: sent probe for da2
da2 at ahci0 bus 5 target 0 lun 0
da2: <SATA WDC WD3200BEVT-2 11.0> Fixed Direct Access SCSI-4 device
da2: Serial Number WD-WXE308K75174
da2: 150.000MB/s transfers
da2: 305245MB (625142448 512 byte sectors: 255H 63S/T 38913C)
DISK_DISK_PROBE: da2
disk_probe (begin): da2
disk_probe (end): da2
ahci0.5: Transient Errors: 400002<PRCS,PSS> (4)
ahci0.5: HOTPLUG - Device removed
(da2:ahci0:5:0:0): lost device
(da2:ahci0:5:0:0): removing device entry
DISK_DISK_DESTROY: da2
ahci0.5: Transient Errors: 40<PCS> (7)
ahci0.5: HOTPLUG - Device inserted
ahci0.5: Waiting 10 seconds on insertion
ahci0.5: PMPROBE(2) No Port Multiplier was found.
ahci0.5: PMPROBE(2) No Port Multiplier was found.
ahci0.5: Found DISK "WDC WD3200BEVT-22ZCT0 11.01A11" serial="WD-WXE308K75174"
ahci0.5: tags=32/32 satacap=0702 satafea=004c NCQ=YES capacity=305245.33MB
ahci0.5: f85=7469 f86=bc09 f87=6163 WC=enabled RA=enabled SEC=freezing
disk_create (begin): (null)2
disk scheduler: set policy of da2 to noop
disk_create (end): da2
_setdiskinfo: da2
disk_setdiskinfo: sent probe for da2
da2 at ahci0 bus 5 target 0 lun 0
da2: <SATA WDC WD3200BEVT-2 11.0> Fixed Direct Access SCSI-4 device
da2: Serial Number WD-WXE308K75174
da2: 150.000MB/s transfers
da2: 305245MB (625142448 512 byte sectors: 255H 63S/T 38913C)
DISK_DISK_PROBE: da2
disk_probe (begin): da2
disk_probe (end): da2

Also available in: Atom PDF