Bug 250638

Summary:

insyde BMC virtual CDROM unresponsive to FreeBSD

Product:

Base System

Reporter:

Ed Maste <emaste>

Component:

misc

Assignee:

freebsd-bugs (Nobody) <bugs>

Status:

New ---

Severity:

Affects Only Me

CC:

bz, grahamperrin

Priority:

---

Version:

CURRENT

Hardware:

Any

OS:

Any

See Also:

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=235151

Attachments:

Description	Flags
usbdump trace of unresponsive virtual CD access	none

Description Ed Maste freebsd_committer

2020-10-26 17:29:45 UTC

Discovered while attempting to install FreeBSD from a virtual CDROM ISO image, where the installer stops trying to mount the root fs, but reproduced after installing FreeBSD by dd'ing an image to the disk from Ubuntu. Hardware is an experimental platform but with (I believe) a standard BMC; will try to reproduce on off-the-shelf hardware.

Upon attaching the virtual CDROM console emits:

ugen0.6: <Linux 4.9.135 with astvhub Virtual Media Gadget 0> at usbus0
umass1 numa-domain 0 on uhub3
umass1: <Linux 4.9.135 with astvhub Virtual Media Gadget 0, class 0/0, rev 2.00/4.09, addr 5> on usbus0
umass1:  SCSI over Bulk-Only; quirks = 0x0100
umass1:2:1: Attached to scbus2
uhub_explore: illegal enable change, port 1
(probe0:umass-sim1:1:0:0): Down reving Protocol Version from 2 to 0?
GEOM: new disk cd0
pass2 at umass-sim1 bus 1 scbus2 target 0 lun 0
pass2: <GENERIC Virtual CDROM YS0J> Removable CD-ROM SCSI device
pass2: 40.000MB/s transfers
cd0 at umass-sim1 bus 1 scbus2 target 0 lun 0
cd0: <GENERIC Virtual CDROM YS0J> Removable CD-ROM SCSI device
cd0: 40.000MB/s transfers
cd0: 337MB (172775 2048 byte sectors)
cd0: quirks=0x10<10_BYTE_ONLY>

but no /dev/cd0 is created

"camcontrol devlist" reports:

<SAMSUNG MZ7LH240HAHQ-00005 HXT7404Q>  at scbus0 target 0 lun 0 (ada0,pass0)
<SanDisk Cruzer Blade 1.26>        at scbus1 target 0 lun 0 (da0,pass1)
<GENERIC Virtual CDROM YS0J>       at scbus2 target 0 lun 0 (pass2,cd0)

running "gpart show" produces on the console:

(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e6 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 3 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e6 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 2 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e6 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 1 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e6 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 0 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e6 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Error 5, Retries exhausted
(cd0:umass-sim1:1:0:0): cddone: got error 0x5 back
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e5 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 3 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e5 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 2 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e5 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 1 more tries remain
(cd0:umass-sim1:1:0:0): READ(10). CDB: 28 00 00 02 a2 e5 00 00 01 00 
(cd0:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(cd0:umass-sim1:1:0:0): Retrying command, 0 more tries remain

^T shows:
load: 0.00  cmd: gpart 2516 [g_waitfor_event] 44.52r 0.00u 0.00s 0% 2540k
mi_switch+0x155 sleepq_switch+0x109 sleepq_timedwait+0x4b _sleep+0x29b g_waitfor_event+0xf0 sysctl_kern_geom_confany+0xc1 sysctl_root_handler_locked+0x9c sysctl_root+0x20a userland_sysctl+0x17d sys___sysctl+0x5f amd64_syscall+0x135 fast_syscall_common+0xf8 

BMC details:
Host Power Status : 	Host is currently ON
BMC Uptime : 	3 Day(s) 21 Hour(s) 29 Min(s) 9 Second(s)
BMC Firmware Build Time : 	Fri May 15 21:19:31 2020
BMC FW Rev : 	03.51.05.2020
Backup BMC FW Rev : 	03.51.05.2020
Build ID :	05.202000

Comment 1 Ed Maste freebsd_committer

2020-10-26 18:07:27 UTC

detaching virtual CD when in this state results in the following panic:

ugen0.6: <Linux 4.9.135 with astvhub Virtual Media Gadget 0> at usbus0 (disconnected)
umass1: at uhub3, port 1, addr 5 (disconnected)
pass2 at umass-sim1 bus 1 scbus2 target 0 lun 0
pass2: <GENERIC Virtual CDROM YS0J>  detached
cd0 at umass-sim1 bus 1 scbus2 target 0 lun 0
cd0: <GENERIC Virtual CDROM YS0J>  detached
panic: g_resize_provider_event but withered
cpuid = 7
time = 1603735205
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe0233a2b420
vpanic() at vpanic+0x182/frame 0xfffffe0233a2b470
panic() at panic+0x43/frame 0xfffffe0233a2b4d0
g_resize_provider_event() at g_resize_provider_event+0x1a5/frame 0xfffffe0233a2b500
g_run_events() at g_run_events+0x156/frame 0xfffffe0233a2b530
g_fork_exit() at fork_exit+0x80/frame 0xfffffe0233a2b570
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe0233a2b570
--- trap 0, rip = 0, rsp = 0, rbp = 0 ---
KDB: enter: panic
[ thread pid 13 tid 100785 ]
Stopped at      kdb_enter+0x37: movq    $0,0x10a8f86(%rip)
db>

Comment 2 Bjoern A. Zeeb freebsd_committer

2020-10-26 18:10:30 UTC

I've seen the g_waitfor_event with gpart show from the rc.d startup file a few times on MMCCAM as well.  It cleared for me after some longer timeout I think.

Can you break into debugger from there (or use procstat) to figure out what the other half is doing?  Some SIM call I think.

Comment 3 Ed Maste freebsd_committer

2020-11-04 14:57:36 UTC

Created attachment 219359 [details]
usbdump trace of unresponsive virtual CD access

Comment 4 Ed Maste freebsd_committer

2020-11-04 15:16:08 UTC

(In reply to Bjoern A. Zeeb from comment #2)

I'd guess the first one here:

   13 100785 geom                g_event             mi_switch+0x155 sleepq_switch+0x109 _sleep+0x2b4 biowait+0x70 g_read_data+0xa3 g_raid_md_taste_jmicron+0xc2 g_raid_taste+0x196 g_new_provider_event+0x9a g_run_events+0x156 fork_exit+0x80 fork_trampoline+0xe 
   13 100786 geom                g_up                mi_switch+0x155 sleepq_switch+0x109 _sleep+0x2b4 g_io_schedule_up+0x3c g_up_procbody+0x5c fork_exit+0x80 fork_trampoline+0xe 
   13 100787 geom                g_down              mi_switch+0x155 sleepq_switch+0x109 _sleep+0x2b4 g_io_schedule_down+0x4c g_down_procbody+0x5c fork_exit+0x80 fork_trampoline+0xe

Comment 5 Ed Maste freebsd_committer

2020-11-04 15:58:31 UTC

(transcribed manually as my console access is via an HTML5 IP KVM over an RDP session)

db> show alllocks
Process 13 (geom) thread 0x... (100785)
exclusive sx GEOM topology (GEOM topology) r = 0 (0x...) locked @ /root/freebsd/sys/geom/part/g_part.c:2049
db>