ONE 4.11.80: DELETE+RECREATE fails to restart the VM

Hello,

I just tried the 4.11.80 OpenNebula on Ubuntu Trusty with KVM.

I start a VM and tried to DELETE+RECREATE it, but the VM never restarts, here are the VM logs:

Mon Mar  9 16:17:14 2015 [Z0][DiM][I]: New VM state is ACTIVE.
Mon Mar  9 16:17:14 2015 [Z0][LCM][I]: New VM state is PROLOG.
Mon Mar  9 16:17:15 2015 [Z0][LCM][I]: New VM state is BOOT
Mon Mar  9 16:17:15 2015 [Z0][VMM][I]: Generating deployment file: /var/lib/one/vms/0/deployment.0
Mon Mar  9 16:17:15 2015 [Z0][VMM][I]: ExitCode: 0
Mon Mar  9 16:17:15 2015 [Z0][VMM][I]: Successfully execute network driver operation: pre.
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: ExitCode: 0
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: Successfully execute virtualization driver operation: deploy.
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: post: Executed "sudo ovs-vsctl set Port vnet0 tag=4".
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,arp,dl_src=02:00:c0:a8:e6:64,priority=45000,actions=drop".
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,arp,dl_src=02:00:c0:a8:e6:64,nw_src=192.168.230.100,priority=46000,actions=normal".
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,dl_src=02:00:c0:a8:e6:64,priority=40000,actions=normal".
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,priority=39000,actions=drop".
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: ExitCode: 0
Mon Mar  9 16:17:16 2015 [Z0][VMM][I]: Successfully execute network driver operation: post.
Mon Mar  9 16:17:16 2015 [Z0][LCM][I]: New VM state is RUNNING
Mon Mar  9 16:17:41 2015 [Z0][LCM][I]: New VM state is CLEANUP.
Mon Mar  9 16:17:41 2015 [Z0][VMM][I]: Driver command for 0 cancelled
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: error: failed to get domain 'one-0'
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: error: Domain not found: no domain with matching name 'one-0'
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: ExitCode: 0
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: Successfully execute virtualization driver operation: cancel.
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: clean: Executed "sudo ovs-ofctl del-flows nebula ,in_port=2,dl_src=02:00:c0:a8:e6:64".
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: clean: Executed "sudo ovs-ofctl del-flows nebula ,arp,in_port=2,dl_src=02:00:c0:a8:e6:64,arp_spa=192.168.230.100".
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: clean: Executed "sudo ovs-ofctl del-flows nebula ,arp,in_port=2,dl_src=02:00:c0:a8:e6:64".
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: clean: Executed "sudo ovs-ofctl del-flows nebula in_port=2".
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: ExitCode: 0
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: Successfully execute network driver operation: clean.
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_delete.
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_delete.
Mon Mar  9 16:17:42 2015 [Z0][VMM][I]: Host successfully cleaned.
Mon Mar  9 16:17:42 2015 [Z0][DiM][I]: New VM state is PENDING
Mon Mar  9 16:17:44 2015 [Z0][LCM][I]: New VM state is RUNNING

The interesting thing is that the VM is seen as RUNNING but there is no qemu-system-x86 process running.

Any idea?

Regards.

Hi Daniel,

It seems quite strange a direct transition from PENDING to RUNNING without
any TM activity… Could you look for the entries in oned.log for that VM,
those at 16:17:00 - 16:18:00 should do…

Cheers

“Ruben S. Montero” forum@opennebula.org writes:

Hi Daniel,

Hello,

It seems quite strange a direct transition from PENDING to RUNNING without
any TM activity… Could you look for the entries in oned.log for that VM,
those at 16:17:00 - 16:18:00 should do…

