Bug 2141964

Guest OS serial output :

http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-11/test-results/1-Host_RHEL.m8.u8.product_rhel.qcow2.virtio_blk.up.virtio_net.Guest.RHEL.8.8.0.x86_64.io-github-autotest-qemu.hotplug_unplug_during_io_repeat.q35/serial-serial0-avocado-vt-vm1.log

Qing Wang,

So you hot-unplugged the disk while iozone was running?

Will ext4 (or any other filesystem) and application, not see errors (EIO or equivalent) if disk is suddenly hot unplugged.

In virtiofs, IIRC, we do this in little bit graceful manner. We disconnect all queues so that any new request submitted on queue will immediately return with -EIO and the wait for pending requests to finish. (virtio_fs_remove()).

I am assuming that virtio-blk must be doing something similar. Have not looked at the code. IOW, if device is suddenly hot-unplugged, filesystem and applications are bound to see I/O failures and might choose to send error messages on the console. And there is no guarantee that filesystem or application will resume automatically when device is plugged back in.

Please correct me if my understanding is not right.

It's not clear to me from the logs when the unplugs happen vs. when the IO errors happen. Logging something to dmesg when you perform the unplug action could make it more clear.

But of course you will see IO errors after you unplug the disk, this is expected.

> Expected results:
> iozone may run on disk after hotplug

As far as  I can tell, it /is/ running on the new disk after it is hotplugged (added) and then it fails after it is unplugged. This is expected, of course.

Surely you don't expect iozone to keep running with no errors after the disk has been unplugged, right?

I upload a normal result of this test.

http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-14

It also will hit same fs error in serial log.
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-14/serial-serial0-avocado-vt-vm1.log
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-14/debug.log

but the iozone may run on new hotplug disk.
it will hit error when the disk is unplugged.
The iozone error is "write: Input/output error\n\niozone: interrupted\n\nexiting iozone\n\n"


but for 4k disk, it looks like new hotplug disk can not work.
The iozone Error is "reading block 140 7f30fde00000\nread: Input/output error\n

So what you're saying is that the last iozone instance is failing even though its disk has _not_ been unplugged yet, right?

The messages in the kernel log do look a bit different from the other instances caused by the unplug:

2022-11-08 02:32:27: [  681.517270] EXT4-fs (vdq1): mounted filesystem with ordered data mode. Opts: (null)
2022-11-08 02:32:40: [  694.648027] blk_update_request: I/O error, dev vdq, sector 614401 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.649759] blk_update_request: I/O error, dev vdq, sector 616433 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.651326] blk_update_request: I/O error, dev vdq, sector 618465 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
2022-11-08 02:32:40: [  694.652792] blk_update_request: I/O error, dev vdq, sector 618497 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.654316] blk_update_request: I/O error, dev vdq, sector 620529 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.655847] blk_update_request: I/O error, dev vdq, sector 622561 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0

And in the QMP logs, I can't see any 'device_del' request for this disk indeed. I also don't see any I/O errors from the host (which would be visible as a QMP event). Maybe the unexpected previous unplugs messed up some state?

Can you confirm that the same iozone invocation doesn't fail on this host and with the same configuration when you run it without unplugging busy disks first? You mentioned that it uses a 4k disk. If something was wrong with respect to request alignment and that caused the I/O errors, it would be visible with a normal run (however, as I said above, it would also be expected to result in a QMP event).

(Actually, with respect to the unplug operations that happen before, I'm wondering why the kernel even allows the unplug. My understanding is that PCI unplug only works with guest cooperation, so QEMU wouldn't unplug the device if the guest kernel didn't confirm it. But that's just an aside.)

The iozone invocation has no issue on the host, and it is executed after each hotplug finished.
The process in guest is:
 hotplugging disk -> iozone -> check iozone pid -> sleep 30s -> check iozone pid to confirm IO is doing.

 

Let's check the log of guest:

[stdlog] 2022-11-08 02:31:44,674 avocado.test INFO | Start iozone under background.

sleep 30s

