I assumed this had something to do with bug #1929446 but it's still reproducing now:
https://46859657da8176be8119-30b0a72bc63e960bd7a500e425d4bd8d.ssl.cf5.rackcdn.com/779275/3/check/nova-live-migration/1122e93/controller/logs/libvirt/libvirtd_log.txt
86445 2021-06-24 11:16:50.947+0000: 73097: info : qemuMonitorIOWrite:450 : QEMU_MONITOR_IO_WRITE: mon=0x7f6a600d7180 buf={"execute":"migrate-incoming","arguments":{"uri":"tcp:[::]:49152"},"id":"libvirt-373"}^M 86446 len=88 ret=88 errno=0 86447 2021-06-24 11:16:50.948+0000: 73097: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"timestamp": {"seconds": 1624533410, "microseconds": 948823}, "event": "MIGRATION", "data": {"status": "setup"}}] 86448 2021-06-24 11:16:50.948+0000: 73097: info : qemuMonitorJSONIOProcessLine:234 : QEMU_MONITOR_RECV_EVENT: mon=0x7f6a600d7180 event={"timestamp": {"seconds": 1624533410, "microseconds": 948823}, "event": "MIGRATION", "data": {"status": "setup"}} 86449 2021-06-24 11:16:50.948+0000: 73097: debug : qemuMonitorJSONIOProcessEvent:181 : mon=0x7f6a600d7180 obj=0x55a2c5a87b20 86450 2021-06-24 11:16:50.948+0000: 73097: debug : qemuMonitorEmitEvent:1198 : mon=0x7f6a600d7180 event=MIGRATION 86451 2021-06-24 11:16:50.948+0000: 73097: debug : qemuProcessHandleEvent:549 : vm=0x7f6a600d4e70 86452 2021-06-24 11:16:50.948+0000: 73097: debug : virObjectEventNew:631 : obj=0x55a2c5a8ac10 86453 2021-06-24 11:16:50.949+0000: 73097: debug : qemuMonitorJSONIOProcessEvent:205 : handle MIGRATION handler=0x7f6a841388f0 data=0x55a2c58fec00 86454 2021-06-24 11:16:50.949+0000: 73097: debug : qemuMonitorEmitMigrationStatus:1484 : mon=0x7f6a600d7180, status=setup 86455 2021-06-24 11:16:50.949+0000: 73097: debug : qemuProcessHandleMigrationStatus:1642 : Migration of domain 0x7f6a600d4e70 instance-0000000e changed state to setup 86456 2021-06-24 11:16:50.949+0000: 73097: debug : virObjectEventDispose:124 : obj=0x55a2c5a8ac10 86457 2021-06-24 11:16:50.949+0000: 73097: debug : virNetlinkEventCallback:862 : dispatching to max 0 clients, called from event watch 7 86458 2021-06-24 11:16:50.949+0000: 73097: debug : virNetlinkEventCallback:876 : event not handled. 86459 2021-06-24 11:16:50.949+0000: 73097: debug : qemuMonitorJSONIOProcessLine:220 : Line [{"return": {}, "id": "libvirt-373"}] 86460 2021-06-24 11:16:50.949+0000: 73097: info : qemuMonitorJSONIOProcessLine:239 : QEMU_MONITOR_RECV_REPLY: mon=0x7f6a600d7180 reply={"return": {}, "id": "libvirt-373"} [..] 87097 2021-06-24 11:17:20.249+0000: 73097: error : virKeepAliveTimerInternal:137 : internal error: connection closed due to keepalive timeout
I'm going to see if I can play around with the keepalive libvirtd configurables in devstack to address this.
I assumed this had something to do with bug #1929446 but it's still reproducing now:
https:/ /46859657da8176 be8119- 30b0a72bc63e960 bd7a500e425d4bd 8d.ssl. cf5.rackcdn. com/779275/ 3/check/ nova-live- migration/ 1122e93/ controller/ logs/libvirt/ libvirtd_ log.txt
86445 2021-06-24 11:16:50.947+0000: 73097: info : qemuMonitorIOWr ite:450 : QEMU_MONITOR_ IO_WRITE: mon=0x7f6a600d7180 buf={"execute" :"migrate- incoming" ,"arguments" :{"uri" :"tcp:[ ::]:49152" },"id": "libvirt- 373"}^M IOProcessLine: 220 : Line [{"timestamp": {"seconds": 1624533410, "microseconds": 948823}, "event": "MIGRATION", "data": {"status": "setup"}}] IOProcessLine: 234 : QEMU_MONITOR_ RECV_EVENT: mon=0x7f6a600d7180 event={"timestamp": {"seconds": 1624533410, "microseconds": 948823}, "event": "MIGRATION", "data": {"status": "setup"}} IOProcessEvent: 181 : mon=0x7f6a600d7180 obj=0x55a2c5a87b20 Event:1198 : mon=0x7f6a600d7180 event=MIGRATION leEvent: 549 : vm=0x7f6a600d4e70 ew:631 : obj=0x55a2c5a8ac10 IOProcessEvent: 205 : handle MIGRATION handler= 0x7f6a841388f0 data=0x55a2c58fec00 MigrationStatus :1484 : mon=0x7f6a600d7180, status=setup leMigrationStat us:1642 : Migration of domain 0x7f6a600d4e70 instance-0000000e changed state to setup ispose: 124 : obj=0x55a2c5a8ac10 Callback: 862 : dispatching to max 0 clients, called from event watch 7 Callback: 876 : event not handled. IOProcessLine: 220 : Line [{"return": {}, "id": "libvirt-373"}] IOProcessLine: 239 : QEMU_MONITOR_ RECV_REPLY: mon=0x7f6a600d7180 reply={"return": {}, "id": "libvirt-373"} erInternal: 137 : internal error: connection closed due to keepalive timeout
86446 len=88 ret=88 errno=0
86447 2021-06-24 11:16:50.948+0000: 73097: debug : qemuMonitorJSON
86448 2021-06-24 11:16:50.948+0000: 73097: info : qemuMonitorJSON
86449 2021-06-24 11:16:50.948+0000: 73097: debug : qemuMonitorJSON
86450 2021-06-24 11:16:50.948+0000: 73097: debug : qemuMonitorEmit
86451 2021-06-24 11:16:50.948+0000: 73097: debug : qemuProcessHand
86452 2021-06-24 11:16:50.948+0000: 73097: debug : virObjectEventN
86453 2021-06-24 11:16:50.949+0000: 73097: debug : qemuMonitorJSON
86454 2021-06-24 11:16:50.949+0000: 73097: debug : qemuMonitorEmit
86455 2021-06-24 11:16:50.949+0000: 73097: debug : qemuProcessHand
86456 2021-06-24 11:16:50.949+0000: 73097: debug : virObjectEventD
86457 2021-06-24 11:16:50.949+0000: 73097: debug : virNetlinkEvent
86458 2021-06-24 11:16:50.949+0000: 73097: debug : virNetlinkEvent
86459 2021-06-24 11:16:50.949+0000: 73097: debug : qemuMonitorJSON
86460 2021-06-24 11:16:50.949+0000: 73097: info : qemuMonitorJSON
[..]
87097 2021-06-24 11:17:20.249+0000: 73097: error : virKeepAliveTim
I'm going to see if I can play around with the keepalive libvirtd configurables in devstack to address this.