Under particular load, virtio-scsi backed / errors out

[Rich]

As I often do, I tried running OpenZFS git master's ZFS Test Suite against the new Ubuntu 21.10 release, to make sure nothing was secretly broken.

This is on an Ubuntu 21.10 amd64 VM (running 5.13.0-20-generic) inside VirtualBox 6.1.26 on Windows 10 x64, using virtio-scsi for the root disk. The host is not experiencing any errors or low disk space or anything whenever this occurs, and other VMs running on the host and same physical disk are unaffected.

I have seen failures like this happen before when using VirtualBox's TRIM/discard functionality, but that has to be very explicitly enabled on the VM, and it's not.

It runs fine for a bit...then suddenly everything crashes and burns, after the root disk starts erroring out:
[ 5281.077557] virtio_scsi virtio1: request:id 869 is not a head!
[ 5284.066557] sd 2:0:0:0: [sda] tag#390 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.066561] sd 2:0:0:0: [sda] tag#390 CDB: Write(10) 2a 00 01 d4 a3 78 00 00 a0 00
[ 5284.066562] blk_update_request: I/O error, dev sda, sector 30712696 op 0x1:(WRITE) flags 0x800 phys_seg 20 prio class 0
[ 5284.066575] Aborting journal on device sda3-8.
[ 5284.066580] sd 2:0:0:0: [sda] tag#391 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.066581] sd 2:0:0:0: [sda] tag#391 CDB: Write(10) 2a 00 01 d4 18 00 00 00 08 00
[ 5284.066582] blk_update_request: I/O error, dev sda, sector 30676992 op 0x1:(WRITE) flags 0x800 phys_seg 1 prio class 0
[ 5284.066584] Buffer I/O error on dev sda3, logical block 3702784, lost sync page write
[ 5284.066586] JBD2: Error -5 detected when updating journal superblock for sda3-8.
[ 5284.070494] EXT4-fs error (device sda3): ext4_journal_check_start:83: comm rs:main Q:Reg: Detected aborted journal
[ 5284.070666] EXT4-fs (sda3): Remounting filesystem read-only
[ 5284.071033] sd 2:0:0:0: [sda] tag#392 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071036] sd 2:0:0:0: [sda] tag#392 CDB: Read(10) 28 00 02 79 f1 80 00 00 08 00
[ 5284.071037] blk_update_request: I/O error, dev sda, sector 41546112 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 5284.071047] sd 2:0:0:0: [sda] tag#393 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071049] sd 2:0:0:0: [sda] tag#393 CDB: Read(10) 28 00 02 79 f1 a0 00 00 18 00
[ 5284.071049] blk_update_request: I/O error, dev sda, sector 41546144 op 0x0:(READ) flags 0x80700 phys_seg 3 prio class 0
[ 5284.071055] sd 2:0:0:0: [sda] tag#394 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071057] sd 2:0:0:0: [sda] tag#394 CDB: Read(10) 28 00 02 79 f1 d8 00 00 08 00
[ 5284.071057] blk_update_request: I/O error, dev sda, sector 41546200 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 5284.071062] sd 2:0:0:0: [sda] tag#395 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071064] sd 2:0:0:0: [sda] tag#395 CDB: Read(10) 28 00 02 79 f1 f0 00 00 08 00
[ 5284.071064] blk_update_request: I/O error, dev sda, sector 41546224 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 5284.071071] sd 2:0:0:0: [sda] tag#396 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071072] sd 2:0:0:0: [sda] tag#396 CDB: Read(10) 28 00 02 79 f2 00 00 00 18 00
[ 5284.071073] blk_update_request: I/O error, dev sda, sector 41546240 op 0x0:(READ) flags 0x80700 phys_seg 3 prio class 0
[ 5284.071078] sd 2:0:0:0: [sda] tag#397 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071079] sd 2:0:0:0: [sda] tag#397 CDB: Read(10) 28 00 02 79 f2 20 00 00 08 00
[ 5284.071080] blk_update_request: I/O error, dev sda, sector 41546272 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 5284.071085] sd 2:0:0:0: [sda] tag#398 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071086] sd 2:0:0:0: [sda] tag#398 CDB: Read(10) 28 00 02 79 f2 00 00 00 08 00
[ 5284.071087] blk_update_request: I/O error, dev sda, sector 41546240 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 5284.071092] sd 2:0:0:0: [sda] tag#399 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5284.071093] sd 2:0:0:0: [sda] tag#399 CDB: Read(10) 28 00 02 79 f2 00 00 00 08 00
[ 5284.071094] blk_update_request: I/O error, dev sda, sector 41546240 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 5406.093848] scsi_io_completion_action: 2 callbacks suppressed
[ 5406.093857] sd 2:0:0:0: [sda] tag#402 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5406.093861] sd 2:0:0:0: [sda] tag#402 CDB: Read(10) 28 00 00 24 ff 40 00 00 08 00
[ 5406.093862] print_req_error: 2 callbacks suppressed
[ 5406.093863] blk_update_request: I/O error, dev sda, sector 2424640 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 5406.093868] Read-error on swap-device (8:0:2424648)
[ 5406.093937] sd 2:0:0:0: [sda] tag#403 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 5406.093940] sd 2:0:0:0: [sda] tag#403 CDB: Read(10) 28 00 00 22 bc 50 00 00 08 00
[ 5406.093941] blk_update_request: I/O error, dev sda, sector 2276432 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 5406.093944] Read-error on swap-device (8:0:2276440)