[stdlog] 2022-11-08 02:32:19,567 avocado.test DEBUG| The index of disks before unplug:
[stdlog]  {'/dev/vda', '/dev/vdp'}   <------indicates the new disk is identified by guest os
...
[stdlog] 2022-11-08 02:32:19,569 avocado.virttest.qemu_monitor DEBUG| Send command: {'execute': 'device_del', 'arguments': {'id': 'stg0'}, 'id': 'AVPnEpRT'}
[stdlog] 2022-11-08 02:32:19,673 aexpect.client DEBUG| Sending command: echo $?
...
[stdlog] 2022-11-08 02:32:23,903 avocado.test DEBUG| The index of disks before hotplug:
[stdlog]  {'/dev/vda'}   <------indicates the new disk is unpluged by guest os

[stdlog] 2022-11-08 02:32:23,904 avocado.test INFO | Start to hotplug devices "stg0" by monitor qmpmonitor1.
[stdlog] 2022-11-08 02:32:23,906 avocado.virttest.qemu_monitor DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Sending command 'blockdev-add' 
[stdlog] 2022-11-08 02:32:23,906 avocado.virttest.qemu_monitor DEBUG| Send command: {'execute': 'blockdev-add', 'arguments': {'node-name': 'file_stg0', 'driver': 'file', 'auto-read-only': True, 'discard': 'unmap', 'aio': 'threads', 'filename': '/home/kvm_autotest_root/images/storage0.qcow2', 'cache': {'direct': True, 'no-flush': False}}, 'id': 'meE4QckK'}
[stdlog] 2022-11-08 02:32:23,908 avocado.virttest.qemu_monitor DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Sending command 'blockdev-add' 
[stdlog] 2022-11-08 02:32:23,908 avocado.virttest.qemu_monitor DEBUG| Send command: {'execute': 'blockdev-add', 'arguments': {'node-name': 'drive_stg0', 'driver': 'qcow2', 'read-only': False, 'cache': {'direct': True, 'no-flush': False}, 'file': 'file_stg0'}, 'id': 't7iuOPpX'}
[stdlog] 2022-11-08 02:32:23,910 avocado.virttest.qemu_monitor DEBUG| (monitor avocado-vt-vm1.qmpmonitor1) Sending command 'device_add' 
[stdlog] 2022-11-08 02:32:23,910 avocado.virttest.qemu_monitor DEBUG| Send command: {'execute': 'device_add', 'arguments': OrderedDict([('driver', 'virtio-blk-pci'), ('id', 'stg0'), ('drive', 'drive_stg0'), ('write-cache', 'on'), ('bus', 'pcie_extra_root_port_0'), ('addr', '0x0'), ('iothread', 'iothread1')]), 'id': 'z9OMDLvl'}
.....

[stdlog] 2022-11-08 02:32:23,926 avocado.virttest.virt_vm DEBUG| Attempting to log into 'avocado-vt-vm1' (timeout 360s)
[stdlog] 2022-11-08 02:32:23,927 avocado.virttest.virt_vm DEBUG| Found/Verified IP 192.168.122.85 for VM avocado-vt-vm1 NIC 0
[stdlog] 2022-11-08 02:32:25,330 aexpect.client DEBUG| Sending command: ls /dev/[vhs]d* | grep -v [0-9]$
[stdlog] 2022-11-08 02:32:25,435 aexpect.client DEBUG| Sending command: echo $?
[stdlog] 2022-11-08 02:32:25,596 aexpect.client DEBUG| Sending command: parted -s "/dev/vdq" mklabel msdos  <--- new disk vdq is accepted by OS
[stdlog] 2022-11-08 02:32:25,721 aexpect.client DEBUG| Sending command: echo $?

