VM Pending to Infinity

Community Support
1

Hi,

It seems I’m having a bit of bad luck. I’ve followed all directions for installing 4.12 on Ubuntu 14.04. I have no problem adding hosts/templates/images. But instantiation of KVM VM’s results in infinite PENDING state - this is repeated in the sched.log over and over - can anyone shed any light on where else to look?:

Wed Jun 10 10:46:32 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 7.4057e-05s
Wed Jun 10 10:47:01 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00196756s
Wed Jun 10 10:47:02 2015 [Z0][VM][D]: Found 2 pending/rescheduling VMs.
Wed Jun 10 10:47:02 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 10:47:02 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00884282s
Wed Jun 10 10:47:02 2015 [Z0][SCHED][D]: Match Making statistics:
Number of VMs: 2
Total time: 0s
Total Match time: 0.000297604s
Total Ranking Time: 0.000344431s
Wed Jun 10 10:47:02 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
VMID Host System DS
-------------------------

2

is there any message in the vm (like onevm show <vm_id>) look for some
SCHED_MESSAGE. double check the capacity required by the VM, that avilable
in the hosts and any specific REQUIREMENT in the VM…

3

yes there is and it’s odd that my hosts are not enabled?

SCHED_MESSAGE=“Wed Jun 10 10:54:32 2015 : No hosts enabled to run VMs”

The entire output is here:

oneadmin@1mgmt1:~$ onevm show 0
VIRTUAL MACHINE 0 INFORMATION
ID : 0
NAME : Trusty-TestVM-0
USER : oneadmin
GROUP : oneadmin
STATE : PENDING
LCM_STATE : LCM_INIT
RESCHED : No
START TIME : 06/10 08:25:33
END TIME : -
DEPLOY ID : -

VIRTUAL MACHINE MONITORING
USED MEMORY : 0K
USED CPU : 0
NET_TX : 0K
NET_RX : 0K

PERMISSIONS
OWNER : um-
GROUP : —
OTHER : —

VM DISKS
ID TARGET IMAGE TYPE SAVE SAVE_AS
0 hda Trusty_X86_65 file NO -

VM NICS
ID NETWORK VLAN BRIDGE IP MAC
0 private no br0 192.168.32.100 02:00:c0:a8:20:64

SECURITY

NIC_ID NETWORK SECURITY_GROUPS
0 private 0

SECURITY GROUP TYPE PROTOCOL NETWORK RANGE
ID NAME VNET START SIZE
0 default OUTBOUND ALL
0 default INBOUND ALL

USER TEMPLATE
SCHED_MESSAGE=“Wed Jun 10 10:54:32 2015 : No hosts enabled to run VMs”

VIRTUAL MACHINE TEMPLATE
AUTOMATIC_REQUIREMENTS="!(PUBLIC_CLOUD = YES)"
CONTEXT=[
DISK_ID=“1”,
TARGET=“hdb” ]
CPU="2"
GRAPHICS=[
LISTEN=“0.0.0.0”,
PORT=“5900”,
TYPE=“vnc” ]
MEMORY="2096"
OS=[
ARCH=“x86_64” ]
TEMPLATE_ID="0"
VCPU="2"
VMID=“0”

4

Could you paste the output of onehost list -x?

