<html xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"> <head> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> <meta name="标题" content=""> <meta name="关键词" content=""> <meta name="Generator" content="Microsoft Word 15 (filtered medium)"> <style></style> </head> <body bgcolor="white" lang="ZH-CN" link="#0563C1" vlink="#954F72"> <div class="WordSection1"> Description of problem: <o:p></o:p> libvirt 3.9 on CentOS Linux release 7.4.1708 (kernel 3.10.0-693.21.1.el7.x86_64) on Qemu version 2.10.0 <o:p></o:p> <o:p> </o:p> I’m currently facing a strange situation. Sometimes my vm is shown by ‘virsh list’ as in state “in shutdown” but there is no qemu-kvm process linked to it. <o:p></o:p> <o:p> </o:p> Libvirt log when “in shutdown” state occur is as follows: <o:p></o:p> “d470c3b284425b9bacb34d3b5f3845fe” is vm’s name, remoteDispatchDomainMemoryStats API is called by ‘collectd’, which is used to collect some vm running states and host information once every 30’s. <o:p></o:p> <o:p> </o:p> 2019-07-25 14:23:58.706+0000: 15818: warning : qemuMonitorJSONIOProcessEvent:235 : type: POWERDOWN, vm: d470c3b284425b9bacb34d3b5f3845fe, cost 1.413 secs <o:p></o:p> 2019-07-25 14:23:59.601+0000: 15818: warning : qemuMonitorJSONIOProcessEvent:235 : type: SHUTDOWN, vm: d470c3b284425b9bacb34d3b5f3845fe, cost 1.202 secs <o:p></o:p> 2019-07-25 14:23:59.601+0000: 15818: warning : qemuMonitorJSONIOProcessEvent:235 : type: STOP, vm: d470c3b284425b9bacb34d3b5f3845fe, cost 1.203 secs <o:p></o:p> 2019-07-25 14:23:59.601+0000: 15818: warning : qemuMonitorJSONIOProcessEvent:235 : type: SHUTDOWN, vm: d470c3b284425b9bacb34d3b5f3845fe, cost 1.203 secs <o:p></o:p> 2019-07-25 14:23:59.629+0000: 15818: error : qemuMonitorIORead:597 : Unable to read from monitor: Connection reset by peer <o:p></o:p> 2019-07-25 14:23:59.629+0000: 121081: warning : qemuProcessEventHandler:4840 : vm: d470c3b284425b9bacb34d3b5f3845fe, event: 6 locked <o:p></o:p> 2019-07-25 14:23:59.629+0000: 15822: error : qemuMonitorJSONCommandWithFd:364 : internal error: Missing monitor reply object <o:p></o:p> 2019-07-25 14:24:29.483+0000: 15821: warning : qemuGetProcessInfo:1468 : cannot parse process status data <o:p></o:p> 2019-07-25 14:24:29.829+0000: 15823: warning : qemuDomainObjBeginJobInternal:4391 : Cannot start job (modify, none) for domain d470c3b284425b9bacb34d3b5f3845fe; current job is (query, none) owned by (15822 remoteDispatchDomainMemoryStats, 0 <null>) for (30s, 0s) <o:p></o:p> 2019-07-25 14:24:29.829+0000: 15823: error : qemuDomainObjBeginJobInternal:4403 : Timed out during operation: cannot acquire state change lock (held by remoteDispatchDomainMemoryStats) <o:p></o:p> 2019-07-25 14:24:29.829+0000: 121081: warning : qemuDomainObjBeginJobInternal:4391 : Cannot start job (destroy, none) for domain d470c3b284425b9bacb34d3b5f3845fe; current job is (query, none) owned by (15822 remoteDispatchDomainMemoryStats, 0 <null>) for (30s, 0s) <o:p></o:p> 2019-07-25 14:24:29.829+0000: 121081: error : qemuDomainObjBeginJobInternal:4403 : Timed out during operation: cannot acquire state change lock (held by remoteDispatchDomainMemoryStats) <o:p></o:p> 2019-07-25 14:24:29.829+0000: 121081: warning : qemuProcessEventHandler:4875 : vm: d470c3b284425b9bacb34d3b5f3845fe, event: 6, cost 31.459 secs <o:p></o:p> <o:p> </o:p> I’ve tried to find out how did this problem happened. I analyzed the execution process of the job and speculated that the problem occurred as follows: <o:p></o:p> step one: libvirt send command 'system_powerdown' to qemu.<o:p></o:p> step two: libvirt receive qemu monitor close event, and then deal EOF event.<o:p></o:p> step three: remoteDispatchDomainMemoryStats job start on the same vm.<o:p></o:p> step four: work thread dealing stop job is waited on job.cond, the timeout is 30s.<o:p></o:p> <o:p> </o:p> It seems that the remoteDispatchDomainMemoryStats job is too slow to let the stop job wait timeout. <o:p></o:p> <o:p> </o:p> Then I tried to reproduce this process. The step is as follows: <o:p></o:p> First step: add a sleep on ‘qemuProcessEventHandler' by using pthread_cond_timedwait. So can execute 'virsh dommemstat active’ command at this time interval. <o:p></o:p> Second step: start a vm to test <o:p></o:p> Third step: execute 'virsh shutdown active’ to shutdown the vm <o:p></o:p> Fourth step: execute 'virsh dommemstat active’ when stop job is sleep. <o:p></o:p> <o:p> </o:p> Then it works. The test vm state became to 'in shutdown’, and the libvirt log is as follows: <o:p></o:p> “active” is my test vm’s name.<o:p></o:p> <o:p> </o:p> 2019-08-05 08:39:57.001+0000: 25889: warning : qemuDomainObjBeginJobInternal:4308 : Starting job: modify (vm=0x7f7bbc145fe0 name=active, current job=none async=none) <o:p></o:p> 2019-08-05 08:39:57.003+0000: 25889: warning : qemuDomainObjEndJob:4522 : Stopping job: modify (async=none vm=0x7f7bbc145fe0 name=active) <o:p></o:p> 2019-08-05 08:39:57.003+0000: 25881: warning : qemuMonitorJSONIOProcessEvent:235 : type: POWERDOWN, vm: active, cost 0.008 secs <o:p></o:p> 2019-08-05 08:39:57.854+0000: 25881: warning : qemuMonitorJSONIOProcessEvent:235 : type: SHUTDOWN, vm: active, cost 1.709 secs <o:p></o:p> 2019-08-05 08:39:57.875+0000: 25881: warning : qemuMonitorJSONIOProcessEvent:235 : type: STOP, vm: active, cost 1.751 secs <o:p></o:p> 2019-08-05 08:39:57.875+0000: 25881: warning : qemuMonitorJSONIOProcessEvent:235 : type: SHUTDOWN, vm: active, cost 1.751 secs <o:p></o:p> 2019-08-05 08:39:57.915+0000: 25881: warning : qemuMonitorIO:756 : Error on monitor <null> <o:p></o:p> 2019-08-05 08:39:57.915+0000: 25881: warning : qemuMonitorIO:777 : Triggering EOF callback <o:p></o:p> 2019-08-05 08:39:57.915+0000: 26915: warning : qemuProcessEventHandler:4822 : usleep 20s <o:p></o:p> 2019-08-05 08:40:01.004+0000: 25886: warning : qemuDomainObjBeginJobInternal:4308 : Starting job: query (vm=0x7f7bbc145fe0 name=active, current job=none async=none) <o:p></o:p> ^@2019-08-05 08:40:17.915+0000: 26915: warning : qemuProcessEventHandler:4845 : vm=0x7f7bbc145fe0, event=6 <o:p></o:p> 2019-08-05 08:40:17.915+0000: 26915: warning : qemuProcessEventHandler:4851 : vm: active, event: 6 locked <o:p></o:p> 2019-08-05 08:40:17.915+0000: 26915: warning : qemuDomainObjBeginJobInternal:4308 : Starting job: destroy (vm=0x7f7bbc145fe0 name=active, current job=query async=none) <o:p></o:p> 2019-08-05 08:40:17.915+0000: 26915: warning : qemuDomainObjBeginJobInternal:4344 : Waiting for job (vm=0x7f7bbc145fe0 name=active), job 26915 qemuProcessEventHandler, owned by 25886 remoteDispatchDomainMemoryStats <o:p></o:p> ^@^@^@2019-08-05 08:40:47.915+0000: 26915: warning : qemuDomainObjBeginJobInternal:4405 : Cannot start job (destroy, none) for domain active; current job is (query, none) owned by (25886 remoteDispatchDomainMemoryStats, 0 <null>) for (46s, 0s) <o:p></o:p> 2019-08-05 08:40:47.915+0000: 26915: error : qemuDomainObjBeginJobInternal:4417 : 操作超时：cannot acquire state change lock (held by remoteDispatchDomainMemoryStats) <o:p></o:p> 2019-08-05 08:40:47.915+0000: 26915: warning : qemuProcessEventHandler:4886 : vm: active, event: 6, cost 31.830 secs <o:p></o:p> <o:p> </o:p> The threads backtraces is as follows: <o:p></o:p> [Switching to thread 17 (Thread 0x7f12fddf5700 (LWP 32580))] <o:p></o:p> #2 0x00007f12eb26df21 in qemuMonitorSend (mon=mon@entry=0x7f12d0013af0, <o:p></o:p> msg=msg@entry=0x7f12fddf46e0) at qemu/qemu_monitor.c:1075 <o:p></o:p> 1075 if (virCondWait(&mon->notify, &mon->parent.lock) < 0) { <o:p></o:p> (gdb) l <o:p></o:p> 1070 PROBE(QEMU_MONITOR_SEND_MSG, <o:p></o:p> 1071 "mon=%p msg=%s fd=%d", <o:p></o:p> 1072 mon, mon->msg->txBuffer, mon->msg->txFD); <o:p></o:p> 1073 <o:p></o:p> 1074 while (mon && mon->msg && !mon->msg->finished) { <o:p></o:p> 1075 if (virCondWait(&mon->notify, &mon->parent.lock) < 0) { <o:p></o:p> 1076 virReportError(VIR_ERR_INTERNAL_ERROR, "%s", <o:p></o:p> 1077 _("Unable to wait on monitor condition")); <o:p></o:p> 1078 goto cleanup; <o:p></o:p> 1079 } <o:p></o:p> (gdb) p *msg <o:p> </o:p> $2 = {txFD = -1, <o:p></o:p> txBuffer = 0x7f12b8000d50 "{\"execute\":\"qom-list\",\"arguments\":{\"path\":\"/machine/peripheral\"},\"id\":\"libvirt-17\"}\r\n", txOffset = 0, <o:p></o:p> txLength = 85, rxBuffer = 0x0, rxLength = 0, rxObject = 0x0, <o:p></o:p> finished = false, passwordHandler = 0x0, passwordOpaque = 0x0} <o:p></o:p> (gdb) bt <o:p></o:p> #0 pthread_cond_wait@@GLIBC_2.3.2 () <o:p></o:p> at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 <o:p></o:p> #1 0x00007f130d738316 in virCondWait (c=c@entry=0x7f12d0013b28, <o:p></o:p> m=m@entry=0x7f12d0013b00) at util/virthread.c:154 <o:p></o:p> #2 0x00007f12eb26df21 in qemuMonitorSend (mon=mon@entry=0x7f12d0013af0, <o:p></o:p> msg=msg@entry=0x7f12fddf46e0) at qemu/qemu_monitor.c:1075 <o:p></o:p> #3 0x00007f12eb283b40 in qemuMonitorJSONCommandWithFd ( <o:p></o:p> mon=mon@entry=0x7f12d0013af0, cmd=cmd@entry=0x7f12b80008c0, <o:p></o:p> scm_fd=scm_fd@entry=-1, reply=reply@entry=0x7f12fddf4780) <o:p></o:p> at qemu/qemu_monitor_json.c:355 <o:p></o:p> #4 0x00007f12eb2904b9 in qemuMonitorJSONCommand (reply=0x7f12fddf4780, <o:p></o:p> cmd=0x7f12b80008c0, mon=0x7f12d0013af0) at qemu/qemu_monitor_json.c:385 <o:p></o:p> ... <o:p></o:p> <o:p> </o:p> I found that on function ‘qemuMonitorUpdateWatch’, if mon->watch is zero, then event would’t be update. But 'qemuMonitorSend' <o:p></o:p> would still wait on mon->notify. So the remoteDispatchDomainMemoryStats job is blocked, and then the stop job blocked too. <o:p></o:p> 618 static void <o:p> </o:p> 619 qemuMonitorUpdateWatch(qemuMonitorPtr mon) <o:p></o:p> 620 { <o:p></o:p> 621 int events = <o:p></o:p> 622 VIR_EVENT_HANDLE_HANGUP | <o:p></o:p> 623 VIR_EVENT_HANDLE_ERROR; <o:p></o:p> 624 <o:p></o:p> 625 if (!mon->watch) <o:p></o:p> 626 return; <o:p></o:p> 627 <o:p></o:p> 628 if (mon->lastError.code == VIR_ERR_OK) { <o:p></o:p> 629 events |= VIR_EVENT_HANDLE_READABLE; <o:p></o:p> 630 <o:p></o:p> 631 if ((mon->msg && mon->msg->txOffset < mon->msg->txLength) && <o:p></o:p> 632 !mon->waitGreeting) <o:p></o:p> 633 events |= VIR_EVENT_HANDLE_WRITABLE; <o:p></o:p> 634 } <o:p></o:p> 635 <o:p></o:p> 636 virEventUpdateHandle(mon->watch, events); <o:p></o:p> 637 } <o:p></o:p> <o:p> </o:p> I try to fix this bugs by add a judgment before qemuMonitorUpdateWatch, and it seem works. <o:p></o:p> 1046 int <o:p></o:p> 1047 qemuMonitorSend(qemuMonitorPtr mon, <o:p></o:p> 1048 qemuMonitorMessagePtr msg) <o:p></o:p> 1049 { <o:p></o:p> 1050 int ret = -1; <o:p></o:p> 1051 <o:p></o:p> 1052 /* Check whether qemu quit unexpectedly */ <o:p></o:p> 1053 if (mon->lastError.code != VIR_ERR_OK) { <o:p></o:p> 1054 VIR_DEBUG("Attempt to send command while error is set %s", <o:p></o:p> 1055 NULLSTR(mon->lastError.message)); <o:p></o:p> 1056 virSetError(&mon->lastError); <o:p></o:p> 1057 return -1; <o:p></o:p> 1058 } <o:p> </o:p> 1059 <o:p></o:p> 1060 if (!mon->watch) { <o:p></o:p> 1061 VIR_WARN("Attempt to send command while mon->watch is zero"); <o:p></o:p> 1062 virReportError(VIR_ERR_INTERNAL_ERROR, "%s", <o:p></o:p> 1063 _("attempt to send command when the monitor is closing")); <o:p></o:p> 1064 return -1; <o:p></o:p> 1065 } <o:p> </o:p> 1066 <o:p></o:p> 1067 mon->msg = msg; <o:p></o:p> 1068 qemuMonitorUpdateWatch(mon); <o:p></o:p> 1069 <o:p></o:p> 1070 PROBE(QEMU_MONITOR_SEND_MSG, <o:p></o:p> 1071 "mon=%p msg=%s fd=%d", <o:p></o:p> 1072 mon, mon->msg->txBuffer, mon->msg->txFD); <o:p></o:p> 1073 <o:p></o:p> 1074 while (mon && mon->msg && !mon->msg->finished) { <o:p></o:p> 1075 if (virCondWait(&mon->notify, &mon->parent.lock) < 0) { <o:p></o:p> 1076 virReportError(VIR_ERR_INTERNAL_ERROR, "%s", <o:p></o:p> 1077 _("Unable to wait on monitor condition")); <o:p></o:p> 1078 goto cleanup; <o:p></o:p> 1079 } <o:p> </o:p> 1080 } <o:p> </o:p> 1081 <o:p></o:p> 1082 if (mon->lastError.code != VIR_ERR_OK) { <o:p></o:p> 1083 VIR_DEBUG("Send command resulted in error %s", <o:p></o:p> 1084 NULLSTR(mon->lastError.message)); <o:p></o:p> 1085 virSetError(&mon->lastError); <o:p></o:p> 1086 goto cleanup; <o:p></o:p> 1087 } <o:p> </o:p> 1088 <o:p></o:p> 1089 ret = 0; <o:p></o:p> 1090 <o:p></o:p> 1091 cleanup: <o:p> </o:p> 1092 mon->msg = NULL; <o:p></o:p> 1093 qemuMonitorUpdateWatch(mon); <o:p></o:p> 1094 <o:p></o:p> 1095 return ret; <o:p></o:p> 1096 } <o:p></o:p> <o:p> </o:p> I’m not really sure that this change will affect other process. <o:p></o:p> <o:p> </o:p> Thanks!<o:p></o:p> <o:p> </o:p> Ma haocong<o:p></o:p> <o:p> </o:p> <o:p> </o:p> </div> </body> </html>