[stdlog] 2022-11-08 02:32:27,384 avocado.test INFO | Start iozone under background.
.....
[stdlog] 2022-11-08 02:32:28,851 aexpect.client DEBUG| Sending command: pgrep -lx iozone
[stdlog] 2022-11-08 02:32:40,423 aexpect.client DEBUG| Sending command: echo $?
[stderr] Exception in thread Thread-29:
[stderr] Traceback (most recent call last):
[stderr]   File "/usr/lib64/python3.6/threading.py", line 937, in _bootstrap_inner
[stderr]     self.run()
[stderr]   File "/home/kar/workspace/avocado-vt/virttest/utils_misc.py", line 125, in run
[stderr]     self._retval = self._target(*self._args, **self._kwargs)
[stderr]   File "/home/kar/workspace/root/avocado/data/avocado-vt/virttest/test-providers.d/downloads/io-github-autotest-qemu/provider/storage_benchmark.py", line 337, in run
[stderr]     return super(Iozone, self).run(cmd, timeout)
[stderr]   File "/home/kar/workspace/root/avocado/data/avocado-vt/virttest/test-providers.d/downloads/io-github-autotest-qemu/provider/storage_benchmark.py", line 243, in run
[stderr]     return self.session.cmd(cmd, timeout=timeout)
[stderr]   File "/home/kar/workspace/lib/python3.6/site-packages/aexpect-1.6.4-py3.6.egg/aexpect/client.py", line 1356, in cmd
[stderr]     raise ShellCmdError(cmd, status, output)
[stderr] aexpect.exceptions.ShellCmdError: Shell command failed: '/home/iozone_inst/src/current/iozone -az -g 10G -y 32k -i 0 -i 1 -I -f /mnt/vdq1/iozone_test'    (status: 61,    output: '\tIozone: Performance Test of File I/O\n\t        Version $Revision: 3.489 $\n\t\tCompiled for 64 bit mode.\n\t\tBuild: linux-AMD64 \n\n\tContributors:William Norcott, Don Capps, Isom Crawford, Kirby Collins\n\t             Al Slater, Scott Rhine, Mike Wisner, Ken Goss\n\t             Steve Landherr, Brad Smith, Mark Kelly, Dr. Alain CYR,\n\t             Randy Dunlap, Mark Montague, Dan Million, Gavin Brebner,\n\t             Jean-Marc Zucconi, Jeff Blomberg, Benny Halevy, Dave Boone,\n\t             Erik Habbinga, Kris Strecker, Walter Wong, Joshua Root,\n\t             Fabrice Bacchella, Zhenghua Xue, Qin Li, Darren Sawyer,\n\t             Vangel Bojaxhi, Ben England, Vikentsi Lapa,\n\t             Alexey Skidanov, Sudhir Kumar.\n\n\tRun began: Tue Nov  8 15:32:26 2022\n\n\tAuto Mode\n\tCross over of record size disabled.\n\tUsing maximum file size of 10485760 kilobytes.\n\tUsing Minimum Record Size 32 kB\n\tO_DIRECT feature enabled\n\tCommand line used: /home/iozone_inst/src/current/iozone -az -g 10G -y 32k -i 0 -i 1 -I -f /mnt/vdq1/iozone_test\n\tOutput is in kBytes/sec\n\tTime Resolution = 0.000001 seconds.\n\tProcessor cache size set to 1024 kBytes.\n\tProcessor cache line size set to 32 bytes.\n\tFile stride size set to 17 * record size.\n                                                              random    random     

iozone error quit

==================================================
kernel log:

2022-11-08 02:32:23: [  678.259446] virtio-pci 0000:06:00.0: enabling device (0000 -> 0002)
2022-11-08 02:32:23: [  678.270099] virtio_blk virtio2: [vdq] 62914560 512-byte logical blocks (32.2 GB/30.0 GiB)
2022-11-08 02:32:23: [  678.271385] vdq: detected capacity change from 0 to 32212254720   <<-----new disk detected.
2022-11-08 02:32:23: [  678.273388]  vdq: vdq1    
2022-11-08 02:32:25: [  679.957501]  vdq:
2022-11-08 02:32:26: [  680.372993]  vdq: vdq1
2022-11-08 02:32:27: [  681.517270] EXT4-fs (vdq1): mounted filesystem with ordered data mode. Opts: (null)
2022-11-08 02:32:40: [  694.648027] blk_update_request: I/O error, dev vdq, sector 614401 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.649759] blk_update_request: I/O error, dev vdq, sector 616433 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.651326] blk_update_request: I/O error, dev vdq, sector 618465 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
2022-11-08 02:32:40: [  694.652792] blk_update_request: I/O error, dev vdq, sector 618497 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.654316] blk_update_request: I/O error, dev vdq, sector 620529 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
2022-11-08 02:32:40: [  694.655847] blk_update_request: I/O error, dev vdq, sector 622561 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
2022-11-08 02:36:04: [  898.842243] vda1: Can't mount, would change RO state    < --- vda1 (root partition broken result in iozone quit) ?
2022-11-08 02:36:04: [[0;32m  OK  [0m] Stopped GSSAPI Proxy Daemon.

=========================================
2022-11-08 02:36:04: [  898.842243] vda1: Can't mount, would change RO state    < --- vda1 (root partition broken result in iozone quit) ?
I think the previous unplugs broken the guest os system file system (not the hotplugged disk)

(In reply to qing.wang from comment #7)
> The iozone invocation has no issue on the host, and it is executed after
> each hotplug finished.
> The process in guest is:
>  hotplugging disk -> iozone -> check iozone pid -> sleep 30s -> check iozone
> pid to confirm IO is doing.

Can iozone finish successfully on the guest when you never unplug a disk in this guest?

> 2022-11-08 02:32:40: [  694.655847] blk_update_request: I/O error, dev vdq,
> sector 622561 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
> 2022-11-08 02:36:04: [  898.842243] vda1: Can't mount, would change RO state
> < --- vda1 (root partition broken result in iozone quit) ?

Note that there is a big time difference between those two messages. I don't think the vda1 error is related to the vdq errors, but it's rather an unrelated quirk of the guest shutdown. The same message exists in the logs of the successful case from comment 5.

(In reply to Kevin Wolf from comment #8)
> (In reply to qing.wang from comment #7)
> > The iozone invocation has no issue on the host, and it is executed after
> > each hotplug finished.
> > The process in guest is:
> >  hotplugging disk -> iozone -> check iozone pid -> sleep 30s -> check iozone
> > pid to confirm IO is doing.
> 
> Can iozone finish successfully on the guest when you never unplug a disk in
> this guest?

Yes, it runs the same command on the disk over 8 hours.

> 
> > 2022-11-08 02:32:40: [  694.655847] blk_update_request: I/O error, dev vdq,
> > sector 622561 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
> > 2022-11-08 02:36:04: [  898.842243] vda1: Can't mount, would change RO state
> > < --- vda1 (root partition broken result in iozone quit) ?
> 
> Note that there is a big time difference between those two messages. I don't
> think the vda1 error is related to the vdq errors, but it's rather an
> unrelated quirk of the guest shutdown. The same message exists in the logs
> of the successful case from comment 5.

(In reply to Kevin Wolf from comment #6)
> So what you're saying is that the last iozone instance is failing even
> though its disk has _not_ been unplugged yet, right?
> 
> The messages in the kernel log do look a bit different from the other
> instances caused by the unplug:
> 
> 2022-11-08 02:32:27: [  681.517270] EXT4-fs (vdq1): mounted filesystem with
> ordered data mode. Opts: (null)
> 2022-11-08 02:32:40: [  694.648027] blk_update_request: I/O error, dev vdq,
> sector 614401 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
> 2022-11-08 02:32:40: [  694.649759] blk_update_request: I/O error, dev vdq,
> sector 616433 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
> 2022-11-08 02:32:40: [  694.651326] blk_update_request: I/O error, dev vdq,
> sector 618465 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
> 2022-11-08 02:32:40: [  694.652792] blk_update_request: I/O error, dev vdq,
> sector 618497 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
> 2022-11-08 02:32:40: [  694.654316] blk_update_request: I/O error, dev vdq,
> sector 620529 op 0x0:(READ) flags 0x4000 phys_seg 254 prio class 0
> 2022-11-08 02:32:40: [  694.655847] blk_update_request: I/O error, dev vdq,
> sector 622561 op 0x0:(READ) flags 0x0 phys_seg 4 prio class 0
> 

These block error messages indeed do seem suspicious. They are not present in success case. Also in error case, I am seeing these once.

So looks like we hot plugged disk /dev/vdq and it was mounted at 2.:32:27 and after 13 seconds we started getting I/O
errors on this disk. 

Are there any qemu logs as well corresponding to above error. May be that will help figure out why I/O to disk /dev/vdq failed.

I upload  a new failed log:
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-22

It has same error blk_update_request and check 
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-22/test-results/1-Host_RHEL.m8.u8.product_rhel.qcow2.virtio_blk.up.virtio_net.Guest.RHEL.8.8.0.x86_64.io-github-autotest-qemu.hotplug_unplug_during_io_repeat.q35/catch_monitor-avocado-vt-vm1-pid-16413.log

There is error message .
2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds": 981048}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "drive_stg0", "reason": "Invalid argument", "operation": "write", "action": "report"}}
2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds": 981172}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "drive_stg0", "reason": "Invalid argument", "operation": "write", "action": "report"}}
2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds": 981223}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "drive_stg0", "reason": "Invalid argument", "operation": "write", "action": "report"}}
2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds": 981271}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "drive_stg0", "reason": "Invalid argument", "operation": "write", "action": "report"}}
2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds": 981304}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "drive_stg0", "reason": "Invalid argument", "operation": "write", "action": "report"}}
2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds": 981328}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "drive_stg0", "reason": "Invalid argument", "operation": "write", "action": "report"}}

The same message also found in :
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-11/test-results/1-Host_RHEL.m8.u8.product_rhel.qcow2.virtio_blk.up.virtio_net.Guest.RHEL.8.8.0.x86_64.io-github-autotest-qemu.hotplug_unplug_during_io_repeat.q35/catch_monitor-avocado-vt-vm1-pid-794693.log

I check the file, it indicates has enough space. 

image: /home/kvm_autotest_root/images/storage0.qcow2
file format: qcow2
virtual size: 30 GiB (32212254720 bytes)
disk size: 2.36 GiB
cluster_size: 65536
Format specific information:
    compat: 1.1
    compression type: zlib
    lazy refcounts: false
    refcount bits: 16
    corrupt: false
    extended l2: false
image: /home/kvm_autotest_root/images/rhel880-64-virtio.qcow2
file format: qcow2
virtual size: 20 GiB (21474836480 bytes)
disk size: 5.79 GiB
cluster_size: 65536
Format specific information:
    compat: 1.1
    compression type: zlib
    lazy refcounts: false
    refcount bits: 16
    corrupt: false
    extended l2: false

(In reply to qing.wang from comment #11)
> There is error message .

Oh, thank you, this is important information. It seems that I looked in the wrong file.

What is the generally speaking the difference between qmpmonitor1-avocado-... and catch_monitor-avocado...? Are there two QMP monitors for the same VM in Avocado test cases?

> 2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds":
> 981048}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false,
> "node-name": "drive_stg0", "reason": "Invalid argument", "operation":
> "write", "action": "report"}}

So there is in fact a failure on the host. EINVAL probably means that something went wrong with the request alignment.

Can we get an strace? It should both show the failing I/O request with EINVAL (with its offset and length, hopefully showing the misalignment) and the probing of the alignment when the image file is opened.

I reupload a new failed log
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-22
(In reply to Kevin Wolf from comment #12)
> (In reply to qing.wang from comment #11)
> > There is error message .
> 
> Oh, thank you, this is important information. It seems that I looked in the
> wrong file.
> 
> What is the generally speaking the difference between
> qmpmonitor1-avocado-... and catch_monitor-avocado...? Are there two QMP
> monitors for the same VM in Avocado test cases?
> 
catch_monitor used to do something like heartbeat  checking and record screenshot
qmdmonitor used to record cases using qmp command.

> > 2022-11-22 03:28:18: {"timestamp": {"seconds": 1669105695, "microseconds":
> > 981048}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false,
> > "node-name": "drive_stg0", "reason": "Invalid argument", "operation":
> > "write", "action": "report"}}
> 
> So there is in fact a failure on the host. EINVAL probably means that
> something went wrong with the request alignment.
> 
> Can we get an strace? It should both show the failing I/O request with
> EINVAL (with its offset and length, hopefully showing the misalignment) and
> the probing of the alignment when the image file is opened.

I reupload a new failed case log and the strace full log may refer to
http://fileshare.englab.nay.redhat.com/pub/section2/images_backup/qbugs/2141964/2022-11-22/strace.log.lz4

Took a quick look at the strace (sorry a quick look took so long), and the only EINVALs it shows are the ones that occur during probing of the I/O and buffer alignment: They’re always ten pread64()s grouped together, the first five read lengths 1/512/1024/2048/4096 to get the I/O alignment (the 4096 one succeeds), the next five similarly read to buffers that are aligned to 1/512/1024/2048/4096 to get the buffer alignment (again, the 4096 one succeeds).  No other EINVALs occur, which may indicate that it came from within qemu.  I’ll try to look into those EINVAL-generating places (especially in qcow2) to see if anything stands out.

I just noticed that this bug exists only for RHEL 8. Do we know if it can be reproduced on RHEL 9?

Here’s what I’ve been trying so far:
- As written in comment 15, I’ve looked through the strace, but found no occurrences of EINVAL that would lead to an error visible to the guest or on the QMP monitor (the only instances I found occurred during probing of the I/O alignment).
- Thus I thought maybe the error is produced by qemu itself, so I’ve looked through the source code, at places where EINVAL is generated, but did not find anything that looked like it might cause the problem seen here.
- I’ve tried to reproduce the issue myself, but so far without any luck.  (To note, I don’t have a physical device with 4k sectors, so I had to resort to using `losetup --sector-size 4096`.)

Can you perhaps see whether the issue appears also in the following configurations?
A. Using a raw storage image instead of qcow2,
B. Adding {"logical_block_size": 4096, "physical_block_size": 4096} to the device_add QMP command that adds the virtio-blk device.

Correction, I was able to reproduce the issue now, and it comes from qemu_iovec_init_extended() (called through bdrv_pad_request()): The number of I/O vector elements required for the operation (1025) exceeds IOV_MAX (1024), a limitation that 4c002cef0e9abe7135d7916c51abce47f7fc1ee2 has introduced.

I’ll try to prepare a test build tomorrow with that commit reverted.

Question is, if that’s indeed the problem, how do we resolve this?  If the internal padding process required for a RMW cycle leads to exceeding the IOV_MAX limit, we (1) can’t really ignore it (reverting the commit seems wrong), and (2) we can’t really make it the guest’s problem, as we do now.  Splitting the write into two seems like an obvious solution, but that’s complicated and may lead to various issues I cannot yet fully foresee.  Joining a couple of adjacent I/O vector elements using a bounce buffer might be simple enough and help alleviate the issue.

(In reply to Hanna Czenczek from comment #18)
> Here’s what I’ve been trying so far:
> - As written in comment 15, I’ve looked through the strace, but found no
> occurrences of EINVAL that would lead to an error visible to the guest or on
> the QMP monitor (the only instances I found occurred during probing of the
> I/O alignment).
> - Thus I thought maybe the error is produced by qemu itself, so I’ve looked
> through the source code, at places where EINVAL is generated, but did not
> find anything that looked like it might cause the problem seen here.
> - I’ve tried to reproduce the issue myself, but so far without any luck. 
> (To note, I don’t have a physical device with 4k sectors, so I had to resort
> to using `losetup --sector-size 4096`.)
> 
> Can you perhaps see whether the issue appears also in the following
> configurations?
> A. Using a raw storage image instead of qcow2,

raw format still hit same issue

http://fileshare.hosts.qa.psi.pek2.redhat.com/pub/section2/images_backup/qbugs/2141964/2023-03-03/job-2023-03-03T02.42-745083f/

> B. Adding {"logical_block_size": 4096, "physical_block_size": 4096} to the
> device_add QMP command that adds the virtio-blk device.

Created attachment 1947687 [details]
Simpler reproducer

I think the issue can be reproduced much more simply (assuming the build I posted over on BZ 2174676 does indeed “fix” it): Running a pwritev() in a guest with 1024 I/O vectors to an area that is only aligned to 512 bytes, while the host disk has 4k sectors, yields I/O errors in the guest (reported by the kernel).

I.e., use as follows:
$ qemu-system-x86_64 \
    -enable-kvm -m 1G \
    -blockdev host_device,node-name=stg,filename=/dev/loop0,cache.direct=on \
    -blockdev file,node-name=sys-prot,filename=${guest-os-disk}.qcow2 \
    -blockdev qcow2,node-name=sys-fmt,file=sys-prot \
    -device virtio-blk,drive=sys-fmt \
    -device virtio-blk,drive=stg \
    -qmp stdio
{"QMP": {"version": {"qemu": {"micro": 0, "minor": 2, "major": 7}, "package": "qemu-foo-bar"}, "capabilities": ["oob"]}}
{"execute":"qmp_capabilities"}
{"return": {}}

Then, in the guest:
$ sudo pwritev 512 1024 /dev/vdb
[   19.098402] I/O error, dev vdb, sector 1 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
[   19.098500] I/O error, dev vdb, sector 127 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
[   19.098530] I/O error, dev vdb, sector 253 op 0x1:(WRITE) flags 0x8800 phys_seg 4 prio class 2
[   19.098580] I/O error, dev vdb, sector 257 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
[   19.098620] I/O error, dev vdb, sector 383 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
[   19.098650] I/O error, dev vdb, sector 509 op 0x1:(WRITE) flags 0x8800 phys_seg 4 prio class 2
[   19.098684] I/O error, dev vdb, sector 513 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
[   19.098732] I/O error, dev vdb, sector 639 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
[   19.098762] I/O error, dev vdb, sector 765 op 0x1:(WRITE) flags 0x8800 phys_seg 4 prio class 2
[   19.098797] I/O error, dev vdb, sector 769 op 0x1:(WRITE) flags 0xc800 phys_seg 126 prio class 2
Writing failed: Input/output error

And in the QMP monitor:

{"timestamp": {"seconds": 1677847471, "microseconds": 716262}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716347}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716384}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716424}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716464}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716498}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716536}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716577}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716610}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716647}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716687}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}
{"timestamp": {"seconds": 1677847471, "microseconds": 716725}, "event": "BLOCK_IO_ERROR", "data": {"device": "", "nospace": false, "node-name": "stg", "reason": "Das Argument ist ung\u00FCltig", "operation": "write", "action": "report"}}