5 
 <HOST_POOL>
  <HOST>
    <ID>0</ID>
    <NAME>1cn2.dev.gogii.net</NAME>
    <STATE>1</STATE>
    <IM_MAD><![CDATA[kvm]]></IM_MAD>
    <VM_MAD><![CDATA[kvm]]></VM_MAD>
    <VN_MAD><![CDATA[dummy]]></VN_MAD>
	    <LAST_MON_TIME>1433961653</LAST_MON_TIME>
	    <CLUSTER_ID>100</CLUSTER_ID>
	    <CLUSTER>DevCluster</CLUSTER>
	    <HOST_SHARE>
	      <DISK_USAGE>0</DISK_USAGE>
	      <MEM_USAGE>0</MEM_USAGE>
	      <CPU_USAGE>0</CPU_USAGE>
		      <MAX_DISK>0</MAX_DISK>
		      <MAX_MEM>49454196</MAX_MEM>
		      <MAX_CPU>800</MAX_CPU>
		      <FREE_DISK>0</FREE_DISK>
		      <FREE_MEM>49024420</FREE_MEM>
		      <FREE_CPU>800</FREE_CPU>
		      <USED_DISK>0</USED_DISK>
		      <USED_MEM>429776</USED_MEM>
		      <USED_CPU>0</USED_CPU>
		      <RUNNING_VMS>0</RUNNING_VMS>
		      <DATASTORES/>
		    </HOST_SHARE>
		    <VMS/>
		    <TEMPLATE>
		      <ARCH><![CDATA[x86_64]]></ARCH>
		      <CPUSPEED><![CDATA[1600]]></CPUSPEED>
		      <HOSTNAME><![CDATA[1cn2.dev.gogii.net]]></HOSTNAME>
		      <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
		      <MODELNAME><![CDATA[Intel(R) Xeon(R) CPU E5504 @ 2.00GHz]]></MODELNAME>
		      <NETRX><![CDATA[0]]></NETRX>
		      <NETTX><![CDATA[0]]></NETTX>
		      <RESERVED_CPU><![CDATA[]]></RESERVED_CPU>
		      <RESERVED_MEM><![CDATA[]]></RESERVED_MEM>
		    </TEMPLATE>
		  </HOST>
		  <HOST>
		    <ID>1</ID>
		    <NAME>1cn3.dev.gogii.net</NAME>
		    <STATE>2</STATE>
		    <IM_MAD><![CDATA[kvm]]></IM_MAD>
		    <VM_MAD><![CDATA[kvm]]></VM_MAD>
		    <VN_MAD><![CDATA[dummy]]></VN_MAD>
		    <LAST_MON_TIME>1433961642</LAST_MON_TIME>
		    <CLUSTER_ID>100</CLUSTER_ID>
		    <CLUSTER>DevCluster</CLUSTER>
		    <HOST_SHARE>
		      <DISK_USAGE>0</DISK_USAGE>
		      <MEM_USAGE>0</MEM_USAGE>
		      <CPU_USAGE>0</CPU_USAGE>
		      <MAX_DISK>0</MAX_DISK>
		      <MAX_MEM>49454196</MAX_MEM>
		      <MAX_CPU>800</MAX_CPU>
		      <FREE_DISK>0</FREE_DISK>
		      <FREE_MEM>49024940</FREE_MEM>
		      <FREE_CPU>800</FREE_CPU>
		      <USED_DISK>0</USED_DISK>
		      <USED_MEM>429256</USED_MEM>
		      <USED_CPU>0</USED_CPU>
		      <RUNNING_VMS>0</RUNNING_VMS>
		      <DATASTORES/>
		    </HOST_SHARE>
		    <VMS/>
		    <TEMPLATE>
		      <ARCH><![CDATA[x86_64]]></ARCH>
		      <CPUSPEED><![CDATA[1600]]></CPUSPEED>
		      <HOSTNAME><![CDATA[1cn3.dev.gogii.net]]></HOSTNAME>
		      <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
		      <MODELNAME><![CDATA[Intel(R) Xeon(R) CPU E5504 @ 2.00GHz]]></MODELNAME>
		      <NETRX><![CDATA[0]]></NETRX>
		      <NETTX><![CDATA[0]]></NETTX>
		      <RESERVED_CPU><![CDATA[]]></RESERVED_CPU>
		      <RESERVED_MEM><![CDATA[]]></RESERVED_MEM>
		    </TEMPLATE>
		  </HOST>
		  <HOST>
		    <ID>2</ID>
		    <NAME>1cn4.dev.gogii.net</NAME>
		    <STATE>1</STATE>
		    <IM_MAD><![CDATA[kvm]]></IM_MAD>
		    <VM_MAD><![CDATA[kvm]]></VM_MAD>
		    <VN_MAD><![CDATA[dummy]]></VN_MAD>
		    <LAST_MON_TIME>1433961654</LAST_MON_TIME>
		    <CLUSTER_ID>100</CLUSTER_ID>
		    <CLUSTER>DevCluster</CLUSTER>
		    <HOST_SHARE>
		      <DISK_USAGE>0</DISK_USAGE>
		      <MEM_USAGE>0</MEM_USAGE>
		      <CPU_USAGE>0</CPU_USAGE>
		      <MAX_DISK>0</MAX_DISK>
		      <MAX_MEM>49454196</MAX_MEM>
		      <MAX_CPU>800</MAX_CPU>
		      <FREE_DISK>0</FREE_DISK>
		      <FREE_MEM>49029152</FREE_MEM>
		      <FREE_CPU>800</FREE_CPU>
		      <USED_DISK>0</USED_DISK>
		      <USED_MEM>425044</USED_MEM>
		      <USED_CPU>0</USED_CPU>
		      <RUNNING_VMS>0</RUNNING_VMS>
		      <DATASTORES/>
		    </HOST_SHARE>
		    <VMS/>
		    <TEMPLATE>
		      <ARCH><![CDATA[x86_64]]></ARCH>
		      <CPUSPEED><![CDATA[1600]]></CPUSPEED>
		      <HOSTNAME><![CDATA[1cn4.dev.gogii.net]]></HOSTNAME>
		      <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
		      <MODELNAME><![CDATA[Intel(R) Xeon(R) CPU E5504 @ 2.00GHz]]></MODELNAME>
		      <NETRX><![CDATA[0]]></NETRX>
		      <NETTX><![CDATA[0]]></NETTX>
		      <RESERVED_CPU><![CDATA[]]></RESERVED_CPU>
		      <RESERVED_MEM><![CDATA[]]></RESERVED_MEM>
		    </TEMPLATE>
		  </HOST>
		  <HOST>
		    <ID>3</ID>
		    <NAME>1cn6.dev.gogii.net</NAME>
		    <STATE>1</STATE>
		    <IM_MAD><![CDATA[kvm]]></IM_MAD>
		    <VM_MAD><![CDATA[kvm]]></VM_MAD>
		    <VN_MAD><![CDATA[dummy]]></VN_MAD>
		    <LAST_MON_TIME>1433961654</LAST_MON_TIME>
		    <CLUSTER_ID>100</CLUSTER_ID>
		    <CLUSTER>DevCluster</CLUSTER>
		    <HOST_SHARE>
		      <DISK_USAGE>0</DISK_USAGE>
		      <MEM_USAGE>0</MEM_USAGE>
		      <CPU_USAGE>0</CPU_USAGE>
		      <MAX_DISK>0</MAX_DISK>
		      <MAX_MEM>24681700</MAX_MEM>
		      <MAX_CPU>800</MAX_CPU>
		      <FREE_DISK>0</FREE_DISK>
		      <FREE_MEM>24413236</FREE_MEM>
		      <FREE_CPU>800</FREE_CPU>
		      <USED_DISK>0</USED_DISK>
		      <USED_MEM>268464</USED_MEM>
		      <USED_CPU>0</USED_CPU>
		      <RUNNING_VMS>0</RUNNING_VMS>
		      <DATASTORES/>
		    </HOST_SHARE>
		    <VMS/>
		    <TEMPLATE>
		      <ARCH><![CDATA[x86_64]]></ARCH>
		      <CPUSPEED><![CDATA[1600]]></CPUSPEED>
		      <HOSTNAME><![CDATA[1cn6.dev.gogii.net]]></HOSTNAME>
		      <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
		      <MODELNAME><![CDATA[Intel(R) Xeon(R) CPU E5504 @ 2.00GHz]]></MODELNAME>
		      <NETRX><![CDATA[0]]></NETRX>
		      <NETTX><![CDATA[0]]></NETTX>
		      <RESERVED_CPU><![CDATA[]]></RESERVED_CPU>
		      <RESERVED_MEM><![CDATA[]]></RESERVED_MEM>
		    </TEMPLATE>
		  </HOST>
		  <HOST>
		    <ID>4</ID>
		    <NAME>1cn7.dev.gogii.net</NAME>
		    <STATE>2</STATE>
		    <IM_MAD><![CDATA[kvm]]></IM_MAD>
		    <VM_MAD><![CDATA[kvm]]></VM_MAD>
		    <VN_MAD><![CDATA[dummy]]></VN_MAD>
		    <LAST_MON_TIME>1433961599</LAST_MON_TIME>
		    <CLUSTER_ID>100</CLUSTER_ID>
		    <CLUSTER>DevCluster</CLUSTER>
		    <HOST_SHARE>
		      <DISK_USAGE>0</DISK_USAGE>
		      <MEM_USAGE>0</MEM_USAGE>
		      <CPU_USAGE>0</CPU_USAGE>
		      <MAX_DISK>0</MAX_DISK>
		      <MAX_MEM>24681700</MAX_MEM>
		      <MAX_CPU>800</MAX_CPU>
		      <FREE_DISK>0</FREE_DISK>
		      <FREE_MEM>24409532</FREE_MEM>
		      <FREE_CPU>800</FREE_CPU>
		      <USED_DISK>0</USED_DISK>
		      <USED_MEM>272168</USED_MEM>
		      <USED_CPU>0</USED_CPU>
		      <RUNNING_VMS>0</RUNNING_VMS>
		      <DATASTORES/>
		    </HOST_SHARE>
		    <VMS/>
		    <TEMPLATE>
		      <ARCH><![CDATA[x86_64]]></ARCH>
		      <CPUSPEED><![CDATA[1600]]></CPUSPEED>
		      <HOSTNAME><![CDATA[1cn7.dev.gogii.net]]></HOSTNAME>
		      <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
		      <MODELNAME><![CDATA[Intel(R) Xeon(R) CPU E5504 @ 2.00GHz]]></MODELNAME>
		      <NETRX><![CDATA[0]]></NETRX>
		      <NETTX><![CDATA[0]]></NETTX>
		      <RESERVED_CPU><![CDATA[]]></RESERVED_CPU>
		      <RESERVED_MEM><![CDATA[]]></RESERVED_MEM>
		    </TEMPLATE>
		  </HOST>
		  <HOST>
		    <ID>5</ID>
		    <NAME>1cn8.dev.gogii.net</NAME>
		    <STATE>2</STATE>
		    <IM_MAD><![CDATA[kvm]]></IM_MAD>
		    <VM_MAD><![CDATA[kvm]]></VM_MAD>
		    <VN_MAD><![CDATA[dummy]]></VN_MAD>
		    <LAST_MON_TIME>1433961599</LAST_MON_TIME>
		    <CLUSTER_ID>100</CLUSTER_ID>
		    <CLUSTER>DevCluster</CLUSTER>
		    <HOST_SHARE>
		      <DISK_USAGE>0</DISK_USAGE>
		      <MEM_USAGE>0</MEM_USAGE>
		      <CPU_USAGE>0</CPU_USAGE>
		      <MAX_DISK>0</MAX_DISK>
		      <MAX_MEM>49453336</MAX_MEM>
		      <MAX_CPU>800</MAX_CPU>
		      <FREE_DISK>0</FREE_DISK>
		      <FREE_MEM>49019980</FREE_MEM>
		      <FREE_CPU>800</FREE_CPU>
		      <USED_DISK>0</USED_DISK>
		      <USED_MEM>433356</USED_MEM>
		      <USED_CPU>0</USED_CPU>
		      <RUNNING_VMS>0</RUNNING_VMS>
		      <DATASTORES/>
		    </HOST_SHARE>
		    <VMS/>
		    <TEMPLATE>
		      <ARCH><![CDATA[x86_64]]></ARCH>
		      <CPUSPEED><![CDATA[1600]]></CPUSPEED>
		      <HOSTNAME><![CDATA[1cn8.dev.gogii.net]]></HOSTNAME>
		      <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
		      <MODELNAME><![CDATA[Intel(R) Xeon(R) CPU E5504 @ 2.00GHz]]></MODELNAME>
		      <NETRX><![CDATA[0]]></NETRX>
		      <NETTX><![CDATA[0]]></NETTX>
		      <RESERVED_CPU><![CDATA[]]></RESERVED_CPU>
		      <RESERVED_MEM><![CDATA[]]></RESERVED_MEM>
		    </TEMPLATE>
		  </HOST>
		</HOST_POOL>