Here are the logs:

Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:8736 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:8736 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:9968 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:9968 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:208 UID:0 DatastorePoolInfo invoked
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:208 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT..."
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:4912 UID:0 DatastorePoolInfo invoked
Mon Mar  9 16:17:13 2015 [Z0][ReM][D]: Req:4912 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT..."
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:7424 UID:0 HostPoolInfo invoked
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:7424 UID:0 HostPoolInfo result SUCCESS, "<HOST_POOL><HOST><ID..."
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:3616 UID:0 ClusterPoolInfo invoked
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:3616 UID:0 ClusterPoolInfo result SUCCESS, "<CLUSTER_POOL><CLUST..."
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:2992 UID:0 AclInfo invoked
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:2992 UID:0 AclInfo result SUCCESS, "<ACL_POOL><ACL><ID>0..."
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:9792 UID:0 VirtualMachineDeploy invoked , 0, 2, false, 0
Mon Mar  9 16:17:14 2015 [Z0][DiM][D]: Deploying VM 0
Mon Mar  9 16:17:14 2015 [Z0][ReM][D]: Req:9792 UID:0 VirtualMachineDeploy result SUCCESS, 0
Mon Mar  9 16:17:14 2015 [Z0][ImM][D]: Datastore system (0) successfully monitored.
Mon Mar  9 16:17:14 2015 [Z0][InM][D]: Host openneb3 (2) successfully monitored.
Mon Mar  9 16:17:15 2015 [Z0][TM][D]: Message received: TRANSFER SUCCESS 0 -

Mon Mar  9 16:17:15 2015 [Z0][VMM][D]: Message received: LOG I 0 ExitCode: 0

Mon Mar  9 16:17:15 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute network driver operation: pre.

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 ExitCode: 0

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute virtualization driver operation: deploy.

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 post: Executed "sudo ovs-vsctl set Port vnet0 tag=4".

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,arp,dl_src=02:00:c0:a8:e6:64,priority=45000,actions=drop".

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,arp,dl_src=02:00:c0:a8:e6:64,nw_src=192.168.230.100,priority=46000,actions=normal".

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,dl_src=02:00:c0:a8:e6:64,priority=40000,actions=normal".

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 post: Executed "sudo ovs-ofctl add-flow nebula in_port=2,priority=39000,actions=drop".

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 ExitCode: 0

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute network driver operation: post.

Mon Mar  9 16:17:16 2015 [Z0][VMM][D]: Message received: DEPLOY SUCCESS 0 one-0

Mon Mar  9 16:17:21 2015 [Z0][ReM][D]: Req:3040 UID:0 SystemConfig invoked
Mon Mar  9 16:17:21 2015 [Z0][ReM][D]: Req:3040 UID:0 SystemConfig result SUCCESS, "<TEMPLATE><AUTH_MAD>..."
Mon Mar  9 16:17:21 2015 [Z0][ReM][D]: Req:5424 UID:0 HostPoolInfo invoked
Mon Mar  9 16:17:21 2015 [Z0][ReM][D]: Req:5424 UID:0 HostPoolInfo result SUCCESS, "<HOST_POOL><HOST><ID..."
Mon Mar  9 16:17:22 2015 [Z0][ReM][D]: Req:4416 UID:0 HostUpdateTemplate invoked , 2, "ARCH="x86_64"...", 0
Mon Mar  9 16:17:22 2015 [Z0][ReM][D]: Req:4416 UID:0 HostUpdateTemplate result SUCCESS, 2
Mon Mar  9 16:17:25 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 40 -

Mon Mar  9 16:17:25 2015 [Z0][ReM][D]: Req:6128 UID:2 VirtualMachinePoolInfo invoked , -2, 0, -2000, -1
Mon Mar  9 16:17:25 2015 [Z0][ReM][D]: Req:6128 UID:2 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:27 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 41 -

Mon Mar  9 16:17:27 2015 [Z0][ReM][D]: Req:7104 UID:2 VirtualMachineInfo invoked , 0
Mon Mar  9 16:17:27 2015 [Z0][ReM][D]: Req:7104 UID:2 VirtualMachineInfo result SUCCESS, "<VM><ID>0</ID><UID>2..."
Mon Mar  9 16:17:41 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 42 -

Mon Mar  9 16:17:41 2015 [Z0][ReM][D]: Req:2288 UID:2 VirtualMachineInfo invoked , 0
Mon Mar  9 16:17:41 2015 [Z0][ReM][D]: Req:2288 UID:2 VirtualMachineInfo result SUCCESS, "<VM><ID>0</ID><UID>2..."
Mon Mar  9 16:17:41 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 43 -

Mon Mar  9 16:17:41 2015 [Z0][ReM][D]: Req:5840 UID:2 VirtualMachineAction invoked , "delete-recreate", 0
Mon Mar  9 16:17:41 2015 [Z0][ReM][D]: Req:5840 UID:2 VirtualMachineAction result SUCCESS, 0
Mon Mar  9 16:17:41 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 44 -