Addendum to comment 22: Forgot to mention the prerequisite steps to get a /dev/loop0 to test:
$ truncate -s 1G ~/tmp/fs.img
$ sudo losetup -f --show --sector-size 4096 --direct-io=on ~/tmp/fs.img
/dev/loop0


Alternatively, the issue can also be seen entirely without a guest:

$ truncate -s 1G ~/tmp/fs.img
$ sudo losetup -f --show --sector-size 4096 --direct-io=on ~/tmp/fs.img
/dev/loop0
$ qemu-io -f raw -t none -c "writev -P 42 512 $(yes 512 | head -n 1024 | tr '\n' ' ')" /dev/loop0
writev failed: Invalid argument
$ qemu-io -f raw -t none -c "writev -P 42 4096 $(yes 512 | head -n 1024 | tr '\n' ' ')" /dev/loop0
wrote 524288/524288 bytes at offset 4096
512 KiB, 1 ops; 00.00 sec (758.435 MiB/sec and 1516.8706 ops/sec)

QE bot(pre verify): Set 'Verified:Tested,SanityOnly' as gating/tier1 test pass.

Passed on 

Red Hat Enterprise Linux release 8.9 Beta (Ootpa)
4.18.0-504.el8.x86_64
qemu-kvm-6.2.0-37.module+el8.9.0+19491+15e62c0a.x86_64
seabios-bin-1.16.0-3.module+el8.9.0+18724+20190c23.noarch
edk2-ovmf-20220126gitbb1bba3d77-5.el8.noarch
libvirt-8.0.0-21.module+el8.9.0+19166+e262ca96.x86_64
virtio-win-prewhql-0.1-239.iso


python ConfigTest.py --testcase=hotplug_unplug_during_io_repeat.default,block_io_with_unaligned_offset --iothread_scheme=roundrobin --nr_iothreads=2 --platform=x86_64 --guestname=RHEL.9.3.0 --driveformat=virtio_blk --imageformat=qcow2 --machines=q35 --customsparams="vm_mem_limit = 12G\nimage_aio=native"  --firmware=default_bios --netdst=virbr0 --nrepeat=20

Verified according to comment #38 result.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Moderate: virt:rhel and virt-devel:rhel security, bug fix, and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2023:6980