I don’t see anything out of order here???

6

no there is nothing wrong here, state is the right one (2 = MONITORED) and the requirements of the VM should fit in the hosts…

7

So it seems that the messages are not consistent, i.e.

Wed Jun 10 10:47:02 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.

in sched.conf, and:

SCHED_MESSAGE="Wed Jun 10 10:54:32 2015 : No hosts enabled to run VMs"

in vm template (at the code level both messages refer to the same counter) Could you double check the timestamps. i.e what are the sched.log messages at 10:54…

8

Well I certainly can’t explain the inconsistency seen below.

Wed Jun 10 10:54:01 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00201246s
Wed Jun 10 10:54:02 2015 [Z0][VM][D]: Found 2 pending/rescheduling VMs.
Wed Jun 10 10:54:02 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 10:54:02 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00877915s
Wed Jun 10 10:54:02 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 10:54:02 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 10:54:02 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 7.4312e-05s
Wed Jun 10 10:54:31 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00224268s
Wed Jun 10 10:54:32 2015 [Z0][VM][D]: Found 2 pending/rescheduling VMs.
Wed Jun 10 10:54:32 2015 [Z0][HOST][D]: Discovered 0 enabled hosts.
Wed Jun 10 10:54:32 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00798932s
Wed Jun 10 10:54:32 2015 [Z0][SCHED][D]: Match-making results for VM 0:
Wed Jun 10 10:54:32 2015 [Z0][SCHED][D]: Match-making results for VM 1:
Wed Jun 10 10:54:32 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 10:54:32 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 10:54:32 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 4.1428e-05s