This doesn't happen on 20.04 (vmlinuz-5.4.0-89-generic - I'll try again on vmlinuz-5.11.0-38-generic to confirm when I get a moment).

It also happens if you just run "fio /usr/share/doc/fio/examples/fio-rand-RW.fio":
[ 609.752340] virtio_scsi virtio1: request:id 424 is not a head!
[ 609.752401] sd 2:0:0:0: [sda] tag#273 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752404] sd 2:0:0:0: [sda] tag#273 CDB: Read(10) 28 00 02 f9 73 00 00 00 08 00
[ 609.752405] blk_update_request: I/O error, dev sda, sector 49902336 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 609.752411] sd 2:0:0:0: [sda] tag#274 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752412] sd 2:0:0:0: [sda] tag#274 CDB: Read(10) 28 00 02 f9 73 00 00 00 08 00
[ 609.752413] blk_update_request: I/O error, dev sda, sector 49902336 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 609.752421] sd 2:0:0:0: [sda] tag#275 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752422] sd 2:0:0:0: [sda] tag#275 CDB: Read(10) 28 00 01 88 03 c0 00 00 08 00
[ 609.752423] blk_update_request: I/O error, dev sda, sector 25691072 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 609.752426] sd 2:0:0:0: [sda] tag#276 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752428] sd 2:0:0:0: [sda] tag#276 CDB: Read(10) 28 00 01 88 03 c0 00 00 08 00
[ 609.752428] blk_update_request: I/O error, dev sda, sector 25691072 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 609.752435] sd 2:0:0:0: [sda] tag#277 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752436] sd 2:0:0:0: [sda] tag#277 CDB: Read(10) 28 00 01 5f 26 60 00 00 08 00
[ 609.752436] blk_update_request: I/O error, dev sda, sector 23012960 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 609.752440] sd 2:0:0:0: [sda] tag#278 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752441] sd 2:0:0:0: [sda] tag#278 CDB: Read(10) 28 00 01 5f 26 60 00 00 08 00
[ 609.752441] blk_update_request: I/O error, dev sda, sector 23012960 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 609.752448] sd 2:0:0:0: [sda] tag#279 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752449] sd 2:0:0:0: [sda] tag#279 CDB: Read(10) 28 00 03 fe b5 20 00 00 08 00
[ 609.752449] blk_update_request: I/O error, dev sda, sector 67024160 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 609.752453] sd 2:0:0:0: [sda] tag#280 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752454] sd 2:0:0:0: [sda] tag#280 CDB: Read(10) 28 00 03 fe b5 20 00 00 08 00
[ 609.752454] blk_update_request: I/O error, dev sda, sector 67024160 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[ 609.752479] sd 2:0:0:0: [sda] tag#281 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752480] sd 2:0:0:0: [sda] tag#281 CDB: Read(10) 28 00 00 52 c0 40 00 00 08 00
[ 609.752481] blk_update_request: I/O error, dev sda, sector 5423168 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[ 609.752484] sd 2:0:0:0: [sda] tag#282 FAILED Result: hostbyte=DID_BAD_TARGET driverbyte=DRIVER_OK cmd_age=0s
[ 609.752485] sd 2:0:0:0: [sda] tag#282 CDB: Read(10) 28 00 00 52 c0 40 00 00 08 00
[ 609.752486] blk_update_request: I/O error, dev sda, sector 5423168 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0

[Rich (rincebrain)]

I lied, it totally happens on 20.04 (w/5.4.0-89-generic) and 21.04 (5.11.0-37-generic), I just had forgotten I hadn't used virtio-scsi on them, just SATA.

Oh boy.