[libvirt-users] virsh migrate results in error: Timed out during operation: cannot acquire state change lock

Thu Feb 9 14:00:41 UTC 2012

Hi all,

Hi have one computer hosting several VM, this particular server is in 
need of maintenance and has to be shutdown.
In order to avoid disrupting the services provided by the VM I intended 
to migrate the VM to another computer.
Computer 1 and 2 do not share any storage. So it is necessary to migrate 
not only the memory but also any data on the hard-drive.

Both computers are running debian squeeze.
Virsh is version 0.8.3.

I issue this command on server one:
sudo LIBVIRT_DEBUG=1 virsh migrate --live --copy-storage-all i00cn1011 
qemu+ssh://user@computer2/session > debug.log 2>&1

On virt-manager on computer 1, the VM appears for a few moments as 
paused, and then disappears.
On computer 1 I receive the error: Timed out during operation: cannot 
acquire state change lock

Does anyone know what the problem may be and how to solve it?

Next I send all the data returned by virsh.

Thanks everyone.

user at computer1:~$ cat debug.log
13:52:07.911: debug : virInitialize:339 : register drivers
13:52:07.911: debug : virRegisterDriver:927 : registering Test as driver 0
13:52:07.911: debug : virRegisterNetworkDriver:733 : registering Test as 
network driver 0
13:52:07.911: debug : virRegisterInterfaceDriver:764 : registering Test 
as interface driver 0
13:52:07.911: debug : virRegisterStorageDriver:795 : registering Test as 
storage driver 0
13:52:07.911: debug : virRegisterDeviceMonitor:826 : registering Test as 
device driver 0
13:52:07.911: debug : virRegisterSecretDriver:857 : registering Test as 
secret driver 0
13:52:07.911: debug : virRegisterNWFilterDriver:888 : registering Test 
as network filter driver 0
13:52:07.911: debug : virRegisterDriver:927 : registering Xen as driver 1
13:52:07.911: debug : virRegisterDriver:927 : registering OPENVZ as driver 2
13:52:07.911: debug : vboxRegister:122 : VBoxCGlueInit failed, using 
dummy driver
13:52:07.911: debug : virRegisterDriver:927 : registering VBOX as driver 3
13:52:07.911: debug : virRegisterNetworkDriver:733 : registering VBOX as 
network driver 1
13:52:07.911: debug : virRegisterStorageDriver:795 : registering VBOX as 
storage driver 1
13:52:07.911: debug : virRegisterDriver:927 : registering remote as driver 4
13:52:07.911: debug : virRegisterNetworkDriver:733 : registering remote 
as network driver 2
13:52:07.911: debug : virRegisterInterfaceDriver:764 : registering 
remote as interface driver 1
13:52:07.911: debug : virRegisterStorageDriver:795 : registering remote 
as storage driver 2
13:52:07.911: debug : virRegisterDeviceMonitor:826 : registering remote 
as device driver 1
13:52:07.911: debug : virRegisterSecretDriver:857 : registering remote 
as secret driver 1
13:52:07.911: debug : virRegisterNWFilterDriver:888 : registering remote 
as network filter driver 1
13:52:07.911: debug : virConnectOpenAuth:1498 : name=(null), 
auth=0x7f3c96c6c7a0, flags=0
13:52:07.911: debug : do_open:1206 : no name, allowing driver auto-select
13:52:07.911: debug : do_open:1243 : trying driver 0 (Test) ...
13:52:07.911: debug : do_open:1249 : driver 0 Test returned DECLINED
13:52:07.911: debug : do_open:1243 : trying driver 1 (Xen) ...
13:52:07.911: debug : do_open:1249 : driver 1 Xen returned DECLINED
13:52:07.911: debug : do_open:1243 : trying driver 2 (OPENVZ) ...
13:52:07.911: debug : do_open:1249 : driver 2 OPENVZ returned DECLINED
13:52:07.911: debug : do_open:1243 : trying driver 3 (VBOX) ...
13:52:07.911: debug : do_open:1249 : driver 3 VBOX returned DECLINED
13:52:07.911: debug : do_open:1243 : trying driver 4 (remote) ...
13:52:07.911: debug : remoteOpen:1120 : Auto-probe remote URI
13:52:07.911: debug : doRemoteOpen:564 : proceeding with name =
13:52:07.911: debug : remoteIO:9886 : Do proc=66 serial=0 length=28 
wait=(nil)
13:52:07.911: debug : remoteIO:9961 : We have the buck 66 0x7f3c96d01010 
0x7f3c96d01010
13:52:07.912: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 64 total (60 more)
13:52:07.912: debug : remoteIOEventLoop:9812 : Giving up the buck 66 
0x7f3c96d01010 (nil)
13:52:07.912: debug : remoteIO:9990 : All done with our call 66 (nil) 
0x7f3c96d01010
13:52:07.912: debug : remoteIO:9886 : Do proc=1 serial=1 length=40 
wait=(nil)
13:52:07.912: debug : remoteIO:9961 : We have the buck 1 0xe671b0 0xe671b0
13:52:07.912: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 56 total (52 more)
13:52:07.912: debug : remoteIOEventLoop:9812 : Giving up the buck 1 
0xe671b0 (nil)
13:52:07.912: debug : remoteIO:9990 : All done with our call 1 (nil) 
0xe671b0
13:52:07.912: debug : remoteIO:9886 : Do proc=110 serial=2 length=28 
wait=(nil)
13:52:07.912: debug : remoteIO:9961 : We have the buck 110 0xe671b0 0xe671b0
13:52:07.913: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 76 total (72 more)
13:52:07.913: debug : remoteIOEventLoop:9812 : Giving up the buck 110 
0xe671b0 (nil)
13:52:07.913: debug : remoteIO:9990 : All done with our call 110 (nil) 
0xe671b0
13:52:07.913: debug : doRemoteOpen:922 : Auto-probed URI is qemu:///system
13:52:07.913: debug : doRemoteOpen:941 : Adding Handler for remote events
13:52:07.913: debug : doRemoteOpen:948 : virEventAddHandle failed: No 
addHandleImpl defined. continuing without events.
13:52:07.913: debug : do_open:1249 : driver 4 remote returned SUCCESS
13:52:07.913: debug : do_open:1269 : network driver 0 Test returned DECLINED
13:52:07.913: debug : do_open:1269 : network driver 1 VBOX returned DECLINED
13:52:07.913: debug : do_open:1269 : network driver 2 remote returned 
SUCCESS
13:52:07.913: debug : do_open:1288 : interface driver 0 Test returned 
DECLINED
13:52:07.913: debug : do_open:1288 : interface driver 1 remote returned 
SUCCESS
13:52:07.913: debug : do_open:1308 : storage driver 0 Test returned DECLINED
13:52:07.913: debug : do_open:1308 : storage driver 1 VBOX returned DECLINED
13:52:07.913: debug : do_open:1308 : storage driver 2 remote returned 
SUCCESS
13:52:07.913: debug : do_open:1328 : node driver 0 Test returned DECLINED
13:52:07.913: debug : do_open:1328 : node driver 1 remote returned SUCCESS
13:52:07.913: debug : do_open:1355 : secret driver 0 Test returned DECLINED
13:52:07.913: debug : do_open:1355 : secret driver 1 remote returned SUCCESS
13:52:07.913: debug : do_open:1375 : nwfilter driver 0 Test returned 
DECLINED
13:52:07.913: debug : do_open:1375 : nwfilter driver 1 remote returned 
SUCCESS
13:52:07.913: debug : virDomainLookupByName:2154 : conn=0xe61390, 
name=i00cn1011
13:52:07.913: debug : remoteIO:9886 : Do proc=23 serial=3 length=44 
wait=(nil)
13:52:07.913: debug : remoteIO:9961 : We have the buck 23 0xe671b0 0xe671b0
13:52:07.913: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 92 total (88 more)
13:52:07.913: debug : remoteIOEventLoop:9812 : Giving up the buck 23 
0xe671b0 (nil)
13:52:07.913: debug : remoteIO:9990 : All done with our call 23 (nil) 
0xe671b0
13:52:07.913: debug : virGetDomain:382 : New hash entry 0xe5da00
13:52:07.913: debug : virConnectOpenAuth:1498 : 
name=qemu+ssh://user@computer2/session, auth=0x7f3c96c6c7a0, flags=0
13:52:07.913: debug : do_open:1204 : name 
"qemu+ssh://user@computer2/session" to URI components:
   scheme qemu+ssh
   opaque (null)
   authority (null)
   server computer2
   user user
   port 0
   path /session