9

So the VM and sched.logs are consistent for that point 0 hosts and messages.

The problem is the previous scheduling step, 6 enabled hosts and no VM dispatched. The sched messages are overwritten in the VM. So, is there any chance to get the system state to that point 6 hosts up and monitored and no scheduled VM, and check if there is a message in the VM?

10

sorry Ruben I don’t follow? What do you mean?

11

It seems that the last messages there are no hosts enabled (or they are in
error state)

Wed Jun 10 10:54:32 2015 [Z0][HOST][D]: Discovered 0 enabled hosts.

Could you bring them back, and see if there are new information in the
onevm show output?

12

I actually tried to instantiate a new vm:

I see this in the sched.log:

Wed Jun 10 12:20:24 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:20:24 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:20:24 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00865405s
Wed Jun 10 12:20:24 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:20:24 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:20:24 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 5.6926e-05s
Wed Jun 10 12:20:53 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00205205s
Wed Jun 10 12:20:54 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:20:54 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:20:54 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00829487s
Wed Jun 10 12:20:54 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:20:54 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:20:54 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 6.0501e-05s
Wed Jun 10 12:21:23 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00189272s
Wed Jun 10 12:21:23 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:21:24 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:21:24 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00841761s
Wed Jun 10 12:21:24 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:21:24 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:21:24 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 7.133e-05s
Wed Jun 10 12:21:53 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00217081s
Wed Jun 10 12:21:53 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:21:54 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:21:54 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00829147s
Wed Jun 10 12:21:54 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:21:54 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:21:54 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 6.1349e-05s
Wed Jun 10 12:22:23 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00194499s
Wed Jun 10 12:22:23 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:22:24 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:22:24 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00840124s
Wed Jun 10 12:22:24 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:22:24 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:22:24 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 6.1971e-05s
Wed Jun 10 12:22:53 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00224552s
Wed Jun 10 12:22:54 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:22:54 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:22:54 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00827975s
Wed Jun 10 12:22:54 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:22:54 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:22:54 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 6.0428e-05s
Wed Jun 10 12:23:23 2015 [Z0][SCHED][I]: Getting scheduled actions information. Total time: 0.00191932s
Wed Jun 10 12:23:24 2015 [Z0][VM][D]: Found 1 pending/rescheduling VMs.
Wed Jun 10 12:23:24 2015 [Z0][HOST][D]: Discovered 6 enabled hosts.
Wed Jun 10 12:23:24 2015 [Z0][SCHED][I]: Getting VM and Host information. Total time: 0.00888487s
Wed Jun 10 12:23:24 2015 [Z0][SCHED][D]: Match Making statistics:
Wed Jun 10 12:23:24 2015 [Z0][SCHED][D]: Dispatching VMs to hosts:
Wed Jun 10 12:23:24 2015 [Z0][SCHED][I]: Dispatching VMs to hosts. Total time: 5.6282e-05s