Mon Mar  9 16:17:41 2015 [Z0][ReM][D]: Req:3248 UID:2 VirtualMachineInfo invoked , 0
Mon Mar  9 16:17:41 2015 [Z0][ReM][D]: Req:3248 UID:2 VirtualMachineInfo result SUCCESS, "<VM><ID>0</ID><UID>2..."
Mon Mar  9 16:17:41 2015 [Z0][VMM][D]: Message received: LOG I 0 Driver command for 0 cancelled
Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 error: failed to get domain 'one-0'

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 error: Domain not found: no domain with matching name 'one-0'

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 ExitCode: 0

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute virtualization driver operation: cancel.

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 clean: Executed "sudo ovs-ofctl del-flows nebula ,in_port=2,dl_src=02:00:c0:a8:e6:64".

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 clean: Executed "sudo ovs-ofctl del-flows nebula ,arp,in_port=2,dl_src=02:00:c0:a8:e6:64,arp_spa=192.168.230.100".

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 clean: Executed "sudo ovs-ofctl del-flows nebula ,arp,in_port=2,dl_src=02:00:c0:a8:e6:64".

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 clean: Executed "sudo ovs-ofctl del-flows nebula in_port=2".

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 ExitCode: 0

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute network driver operation: clean.

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute transfer manager driver operation: tm_delete.

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: LOG I 0 Successfully execute transfer manager driver operation: tm_delete.

Mon Mar  9 16:17:42 2015 [Z0][VMM][D]: Message received: CLEANUP SUCCESS 0

Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:8240 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:8240 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:1968 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:1968 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:4128 UID:0 DatastorePoolInfo invoked
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:4128 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT..."
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:6048 UID:0 DatastorePoolInfo invoked
Mon Mar  9 16:17:43 2015 [Z0][ReM][D]: Req:6048 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT..."
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:4544 UID:0 HostPoolInfo invoked
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:4544 UID:0 HostPoolInfo result SUCCESS, "<HOST_POOL><HOST><ID..."
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:1536 UID:0 ClusterPoolInfo invoked
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:1536 UID:0 ClusterPoolInfo result SUCCESS, "<CLUSTER_POOL><CLUST..."
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:8240 UID:0 AclInfo invoked
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:8240 UID:0 AclInfo result SUCCESS, "<ACL_POOL><ACL><ID>0..."
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:944 UID:0 VirtualMachineDeploy invoked , 0, 2, false, 0
Mon Mar  9 16:17:44 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 45 -

Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:5664 UID:2 VirtualMachinePoolInfo invoked , -2, 0, -2000, -1
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:5664 UID:2 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:44 2015 [Z0][ReM][D]: Req:944 UID:0 VirtualMachineDeploy result SUCCESS, 0
Mon Mar  9 16:17:47 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 46 -

Mon Mar  9 16:17:47 2015 [Z0][ReM][D]: Req:3568 UID:2 VirtualMachinePoolInfo invoked , -2, 0, -2000, -1
Mon Mar  9 16:17:47 2015 [Z0][ReM][D]: Req:3568 UID:2 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL><VM><ID>0</..."
Mon Mar  9 16:17:47 2015 [Z0][InM][D]: Monitoring datastore default (1)
Mon Mar  9 16:17:47 2015 [Z0][InM][D]: Monitoring datastore files (2)
Mon Mar  9 16:17:48 2015 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Mon Mar  9 16:17:48 2015 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Mon Mar  9 16:17:50 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 47 -

Mon Mar  9 16:17:50 2015 [Z0][ReM][D]: Req:9824 UID:2 VirtualMachineInfo invoked , 0
Mon Mar  9 16:17:50 2015 [Z0][ReM][D]: Req:9824 UID:2 VirtualMachineInfo result SUCCESS, "<VM><ID>0</ID><UID>2..."
Mon Mar  9 16:18:00 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 48 -

Mon Mar  9 16:18:00 2015 [Z0][ReM][D]: Req:9376 UID:2 VirtualMachineInfo invoked , 0

Regards.

Daniel Dehennin
Récupérer ma clef GPG: gpg --recv-keys 0xCC1E9E5B7A6FE2DF
Fingerprint: 3E69 014E 5C23 50E8 9ED6 2AAD CC1E 9E5B 7A6F E2DF

Hi Daniel,

This is indeed a bug. THANK YOU very much for the feedback!. We’ll fixed
for final.

Cheers

I tried to reproduce Daniel’s result but it seems to fail in a different fashion (error: failed to get domain ‘one-63’)

