<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=Windows-1252">
</head>
<body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; color: rgb(0, 0, 0); font-size: 14px; font-family: Calibri, sans-serif;">
<div>Dear all,</div>
<div><br>
</div>
<div>We are experiencing this problem over and over again with different Vms, the situation is as follows</div>
<ul>
<li>we are backing up all VM’s through iterating through the VM (see attached python file) which basically follow the recommendations</li><li>This process run well for a while but at some point we get a problem with a random VM (it is always different machines) the backup process tries to remove all snapshots and this is in the log files</li></ul>
<div><br>
</div>
<div>Vdsm.log</div>
<div><— snip —></div>
<div>
<div>Thread-8246::DEBUG::2015-05-27 16:56:00,003::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 68 edom: 10 level: 2 message: Timed out during operation: cannot acquire state change lock</div>
<div>Thread-8246::ERROR::2015-05-27 16:56:00,016::vm::5761::vm.Vm::(queryBlockJobs) vmId=`84da8d5e-4a9d-4272-861a-a706ebce3160`::Error getting block job info</div>
<div>Traceback (most recent call last):</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 5759, in queryBlockJobs</div>
<div> liveInfo = self._dom.blockJobInfo(drive.name, 0)</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 697, in f</div>
<div> raise toe</div>
<div>TimeoutError: Timed out during operation: cannot acquire state change lock</div>
<div>VM Channels Listener::DEBUG::2015-05-27 16:56:00,561::vmchannels::96::vds::(_handle_timeouts) Timeout on fileno 55.</div>
</div>
<div><— snip —></div>
<div><br>
</div>
<div>Syslog / journarctl</div>
<div><— snip —></div>
<div>
<div>May 27 16:55:15 mc-dc3ham-compute-04-live.mc.mcon.net libvirtd[1751]: Cannot start job (modify, none) for domain fab-cms-app-01-live-fab-mcon-net; current job is (modify, none) owned by (1780, 0)</div>
<div>May 27 16:55:15 mc-dc3ham-compute-04-live.mc.mcon.net libvirtd[1751]: Timed out during operation: cannot acquire state change lock</div>
<div>May 27 16:55:15 mc-dc3ham-compute-04-live.mc.mcon.net vdsm[10478]: vdsm vm.Vm ERROR vmId=`84da8d5e-4a9d-4272-861a-a706ebce3160`::Error getting block job info</div>
<div> Traceback (most recent call last):</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 5759, in queryBlockJobs</div>
<div> liveInfo = self._dom.blockJobInfo(drive.name, 0)</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 697, in f</div>
<div> raise toe</div>
<div> TimeoutError: Timed out during operation: cannot acquire state change lock</div>
</div>
<div><— snip —> </div>
<div><br>
</div>
<div>The result is, that the VM is non-operational, the qemu process is running and ovirt show it with a “?”, this itself would not be that bad if we could recover from this problem, but the only thing we found so far to resolve this, is to put the hypervisor
host in maintenance and then with the last VM with the “?” reboot it, we found no other way that allowed us to reboot this VM.</div>
<div>Even after actually killing the qemu process, there is no way to do anything with this VM.</div>
<div><br>
</div>
<div>I think i understand that the problem arises when 2 threads are making requests against the same VM, however, in the last case the VM was not doing anything else as far as we can see.</div>
<div><br>
</div>
<div>I found a bug that seems to be very similar (‘a little older though) in launchpad, but libvirt related.</div>
<div><br>
</div>
<div><a href="https://bugs.launchpad.net/nova/+bug/1254872">https://bugs.launchpad.net/nova/+bug/1254872</a></div>
<div><br>
</div>
<div>These are the libvirt versions on the server</div>
<div><br>
</div>
<div>
<div>libvirt-daemon-driver-nwfilter-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-driver-interface-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-driver-storage-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-lock-sanlock-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-client-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-config-nwfilter-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-driver-secret-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-driver-qemu-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-python-1.2.8-7.el7_1.1.x86_64</div>
<div>libvirt-daemon-driver-nodedev-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-driver-network-1.2.8-16.el7_1.3.x86_64</div>
<div>libvirt-daemon-kvm-1.2.8-16.el7_1.3.x86_64</div>
</div>
<div><br>
</div>
<div>VDSM version</div>
<div>
<div>vdsm-python-4.16.14-0.el7.noarch</div>
<div>vdsm-jsonrpc-4.16.14-0.el7.noarch</div>
<div>vdsm-yajsonrpc-4.16.14-0.el7.noarch</div>
<div>vdsm-4.16.14-0.el7.x86_64</div>
<div>vdsm-python-zombiereaper-4.16.14-0.el7.noarch</div>
<div>vdsm-cli-4.16.14-0.el7.noarch</div>
<div>vdsm-xmlrpc-4.16.14-0.el7.noarch</div>
</div>
<div><br>
</div>
<div>Kernel</div>
<div>3.10.0-229.4.2.el7.x86_64</div>
<div><br>
</div>
<div><br>
</div>
<div>Any idea where to go ?</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div>Regards</div>
<div>Soeren </div>
<div><br>
</div>
<div><br>
</div>
<span id="OLK_SRC_BODY_SECTION">
<div style="font-family:Calibri; font-size:11pt; text-align:left; color:black; BORDER-BOTTOM: medium none; BORDER-LEFT: medium none; PADDING-BOTTOM: 0in; PADDING-LEFT: 0in; PADDING-RIGHT: 0in; BORDER-TOP: #b5c4df 1pt solid; BORDER-RIGHT: medium none; PADDING-TOP: 3pt">
<span style="font-weight:bold">From: </span>Soeren Malchow <<a href="mailto:soeren.malchow@mcon.net">soeren.malchow@mcon.net</a>><br>
<span style="font-weight:bold">Date: </span>Monday 25 May 2015 22:27<br>
<span style="font-weight:bold">To: </span>"<a href="mailto:users@ovirt.org">users@ovirt.org</a>" <<a href="mailto:users@ovirt.org">users@ovirt.org</a>><br>
<span style="font-weight:bold">Subject: </span>[ovirt-users] VM crashes during snapshot/clone/export and show only "?"<br>
</div>
<div><br>
</div>
<div>
<div style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; color: rgb(0, 0, 0); font-size: 14px; font-family: Calibri, sans-serif;">
<div>Dear all,</div>
<div><br>
</div>
<div>In version 3.5.2 on CentOS 7.1 we now have the problem that the backup script seems to trigger a crash of Vms, this is the second time, the first time i could only solve the problem by rebooting the hypervisor host and acknowleding “host has been rebooted”</div>
<div><br>
</div>
<div>This problems happens while removing snapshots after snapshot –> clone -> export procedures.</div>
<div><br>
</div>
<div>The actual qemu process is still running after following log output, but the VM is not responsive anymore, i can kill the process problem.</div>
<div><br>
</div>
<div>Two questions for this:</div>
<div><br>
</div>
<div>How can I avoid this problem ?</div>
<div>Is there a way to tell ovirt that the qemu process is gone and that the VM can be started again ? </div>
<div><br>
</div>
<div><— snip —> </div>
<div>
<div>May 25 22:03:47 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: metadata not found: Requested metadata element is not present</div>
<div>May 25 22:03:47 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: metadata not found: Requested metadata element is not present</div>
<div>May 25 22:03:48 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: internal error: End of file from monitor</div>
<div>May 25 22:03:48 mc-dc3ham-compute-02-live.mc.mcon.net kernel: IDMZ_MC_PUBLIC: port 3(vnet3) entered disabled state</div>
<div>May 25 22:03:48 mc-dc3ham-compute-02-live.mc.mcon.net kernel: device vnet3 left promiscuous mode</div>
<div>May 25 22:03:48 mc-dc3ham-compute-02-live.mc.mcon.net kernel: IDMZ_MC_PUBLIC: port 3(vnet3) entered disabled state</div>
<div>May 25 22:03:48 mc-dc3ham-compute-02-live.mc.mcon.net kvm[22973]: 15 guests now active</div>
<div>May 25 22:03:48 mc-dc3ham-compute-02-live.mc.mcon.net systemd-machined[14412]: Machine qemu-mc-glpi-app-01-live.mc.mcon.net terminated.</div>
<div>May 25 22:04:11 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: Cannot start job (modify, none) for domain mc-glpi-app-01-live.mc.mcon.net; current job is (modify, none) own</div>
<div>ed by (1534, 0)</div>
<div>May 25 22:04:11 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: Timed out during operation: cannot acquire state change lock</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: Cannot start job (modify, none) for domain mc-glpi-app-01-live.mc.mcon.net; current job is (modify, none) own</div>
<div>ed by (1534, 0)</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: Timed out during operation: cannot acquire state change lock</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: metadata not found: Requested metadata element is not present</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net vdsm[3230]: vdsm vm.Vm ERROR vmId=`598bdf61-2f2c-4569-9513-93043890f676`::Error getting block job info</div>
<div> Traceback (most recent call last):</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 5759, in queryBlockJobs</div>
<div> liveInfo = self._dom.blockJobInfo(drive.name, 0)</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 697, in f</div>
<div> raise toe</div>
<div> TimeoutError: Timed out during operation: cannot acquire state change lock</div>
</div>
<div><— snip —></div>
<div><br>
</div>
<div><br>
</div>
<div><— snip —></div>
<div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net vdsm[3230]: vdsm vm.Vm ERROR vmId=`598bdf61-2f2c-4569-9513-93043890f676`::Stats function failed: <AdvancedStatsFunction _samp</div>
<div> Traceback (most recent call last):</div>
<div> File "/usr/share/vdsm/virt/sampling.py", line 484, in collect</div>
<div> statsFunction()</div>
<div> File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__</div>
<div> retValue = self._function(*args, **kwargs)</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 346, in _sampleVmJobs</div>
<div> return self._vm.queryBlockJobs()</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 5759, in queryBlockJobs</div>
<div> liveInfo = self._dom.blockJobInfo(drive.name, 0)</div>
<div> AttributeError: 'NoneType' object has no attribute 'blockJobInfo'</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: metadata not found: Requested metadata element is not present</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: metadata not found: Requested metadata element is not present</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net libvirtd[1386]: metadata not found: Requested metadata element is not present</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net vdsm[3230]: vdsm vm.Vm ERROR vmId=`598bdf61-2f2c-4569-9513-93043890f676`::Stats function failed: <AdvancedStatsFunction _samp</div>
<div> Traceback (most recent call last):</div>
<div> File "/usr/share/vdsm/virt/sampling.py", line 484, in collect</div>
<div> statsFunction()</div>
<div> File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__</div>
<div> retValue = self._function(*args, **kwargs)</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 338, in _sampleVcpuPinning</div>
<div> vCpuInfos = self._vm._dom.vcpus()</div>
<div> AttributeError: 'NoneType' object has no attribute 'vcpus'</div>
<div>May 25 22:04:18 mc-dc3ham-compute-02-live.mc.mcon.net vdsm[3230]: vdsm vm.Vm ERROR vmId=`598bdf61-2f2c-4569-9513-93043890f676`::Stats function failed: <AdvancedStatsFunction _samp</div>
<div> Traceback (most recent call last):</div>
<div> File "/usr/share/vdsm/virt/sampling.py", line 484, in collect</div>
<div> statsFunction()</div>
<div> File "/usr/share/vdsm/virt/sampling.py", line 359, in __call__</div>
<div> retValue = self._function(*args, **kwargs)</div>
<div> File "/usr/share/vdsm/virt/vm.py", line 349, in _sampleCpuTune</div>
<div> infos = self._vm._dom.schedulerParameters()</div>
<div> AttributeError: 'NoneType' object has no attribute ‘schedulerParameters'</div>
</div>
<div><br>
</div>
<div><— snip —> </div>
</div>
</div>
</span>
</body>
</html>