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

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@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