Mar 10 09:10:11 test-oned2 oned[12905]: [Z0][ReM][D]: Req:9344 UID:0 VirtualMachineAction invoked , "delete-recreate", 63
Mar 10 09:10:12 test-oned2 oned[12905]: [Z0][ReM][D]: Req:9344 UID:0 VirtualMachineAction result SUCCESS, 63
Mar 10 09:10:12 test-oned2 oned[12905]: [VM 63][Z0][LCM][I]: New VM state is CLEANUP.
Mar 10 09:10:12 test-oned2 oned[12905]: [VM 63][Z0][LCM][I]: New VM state is CLEANUP.
Mar 10 09:10:12 test-oned2 oned[12905]: [Z0][ReM][D]: Req:6464 UID:0 VirtualMachineInfo invoked , 63
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][ReM][D]: Req:6464 UID:0 VirtualMachineInfo result SUCCESS, "<VM><ID>63</ID><UID>..."
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 Driver command for 63 cancelled
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Driver command for 63 cancelled
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Driver command for 63 cancelled
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 error: failed to get domain 'one-63'
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: error: failed to get domain 'one-63'
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: error: failed to get domain 'one-63'
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 error: Domain not found: no domain with matching name 'one-63'
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: error: Domain not found: no domain with matching name 'one-63'
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: error: Domain not found: no domain with matching name 'one-63'
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 ExitCode: 0
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: ExitCode: 0
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: ExitCode: 0
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 Successfully execute virtualization driver operation: cancel.
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute virtualization driver operation: cancel.
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute virtualization driver operation: cancel.
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 ExitCode: 0
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: ExitCode: 0
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: ExitCode: 0
Mar 10 09:10:13 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 Successfully execute network driver operation: clean.
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute network driver operation: clean.
Mar 10 09:10:13 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute network driver operation: clean.
Mar 10 09:10:14 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 Successfully execute transfer manager driver operation: tm_delete.
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_delete.
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_delete.
Mar 10 09:10:14 test-oned2 oned[12905]: [Z0][VMM][D]: VM 21 successfully monitored: STATE=a USEDCPU=0.0 USEDMEMORY=2097152 NETRX=15675322 NETTX=7688336
Mar 10 09:10:14 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: LOG I 63 Successfully execute transfer manager driver operation: tm_delete.
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_delete.
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Successfully execute transfer manager driver operation: tm_delete.
Mar 10 09:10:14 test-oned2 oned[12905]: [Z0][VMM][D]: Message received: CLEANUP SUCCESS 63 
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Host successfully cleaned.
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][VMM][I]: Host successfully cleaned.
Mar 10 09:10:14 test-oned2 oned[12905]: [Z0][VMM][D]: VM 28 successfully monitored: STATE=a USEDCPU=35.9 USEDMEMORY=2097152 NETRX=63706692994 NETTX=63139906290
Mar 10 09:10:14 test-oned2 oned[12905]: [Z0][VMM][D]: VM 24 successfully monitored: STATE=a USEDCPU=13.5 USEDMEMORY=2097152 NETRX=20933039003 NETTX=19245833394
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][DiM][I]: New VM state is PENDING
Mar 10 09:10:14 test-oned2 oned[12905]: [VM 63][Z0][DiM][I]: New VM state is PENDING
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][VM][D]: Pending/rescheduling VM and capacity requirements:
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][VM][D]: Pending/rescheduling VM and capacity requirements:
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][VM][D]:       VM  CPU      Memory   System DS  Image DS
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][VM][D]: ------------------------------------------------------------
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][VM][D]:       63   20     1048576           0  DS 101: 0 
Mar 10 09:10:15 test-oned2 oned[12905]: [Z0][ReM][D]: Req:8896 UID:0 DatastorePoolInfo invoked 
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][VM][D]:       VM  CPU      Memory   System DS  Image DS
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][VM][D]: ------------------------------------------------------------
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][VM][D]:       63   20     1048576           0  DS 101: 0 
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][HOST][D]: Discovered Hosts (enabled):
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][HOST][D]: Discovered Hosts (enabled):
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][HOST][D]:  0 1
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: Scheduling Results:
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: Scheduling Results:
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: Virtual Machine: 63
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: 
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #011PRI#011ID - HOSTS
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #011------------------------
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #011-0.25#0110
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #011-1#0111
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: 
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #011PRI#011ID - DATASTORES
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #011------------------------
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: #0111#011100
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][SCHED][I]: 
Mar 10 09:10:15 test-oned2 mm_sched[30401]: [Z0][VM][I]: Dispatching VM 63 to host 0 and datastore 100
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: Virtual Machine: 63
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: 
Mar 10 09:10:15 test-oned2 oned[12905]: [Z0][ReM][D]: Req:2352 UID:0 VirtualMachineDeploy invoked , 63, 0, false, 100
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #011PRI#011ID - HOSTS
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #011------------------------
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #011-0.25#0110
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #011-1#0111
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: 
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #011PRI#011ID - DATASTORES
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #011------------------------
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: #0111#011100
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][SCHED][I]: 
Mar 10 09:10:15 test-oned2 mm_sched[12906]: [Z0][VM][I]: Dispatching VM 63 to host 0 and datastore 100
Mar 10 09:10:15 test-oned2 oned[12905]: [Z0][ReM][D]: Req:1520 UID:0 VirtualMachineDeploy invoked , 63, 0, false, 100
Mar 10 09:10:17 test-oned2 oned[12905]: [Z0][HKM][D]: Message received: EXECUTE SUCCESS 63 send_gratuitous_arp: No VNET Interface found, unable to send gratuitous ARP Reply
Mar 10 09:10:18 test-oned2 oned[12905]: [VM 63][Z0][LCM][I]: New VM state is RUNNING
Mar 10 09:10:18 test-oned2 oned[12905]: [VM 63][Z0][LCM][I]: New VM state is RUNNING
Mar 10 09:10:18 test-oned2 oned[12905]: [Z0][ReM][D]: Req:2352 UID:0 VirtualMachineDeploy result SUCCESS, 63
Mar 10 09:10:18 test-oned2 oned[12905]: [Z0][ReM][E]: Req:1520 UID:0 VirtualMachineDeploy result FAILURE [VirtualMachineDeploy] Wrong state to perform action
Mar 10 09:10:18 test-oned2 mm_sched[12906]: [Z0][VM][E]: Error deploying virtual machine 63 to HID: 0. Reason: [VirtualMachineDeploy] Wrong state to perform action
Mar 10 09:10:18 test-oned2 oned[12905]: [Z0][VMM][D]: VM 63 successfully monitored: STATE=a USEDCPU=0.0 USEDMEMORY=1048576 NETRX=0 NETTX=8703396
Mar 10 09:10:18 test-oned2 mm_sched[12906]: [Z0][VM][I]: Dispatching VM 63 to host 1 and datastore 100
Mar 10 09:10:18 test-oned2 oned[12905]: [Z0][ReM][D]: Req:3968 UID:0 VirtualMachineDeploy invoked , 63, 1, false, 100
Mar 10 09:10:35 test-oned2 oned[12905]: [VM 63][Z0][HKM][I]: Success executing Hook: send_gratuitous_arp: No VNET Interface found, unable to send gratuitous ARP Reply. 
Mar 10 09:10:35 test-oned2 oned[12905]: [VM 63][Z0][HKM][I]: Success executing Hook: send_gratuitous_arp: No VNET Interface found, unable to send gratuitous ARP Reply. 
Mar 10 09:10:35 test-oned2 oned[12905]: [Z0][HKM][D]: Message received: No VNET Interface found, unable to send gratuitous ARP Reply
Mar 10 09:10:35 test-oned2 oned[12905]: [Z0][HKM][D]: Message received: EXECUTE SUCCESS 63 notify_running: 
Mar 10 09:10:35 test-oned2 oned[12905]: [VM 63][Z0][HKM][I]: Success executing Hook: notify_running: . 
Mar 10 09:10:35 test-oned2 oned[12905]: [VM 63][Z0][HKM][I]: Success executing Hook: notify_running: . 
Mar 10 09:10:35 test-oned2 oned[12905]: [Z0][ReM][E]: Req:3968 UID:0 VirtualMachineDeploy result FAILURE [VirtualMachineDeploy] Wrong state to perform action
Mar 10 09:10:35 test-oned2 mm_sched[12906]: [Z0][VM][E]: Error deploying virtual machine 63 to HID: 1. Reason: [VirtualMachineDeploy] Wrong state to perform action
Mar 10 09:10:51 test-oned2 oned[12905]: [VM 63][Z0][DiM][I]: New VM state is POWEROFF
Mar 10 09:10:51 test-oned2 oned[12905]: [VM 63][Z0][DiM][I]: New VM state is POWEROFF