VIRTUAL MACHINE 2 INFORMATION
ID : 2
NAME : Todds_1204
USER : oneadmin
GROUP : oneadmin
STATE : PENDING
LCM_STATE : LCM_INIT
RESCHED : No
START TIME : 06/10 12:20:02
END TIME : -
DEPLOY ID : -

VIRTUAL MACHINE MONITORING
USED MEMORY : 0K
USED CPU : 0
NET_TX : 0K
NET_RX : 0K

PERMISSIONS
OWNER : um-
GROUP : —
OTHER : —

VM DISKS
ID TARGET IMAGE TYPE SAVE SAVE_AS
0 hda Precise_X86_64 cdro NO -

VM NICS
ID NETWORK VLAN BRIDGE IP MAC
0 private no br0 192.168.32.101 02:00:c0:a8:20:65

SECURITY

NIC_ID NETWORK SECURITY_GROUPS
0 private 0

SECURITY GROUP TYPE PROTOCOL NETWORK RANGE
ID NAME VNET START SIZE
0 default OUTBOUND ALL
0 default INBOUND ALL

VIRTUAL MACHINE TEMPLATE
AUTOMATIC_REQUIREMENTS="!(PUBLIC_CLOUD = YES)"
CONTEXT=[
DISK_ID=“1”,
TARGET=“hdb” ]
CPU="2"
GRAPHICS=[
LISTEN=“0.0.0.0”,
PORT=“5902”,
TYPE=“vnc” ]
MEMORY="2096"
OS=[
ARCH=“x86_64” ]
TEMPLATE_ID="1"
VCPU="2"
VMID=“2”

