libvirt users - Feb 2012 - 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 at 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 at computer2/session, auth=0x7f3c96c6c7a0, flags=0
13:52:07.913: debug : do_open:1204 : name 
"qemu+ssh://user at 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>

On 02/09/2012 07:00 AM, Nuno Sousa wrote:
> 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 at computer2/session > debug.log 2>&1
Based on IRC conversations, I'm assuming you already made sure that
computer2 already sees all the same disk image files, with the same
sizes, as are present on computer1 (the contents need not be identical,
since that is what --copy-storage-all is supposed to fix, but libvirt
currently does not pre-create the files on the destination and leaves
the user to do so instead - patches to fix that are welcome).
> 
> 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
You said virsh 0.8.3 on the source, but I'd also like to make sure what
version of libvirtd is running on the two machines?  There are some
known bugs in older libvirt versions where we had bad locking calls; and
some of these bugs could be triggered by migration, such as if
virt-manager is querying domain status at the same time that migration
shuts down the source because the destination is ready to run.

You may want to upgrade to 0.9.9 (stable release) or 0.9.10-rc2 (release
candidate for next week's release) on both machines, to try and get bugs
that have been fixed in the meantime out of your way.  You can safely
upgrade libvirt even while your VM continues to run.
> 
> Does anyone know what the problem may be and how to solve it?
At any rate, when older libvirtd hits the 'cannot acquire state change
lock' bug, the only solution is to restart libvirtd (again, a safe
operation; your guest will continue to run in the meantime).

I personally haven't played with --copy-storage-all, and know that it
doesn't get tested quite as much as shared storage, so I hope you can
get things working.

-- 
Eric Blake   eblake at redhat.com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 620 bytes
Desc: OpenPGP digital signature
URL:
<http://listman.redhat.com/archives/libvirt-users/attachments/20120209/6f61b994/attachment.sig>