13:52:07.913: debug : do_open:1243 : trying driver 0 (Test) ...
13:52:07.913: debug : do_open:1249 : driver 0 Test returned DECLINED
13:52:07.913: debug : do_open:1243 : trying driver 1 (Xen) ...
13:52:07.913: debug : do_open:1249 : driver 1 Xen returned DECLINED
13:52:07.913: debug : do_open:1243 : trying driver 2 (OPENVZ) ...
13:52:07.913: debug : do_open:1249 : driver 2 OPENVZ returned DECLINED
13:52:07.913: debug : do_open:1243 : trying driver 3 (VBOX) ...
13:52:07.913: debug : do_open:1249 : driver 3 VBOX returned DECLINED
13:52:07.913: debug : do_open:1243 : trying driver 4 (remote) ...
13:52:07.913: debug : doRemoteOpen:564 : proceeding with name = 
qemu:///session
13:52:07.914: debug : virExecWithHook:712 : ssh -l user computer2 sh -c 
'nc -q 2>&1 | grep -q "requires an argument";if [ $? -eq 0 ] ; then   
CMD="nc -q 0 -U /var/run/libvirt/libvirt-sock";else   CMD="nc -U 
/var/run/libvirt/libvirt-sock";fi;eval "$CMD";'
13:52:07.914: debug : remoteIO:9886 : Do proc=66 serial=0 length=28 
wait=(nil)
13:52:07.914: debug : remoteIO:9961 : We have the buck 66 0xeaabd0 0xeaabd0
13:52:08.006: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 36 total (32 more)
13:52:08.006: debug : remoteIOEventLoop:9812 : Giving up the buck 66 
0xeaabd0 (nil)
13:52:08.006: debug : remoteIO:9990 : All done with our call 66 (nil) 
0xeaabd0
13:52:08.006: debug : remoteIO:9886 : Do proc=1 serial=1 length=56 
wait=(nil)
13:52:08.006: debug : remoteIO:9961 : We have the buck 1 0xeaabd0 0xeaabd0
13:52:08.007: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 28 total (24 more)
13:52:08.007: debug : remoteIOEventLoop:9812 : Giving up the buck 1 
0xeaabd0 (nil)
13:52:08.007: debug : remoteIO:9990 : All done with our call 1 (nil) 
0xeaabd0
13:52:08.007: debug : doRemoteOpen:941 : Adding Handler for remote events
13:52:08.007: debug : doRemoteOpen:948 : virEventAddHandle failed: No 
addHandleImpl defined. continuing without events.
13:52:08.007: debug : do_open:1249 : driver 4 remote returned SUCCESS
13:52:08.007: debug : do_open:1269 : network driver 0 Test returned DECLINED
13:52:08.007: debug : do_open:1269 : network driver 1 VBOX returned DECLINED
13:52:08.007: debug : do_open:1269 : network driver 2 remote returned 
SUCCESS
13:52:08.007: debug : do_open:1288 : interface driver 0 Test returned 
DECLINED
13:52:08.007: debug : do_open:1288 : interface driver 1 remote returned 
SUCCESS
13:52:08.007: debug : do_open:1308 : storage driver 0 Test returned DECLINED
13:52:08.007: debug : do_open:1308 : storage driver 1 VBOX returned DECLINED
13:52:08.007: debug : do_open:1308 : storage driver 2 remote returned 
SUCCESS
13:52:08.007: debug : do_open:1328 : node driver 0 Test returned DECLINED
13:52:08.007: debug : do_open:1328 : node driver 1 remote returned SUCCESS
13:52:08.007: debug : do_open:1355 : secret driver 0 Test returned DECLINED
13:52:08.007: debug : do_open:1355 : secret driver 1 remote returned SUCCESS
13:52:08.007: debug : do_open:1375 : nwfilter driver 0 Test returned 
DECLINED
13:52:08.007: debug : do_open:1375 : nwfilter driver 1 remote returned 
SUCCESS
13:52:08.007: debug : virDomainMigrate:3517 : domain=0xe5da00, 
dconn=0xe62b00, flags=65, dname=(null), uri=(null), bandwidth=0
13:52:08.008: debug : remoteIO:9886 : Do proc=60 serial=4 length=32 
wait=(nil)
13:52:08.008: debug : remoteIO:9961 : We have the buck 60 0xeaac10 0xeaac10
13:52:08.008: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 60 total (56 more)
13:52:08.008: debug : remoteIOEventLoop:9812 : Giving up the buck 60 
0xeaac10 (nil)
13:52:08.008: debug : remoteIO:9990 : All done with our call 60 (nil) 
0xeaac10
13:52:08.008: debug : remoteIO:9886 : Do proc=60 serial=5 length=32 
wait=(nil)
13:52:08.008: debug : remoteIO:9961 : We have the buck 60 0xeaac10 0xeaac10
13:52:08.008: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 60 total (56 more)
13:52:08.008: debug : remoteIOEventLoop:9812 : Giving up the buck 60 
0xeaac10 (nil)
13:52:08.008: debug : remoteIO:9990 : All done with our call 60 (nil) 
0xeaac10
13:52:08.008: debug : remoteIO:9886 : Do proc=60 serial=2 length=32 
wait=(nil)
13:52:08.008: debug : remoteIO:9961 : We have the buck 60 0xeaac10 0xeaac10
13:52:08.009: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 32 total (28 more)
13:52:08.009: debug : remoteIOEventLoop:9812 : Giving up the buck 60 
0xeaac10 (nil)
13:52:08.009: debug : remoteIO:9990 : All done with our call 60 (nil) 
0xeaac10
13:52:08.009: debug : remoteIO:9886 : Do proc=14 serial=6 length=68 
wait=(nil)
13:52:08.009: debug : remoteIO:9961 : We have the buck 14 0xeaac10 0xeaac10
13:52:08.009: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 2540 total (2536 more)
13:52:08.009: debug : remoteIOEventLoop:9812 : Giving up the buck 14 
0xeaac10 (nil)
13:52:08.010: debug : remoteIO:9990 : All done with our call 14 (nil) 
0xeaac10
13:52:08.010: debug : virDomainGetInfo:3017 : domain=0xe5da00, 
info=0x7fff102893e0
13:52:08.010: debug : remoteIO:9886 : Do proc=16 serial=7 length=64 
wait=(nil)
13:52:08.010: debug : remoteIO:9961 : We have the buck 16 0xeaac10 0xeaac10
13:52:08.010: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 88 total (84 more)
13:52:08.010: debug : remoteIOEventLoop:9812 : Giving up the buck 16 
0xeaac10 (nil)
13:52:08.010: debug : remoteIO:9990 : All done with our call 16 (nil) 
0xeaac10
13:52:08.010: debug : remoteIO:9886 : Do proc=108 serial=3 length=2536 
wait=(nil)
13:52:08.010: debug : remoteIO:9961 : We have the buck 108 0xeaac10 0xeaac10
13:52:08.291: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 68 total (64 more)
13:52:08.291: debug : remoteIOEventLoop:9812 : Giving up the buck 108 
0xeaac10 (nil)
13:52:08.291: debug : remoteIO:9990 : All done with our call 108 (nil) 
0xeaac10
13:52:08.291: debug : remoteIO:9886 : Do proc=62 serial=8 length=120 
wait=(nil)
13:52:08.291: debug : remoteIO:9961 : We have the buck 62 0xeaac10 0xeaac10
13:52:38.000: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 208 total (204 more)
13:52:38.000: debug : remoteIOEventLoop:9812 : Giving up the buck 62 
0xeaac10 (nil)
13:52:38.000: debug : remoteIO:9990 : All done with our call 62 (nil) 
0xeaac10
13:52:38.000: debug : remoteIO:9886 : Do proc=109 serial=4 length=92 
wait=(nil)
13:52:38.000: debug : remoteIO:9961 : We have the buck 109 0xeaac10 0xeaac10
13:52:38.211: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 120 total (116 more)
13:52:38.211: debug : remoteIOEventLoop:9812 : Giving up the buck 109 
0xeaac10 (nil)
13:52:38.211: debug : remoteIO:9990 : All done with our call 109 (nil) 
0xeaac10
13:52:38.211: debug : virConnectClose:1524 : conn=0xe62b00
13:52:38.211: debug : virUnrefConnect:294 : unref connection 0xe62b00 1
13:52:38.211: debug : remoteIO:9886 : Do proc=2 serial=5 length=28 
wait=(nil)
13:52:38.211: debug : remoteIO:9961 : We have the buck 2 0xeaac10 0xeaac10
13:52:38.212: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 28 total (24 more)
13:52:38.212: debug : remoteIOEventLoop:9812 : Giving up the buck 2 
0xeaac10 (nil)
13:52:38.212: debug : remoteIO:9990 : All done with our call 2 (nil) 
0xeaac10
13:52:38.212: debug : virReleaseConnect:249 : release connection 0xe62b00
13:52:38.212: debug : virDomainFree:2242 : domain=0xe5da00
13:52:38.212: debug : virUnrefDomain:463 : unref domain 0xe5da00 i00cn1011 1
13:52:38.212: debug : virReleaseDomain:416 : release domain 0xe5da00 
i00cn1011 4dd247bc-533a-db0d-f1e5-f1310169e62f
13:52:38.213: debug : virReleaseDomain:433 : unref connection 0xe61390 2
error: Timed out during operation: cannot acquire state change lock
13:52:38.213: debug : virConnectClose:1524 : conn=0xe61390
13:52:38.213: debug : virUnrefConnect:294 : unref connection 0xe61390 1
13:52:38.213: debug : remoteIO:9886 : Do proc=2 serial=9 length=28 
wait=(nil)
13:52:38.213: debug : remoteIO:9961 : We have the buck 2 0xe671b0 0xe671b0
13:52:38.213: debug : remoteIODecodeMessageLength:9314 : Got length, now 
need 56 total (52 more)
13:52:38.213: debug : remoteIOEventLoop:9812 : Giving up the buck 2 
0xe671b0 (nil)
13:52:38.213: debug : remoteIO:9990 : All done with our call 2 (nil) 
0xe671b0
13:52:38.213: debug : virReleaseConnect:249 : release connection 0xe61390
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/libvirt-users/attachments/20120209/c3c72b4d/attachment.htm>