13

Do not see anything wrong there (maybe missing some messages). Do you see anything in oned.log, is any deploy message?

14

I don’t see any errors here?

oned.log for 12:20:

Wed Jun 10 12:20:02 2015 [Z0][ReM][D]: Req:1040 UID:0 TemplateInfo invoked , 1
Wed Jun 10 12:20:02 2015 [Z0][ReM][D]: Req:1040 UID:0 TemplateInfo result SUCCESS, "1</I…"
Wed Jun 10 12:20:02 2015 [Z0][ReM][D]: Req:8000 UID:0 TemplateInstantiate invoked , 1, “Todds_1204”, false, ""
Wed Jun 10 12:20:03 2015 [Z0][ReM][D]: Req:8000 UID:0 TemplateInstantiate result SUCCESS, 2
Wed Jun 10 12:20:04 2015 [Z0][InM][D]: Monitoring host 1cn7.dev.gogii.net (4)
Wed Jun 10 12:20:05 2015 [Z0][InM][D]: Monitoring host 1cn8.dev.gogii.net (5)
Wed Jun 10 12:20:08 2015 [Z0][InM][D]: Host 1cn7.dev.gogii.net (4) successfully monitored.
Wed Jun 10 12:20:08 2015 [Z0][InM][D]: Host 1cn8.dev.gogii.net (5) successfully monitored.
Wed Jun 10 12:20:09 2015 [Z0][ReM][D]: Req:1088 UID:0 VirtualMachinePoolInfo invoked , -2, 0, -2000, -1
Wed Jun 10 12:20:09 2015 [Z0][ReM][D]: Req:1088 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL>2</…"
Wed Jun 10 12:20:11 2015 [Z0][ReM][D]: Req:8208 UID:0 VirtualMachineInfo invoked , 2
Wed Jun 10 12:20:11 2015 [Z0][ReM][D]: Req:8208 UID:0 VirtualMachineInfo result SUCCESS, "20…"
Wed Jun 10 12:20:18 2015 [Z0][ReM][D]: Req:1264 UID:0 VirtualMachineInfo invoked , 2
Wed Jun 10 12:20:18 2015 [Z0][ReM][D]: Req:1264 UID:0 VirtualMachineInfo result SUCCESS, "20…"
Wed Jun 10 12:20:23 2015 [Z0][ReM][D]: Req:6624 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Jun 10 12:20:23 2015 [Z0][ReM][D]: Req:6624 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL>2</…"
Wed Jun 10 12:20:23 2015 [Z0][ReM][D]: Req:528 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Jun 10 12:20:23 2015 [Z0][ReM][D]: Req:528 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL>2</…"
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:7456 UID:0 DatastorePoolInfo invoked
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:7456 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT…"
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:9888 UID:0 DatastorePoolInfo invoked
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:9888 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT…"
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:2080 UID:0 HostPoolInfo invoked
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:2080 UID:0 HostPoolInfo result SUCCESS, "<HOST_POOL><ID…"
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:8416 UID:0 ClusterPoolInfo invoked
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:8416 UID:0 ClusterPoolInfo result SUCCESS, "<CLUSTER_POOL><CLUST…"
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:9824 UID:0 AclInfo invoked
Wed Jun 10 12:20:24 2015 [Z0][ReM][D]: Req:9824 UID:0 AclInfo result SUCCESS, "<ACL_POOL>0…"
Wed Jun 10 12:20:27 2015 [Z0][InM][D]: Monitoring datastore default (1)
Wed Jun 10 12:20:27 2015 [Z0][InM][D]: Monitoring datastore files (2)
Wed Jun 10 12:20:28 2015 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Wed Jun 10 12:20:28 2015 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Wed Jun 10 12:20:45 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 70 -

Wed Jun 10 12:20:45 2015 [Z0][ReM][D]: Req:9120 UID:0 VirtualMachineInfo invoked , 2
Wed Jun 10 12:20:45 2015 [Z0][ReM][D]: Req:9120 UID:0 VirtualMachineInfo result SUCCESS, "20…"
Wed Jun 10 12:20:45 2015 [Z0][ReM][D]: Req:816 UID:0 VirtualMachineInfo invoked , 2
Wed Jun 10 12:20:45 2015 [Z0][ReM][D]: Req:816 UID:0 VirtualMachineInfo result SUCCESS, "20…"
Wed Jun 10 12:20:47 2015 [Z0][InM][D]: Monitoring host 1cn3.dev.gogii.net (1)
Wed Jun 10 12:20:51 2015 [Z0][ReM][D]: Req:288 UID:0 VirtualMachineInfo invoked , 2
Wed Jun 10 12:20:51 2015 [Z0][ReM][D]: Req:288 UID:0 VirtualMachineInfo result SUCCESS, "20…"
Wed Jun 10 12:20:51 2015 [Z0][InM][D]: Host 1cn3.dev.gogii.net (1) successfully monitored.
Wed Jun 10 12:20:53 2015 [Z0][ReM][D]: Req:4112 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Jun 10 12:20:53 2015 [Z0][ReM][D]: Req:4112 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL>2</…"
Wed Jun 10 12:20:53 2015 [Z0][ReM][D]: Req:2000 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Jun 10 12:20:53 2015 [Z0][ReM][D]: Req:2000 UID:0 VirtualMachinePoolInfo result SUCCESS, "<VM_POOL>2</…"
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:9232 UID:0 DatastorePoolInfo invoked
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:9232 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT…"
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:6880 UID:0 DatastorePoolInfo invoked
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:6880 UID:0 DatastorePoolInfo result SUCCESS, "<DATASTORE_POOL><DAT…"
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:6528 UID:0 HostPoolInfo invoked
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:6528 UID:0 HostPoolInfo result SUCCESS, "<HOST_POOL><ID…"
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:7136 UID:0 ClusterPoolInfo invoked
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:7136 UID:0 ClusterPoolInfo result SUCCESS, "<CLUSTER_POOL><CLUST…"
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:1824 UID:0 AclInfo invoked
Wed Jun 10 12:20:54 2015 [Z0][ReM][D]: Req:1824 UID:0 AclInfo result SUCCESS, "<ACL_POOL>0…"
Wed Jun 10 12:21:02 2015 [Z0][InM][D]: Monitoring host 1cn2.dev.gogii.net (0)
Wed Jun 10 12:21:03 2015 [Z0][InM][D]: Monitoring host 1cn4.dev.gogii.net (2)
Wed Jun 10 12:21:03 2015 [Z0][InM][D]: Monitoring host 1cn6.dev.gogii.net (3)
Wed Jun 10 12:21:06 2015 [Z0][InM][D]: Host 1cn2.dev.gogii.net (0) successfully monitored.
Wed Jun 10 12:21:07 2015 [Z0][InM][D]: Host 1cn4.dev.gogii.net (2) successfully monitored.
Wed Jun 10 12:21:07 2015 [Z0][InM][D]: Host 1cn6.dev.gogii.net (3) successfully monitored.
Wed Jun 10 12:21:17 2015 [Z0][InM][D]: Monitoring host 1cn7.dev.gogii.net (4)
Wed Jun 10 12:21:18 2015 [Z0][InM][D]: Monitoring host 1cn8.dev.gogii.net (5)
Wed Jun 10 12:21:21 2015 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 71 -

15

is there any output for:

 grep -i deploy -5 oned.log*
16

I only see this from earlier?

oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/migrate_local: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/kvmrc: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/poll: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/detach_nic: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/snapshot_delete: Permission denied
oned.log:Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/deploy: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/save: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/shutdown: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/reboot: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/cancel: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/kvm/migrate: Permission denied

oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/ec2: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/az: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/poll: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/detach_nic: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/snapshot_delete: Permission denied
oned.log:Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/deploy: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/save: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/shutdown: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/reboot: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/vmware_driver.rb: Permission denied
oned.log-Wed Jun 10 08:10:33 2015 [Z0][InM][I]: scp: /var/tmp/one/./vmm/vmware/cancel: Permission denied

17

I’ve solved this by completely re-installing all boxes… Thank you for your help Ruben!

18

Great! I was totally puzzled

1 Like