Bug 1918211
| Summary: | Input/output error when cancelling the migration of --copy-storage-all --p2p | ||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 9 | Reporter: | Han Han <hhan> | ||||||||
| Component: | libvirt | Assignee: | Michal Privoznik <mprivozn> | ||||||||
| libvirt sub component: | General | QA Contact: | Han Han <hhan> | ||||||||
| Status: | CLOSED WONTFIX | Docs Contact: | |||||||||
| Severity: | low | ||||||||||
| Priority: | low | CC: | fjin, jdenemar, jsuchane, kchamart, lmen, mprivozn, pkrempa, virt-maint, yalzhang | ||||||||
| Version: | 9.0 | Keywords: | Triaged, Upstream | ||||||||
| Target Milestone: | rc | ||||||||||
| Target Release: | --- | ||||||||||
| Hardware: | Unspecified | ||||||||||
| OS: | Unspecified | ||||||||||
| Whiteboard: | |||||||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||||||
| Doc Text: | Story Points: | --- | |||||||||
| Clone Of: | Environment: | ||||||||||
| Last Closed: | 2022-07-20 07:27:55 UTC | Type: | Bug | ||||||||
| Regression: | --- | Mount Type: | --- | ||||||||
| Documentation: | --- | CRM: | |||||||||
| Verified Versions: | Category: | --- | |||||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||||
| Cloudforms Team: | --- | Target Upstream Version: | 7.6.0 | ||||||||
| Embargoed: | |||||||||||
| Attachments: |
|
||||||||||
The error happens at: 2021-01-20 01:19:50.754+0000: 106219: error : virNetSocketReadWire:1814 : End of file while reading data: : Input/output error A slightly more useful context is:
2021-01-20 01:19:50.748+0000: 106219: info : qemuMonitorSend:950 : QEMU_MONITOR_SEND_MSG: mon=0x7f30b80441d0 msg={"execute":"migrate-set-parameters","arguments":{"compress-level":1,"compress-threads":8,"decompress-threads":2,"cpu-throttle-initial":20,"cpu-throttle-increment":10,"tls-creds":"","tls-hostname":"","max-bandwidth":134217728,"downtime-limit":300,"block-incremental":false,"xbzrle-cache-size":67108864,"max-postcopy-bandwidth":0,"multifd-channels":2},"id":"libvirt-452"}
fd=-1
2021-01-20 01:19:50.748+0000: 107252: info : qemuMonitorIOWrite:437 : QEMU_MONITOR_IO_WRITE: mon=0x7f30b80441d0 buf={"execute":"migrate-set-parameters","arguments":{"compress-level":1,"compress-threads":8,"decompress-threads":2,"cpu-throttle-initial":20,"cpu-throttle-increment":10,"tls-creds":"","tls-hostname":"","max-bandwidth":134217728,"downtime-limit":300,"block-incremental":false,"xbzrle-cache-size":67108864,"max-postcopy-bandwidth":0,"multifd-channels":2},"id":"libvirt-452"}
len=371 ret=371 errno=0
2021-01-20 01:19:50.751+0000: 107252: debug : qemuMonitorJSONIOProcessLine:222 : Line [{"return": {}, "id": "libvirt-452"}]
2021-01-20 01:19:50.751+0000: 107252: info : qemuMonitorJSONIOProcessLine:242 : QEMU_MONITOR_RECV_REPLY: mon=0x7f30b80441d0 reply={"return": {}, "id": "libvirt-452"}
2021-01-20 01:19:50.751+0000: 106219: debug : qemuDomainObjExitMonitorInternal:5726 : Exited monitor (mon=0x7f30b80441d0 vm=0x7f30bc1aca70 name=seabios)
2021-01-20 01:19:50.751+0000: 106219: debug : qemuDomainObjEndJob:1143 : Stopping job: async nested (async=migration out vm=0x7f30bc1aca70 name=seabios)
2021-01-20 01:19:50.751+0000: 106219: debug : qemuDomainObjEnterRemote:5833 : Entering remote (vm=0x7f30bc1aca70 name=seabios)
2021-01-20 01:19:50.751+0000: 106219: debug : virConnectUnregisterCloseCallback:1479 : conn=0x7f30ac00e8d0
2021-01-20 01:19:50.752+0000: 106219: debug : qemuDomainObjExitRemote:5844 : Exited remote (vm=0x7f30bc1aca70 name=seabios)
2021-01-20 01:19:50.754+0000: 106219: error : virNetSocketReadWire:1814 : End of file while reading data: : Input/output error
2021-01-20 01:19:50.754+0000: 106219: debug : virObjectEventStateDispose:518 : obj=0x7f30bc1cd240
2021-01-20 01:19:50.754+0000: 106219: debug : qemuMigrationSrcRestoreDomainState:140 : driver=0x7f30bc112be0, vm=0x7f30bc1aca70, pre-mig-state=nostate, state=running, reason=booted
2021-01-20 01:19:50.754+0000: 106219: debug : qemuDomainObjEndAsyncJob:1181 : Stopping async job: migration out (vm=0x7f30bc1aca70 name=seabios)
It happens after the migration is cancelled when presumably closing the connection to the destination.
See also: Bug 1821277 - virNetSocketReadWire:1806 : End of file while reading data: Input/output error They may be same issue, and chhu has managed to reproduce bug 1821277 with just "start&&destroy vm" for multiple times(bug 1821277 comment 19) (In reply to Fangge Jin from comment #3) > See also: Bug 1821277 - virNetSocketReadWire:1806 : End of file while > reading data: Input/output error > They may be same issue, and chhu has managed to reproduce bug 1821277 with > just "start&&destroy vm" for multiple times(bug 1821277 comment 19) No, in the end it wasn't because what chhu did was 'CTRL+C' virsh. Which of course leads to the I/O error message because the connection was not closed cleanly. I've summarized that in bug 1821277#c29. @hhan Although you said reproduce rate is 90%, I can't reproduce it at all (In reply to Fangge Jin from comment #5) > @hhan > Although you said reproduce rate is 90%, I can't reproduce it at all Yes. I cannot reproduce that in physical machines, either. But reproduced in nested VMs The error is printed as a result of this code: src/qemu/qemu_migration.c=5064=qemuMigrationSrcPerformPeer2Peer(virQEMUDriver *driver, -- src/qemu/qemu_migration.c-5216- cleanup: src/qemu/qemu_migration.c-5217- virErrorPreserveLast(&orig_err); src/qemu/qemu_migration.c:5218: qemuDomainObjEnterRemote(vm); src/qemu/qemu_migration.c-5219- virConnectUnregisterCloseCallback(dconn, qemuMigrationSrcConnectionClosed); src/qemu/qemu_migration.c-5220- ignore_value(qemuDomainObjExitRemote(vm, false)); src/qemu/qemu_migration.c-5221- virErrorRestore(&orig_err); src/qemu/qemu_migration.c-5222- return ret; src/qemu/qemu_migration.c-5223-} More specifically in virConnectUnregisterCloseCallback() which tries to call REMOTE_PROC_CONNECT_UNREGISTER_CLOSE_CALLBACK on the remote side. While I agree that polluting logs with I/O errors doesn't look good, it's also a harmless message. But I think I have an idea how to fix it. Patch proposed upstream: https://listman.redhat.com/archives/libvir-list/2021-July/msg00525.html Merged upstream as: bab44aa963 qemu_migration: Unregister close callback only if connection still exists v7.5.0-134-gbab44aa963 Michal, please check the results of comment11 Created attachment 1805869 [details]
The VM xml and libvirtd.log
Tested on libvirt v7.5.0-246-gcd72f0cd9f qemu-6.0.0-11.fc35.x86_64 as the bug report
Sometimes it will trigger this error when cancelling migration:
error: End of file while reading data: virt-ssh-helper: could not proxy traffic: End of file while reading data: Input/output error: Input/output error
Han, I'm sorry but I'm unable to reproduce. The message is harmless though. Nevertheless, can you please attach GDB and try to get stacktrace when the error is reproduced? It should be sufficient to set breakpoint on virReportSystemErrorFull() and once the breakpoint is hit then get backtrace. I would get it myself, but I'm unable to reproduce the problem. Not sure if it can be reproduced on libvirt-v7.6.0-rc2 qemu-6.0.0-12.fc35.x86_64 because of the blocker issue https://gitlab.com/libvirt/libvirt/-/issues/197 Tested on libvirt-7.6.0-1.module+el8.5.0+12097+2c77910b.x86_64 qemu-kvm-6.0.0-26.module+el8.5.0+12044+525f0ebc.x86_64, but the reproducing steps are blocked by BZ1989415 after several loops. So I am not sure if this bug is really fixed. Created attachment 1816821 [details] The libvirtd log during "error: End of file while reading data: : Input/output error" Reproduced on libvirt-7.6.0-2.module+el8.5.0+12219+a5ea13d2.x86_64 qemu-kvm-6.0.0-28.module+el8.5.0+12271+fffa967b.x86_64 as the cases of https://bugzilla.redhat.com/show_bug.cgi?id=1989415#c9 Script output: ➜ bug bash run-io.sh Mon Aug 23 06:23:26 EDT 2021 It will sleep for 16.17 Mon Aug 23 06:23:42 EDT 2021 It will sleep for 16.18 error: operation aborted: migration out: canceled by client Mon Aug 23 06:23:59 EDT 2021 It will sleep for 17.42 error: operation aborted: migration out: canceled by client Mon Aug 23 06:24:16 EDT 2021 It will sleep for 16.49 error: operation aborted: migration out: canceled by client Mon Aug 23 06:24:33 EDT 2021 It will sleep for 18.75 error: End of file while reading data: : Input/output error Mon Aug 23 06:24:52 EDT 2021 It will sleep for 16.3 error: operation aborted: migration out: canceled by client FailedQA according to comment19 I couldn't really find the source of the problem. However, it doesn't really matter whether one gets I/O error or cancelled error. Therefore I think this bug can be closed. Any objections? (In reply to Michal Privoznik from comment #21) > I couldn't really find the source of the problem. However, it doesn't really > matter whether one gets I/O error or cancelled error. Therefore I think this > bug can be closed. Any objections? What makes the bug strange is that the 'I/O error' is never reproduced at physical host but reproduced often in nest-virt hosts. I think it is better to keep it open until we find the real reason. Bulk update: Move RHEL-AV bugs to RHEL9. If necessary to resolve in RHEL8, then clone to the current RHEL8 release. After evaluating this issue, there are no plans to address it further or fix it in an upcoming release. Therefore, it is being closed. If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened. |
Created attachment 1749009 [details] VM xml, libvirtd log, qmp log Description of problem: As subject Version-Release number of selected component (if applicable): libvirt-7.0.0-2.module+el8.4.0+9520+ef609c5f.x86_64 qemu-kvm-5.2.0-3.module+el8.4.0+9499+42e58f08.x86_64 How reproducible: 90% Steps to Reproduce: 1.Prepare a running VM and the migration env 2. The cancel migration loop as following: DOM=seabios for i in {1..200};do virsh migrate $DOM qemu+ssh://root@XXXX/system --live --copy-storage-all --p2p & sleep_time=$((10 + $RANDOM % 52)) echo "It will sleep for $sleep_time" sleep $sleep_time virsh domjobabort $DOM wait done The the error will happen at the wait result of virsh migrate: error: operation aborted: migration out: canceled by client You can also reproduce it by run `virsh migrate $DOM qemu+ssh://root@XXXX/system --live --copy-storage-all --p2p` and the interrupt it by CTRL+C Actual results: As subject Expected results: No error Additional info: