System VMs not starting

["Vosbury, David" <da...@systemsmadesimple.com>]

I've been trying to get an new install of CloudStack 4.2 working with a Vsphere cluster. I've went through creating my zone with advanced networking. I can see the system VMs but they are not started. The secondary storage vm seems to keep appearing and disappearing however. When I look in vcenter I see that vms are being created one after another named root-2 and then root-192, root-193 etc. They keep creating one after another until I shutdown the management service. Here is part of the management-server.log

Has anyone seen this before. I've seen some references to bugs that sound like this problem that were supposedly fixed back in August. I don' t know if I have an earlier build of 4.2, but I downloaded and compiled it just last week and I'm having this issue.

2013-12-05 00:07:28,642 WARN  [utils.crypt.EncryptionSecretKeyChecker] (Timer-2:null) Encryption already enabled, is check() called twice?
2013-12-05 00:07:29,394 DEBUG [cloud.server.ConfigurationServerImpl] (Timer-2:null) mount: warning: /systemvm_mnt seems to be mounted read-only.
2013-12-05 00:07:30,316 INFO  [xen.resource.XenServerConnectionPool] (Timer-2:null) XenServer Connection Pool Configs: manage.xenserver.pool.master=true; sleep.interval.on.error=10000
2013-12-05 00:07:30,997 WARN  [utils.crypt.EncryptionSecretKeyChecker] (Timer-2:null) Encryption already enabled, is check() called twice?
2013-12-05 00:07:34,050 WARN  [apache.cloudstack.alerts] (Cluster-Notification-1:null)  alertType:: 14 // dataCenterId:: 0 // podId:: 0 // clusterId:: null // message:: Management server node 10.2.150.100 is up
2013-12-05 00:07:34,071 WARN  [cloud.cluster.ClusterManagerImpl] (Cluster-Notification-1:null) Notifying management server join event took 39 ms
2013-12-05 00:08:33,140 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-2:esxi2.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:08:33,145 DEBUG [agent.transport.Request] (DirectAgent-2:null) Seq 1-1861287941: Processing:  { Ans: , MgmtId: 146454222325, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-2' already exists.","wait":0}}] }
2013-12-05 00:08:33,163 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (consoleproxy-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@4838d3f7), no need to delete from object in store ref table
2013-12-05 00:08:33,164 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:08:33,169 INFO  [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:08:56,958 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-4:esxi1.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-203/ROOT-203.vmdk was not found
2013-12-05 00:08:56,960 DEBUG [agent.transport.Request] (DirectAgent-4:null) Seq 2-2058223621: Processing:  { Ans: , MgmtId: 146454222325, via: 2, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-203/ROOT-203.vmdk was not found","wait":0}}] }
2013-12-05 00:08:56,978 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (secstorage-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@6e0e449e), no need to delete from object in store ref table
2013-12-05 00:08:56,979 DEBUG [cloud.storage.VolumeManagerImpl] (secstorage-1:null) Unable to create Vol[203|vm=203|ROOT]:java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-203/ROOT-203.vmdk was not found
2013-12-05 00:08:56,980 INFO  [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[203|vm=203|ROOT]:java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-203/ROOT-203.vmdk was not found
2013-12-05 00:08:57,231 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:08:57,272 WARN  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-2-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:08:57,333 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:08:57,370 WARN  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-203-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:08:57,376 INFO  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 203, will recycle it and start a new one
2013-12-05 00:09:02,891 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-15:esxi1.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: The name 'ROOT-203' already exists.
2013-12-05 00:09:02,896 DEBUG [agent.transport.Request] (DirectAgent-15:null) Seq 2-2058223626: Processing:  { Ans: , MgmtId: 146454222325, via: 2, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-203' already exists.","wait":0}}] }
2013-12-05 00:09:02,911 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (secstorage-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@555bb5a1), no need to delete from object in store ref table
2013-12-05 00:09:02,912 DEBUG [cloud.storage.VolumeManagerImpl] (secstorage-1:null) Unable to create Vol[203|vm=203|ROOT]:java.lang.RuntimeException: The name 'ROOT-203' already exists.
2013-12-05 00:09:02,912 INFO  [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[203|vm=203|ROOT]:java.lang.RuntimeException: The name 'ROOT-203' already exists.
2013-12-05 00:09:03,011 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-1:esxi2.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:09:03,015 DEBUG [agent.transport.Request] (DirectAgent-1:null) Seq 1-1861287943: Processing:  { Ans: , MgmtId: 146454222325, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-2' already exists.","wait":0}}] }
2013-12-05 00:09:03,031 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (consoleproxy-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@10aba5d3), no need to delete from object in store ref table
2013-12-05 00:09:03,032 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:09:03,032 INFO  [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:09:03,171 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:09:03,205 WARN  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-203-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:09:03,209 INFO  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 203, will recycle it and start a new one
2013-12-05 00:09:03,312 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:09:03,346 WARN  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-2-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:09:32,800 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-16:esxi2.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:09:32,804 DEBUG [agent.transport.Request] (DirectAgent-16:null) Seq 1-1861287944: Processing:  { Ans: , MgmtId: 146454222325, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-2' already exists.","wait":0}}] }
2013-12-05 00:09:32,816 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (consoleproxy-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@761b309), no need to delete from object in store ref table
2013-12-05 00:09:32,817 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:09:32,817 INFO  [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:09:55,743 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-6:esxi1.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-204/ROOT-204.vmdk was not found
2013-12-05 00:09:55,747 DEBUG [agent.transport.Request] (DirectAgent-6:null) Seq 2-2058223629: Processing:  { Ans: , MgmtId: 146454222325, via: 2, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-204/ROOT-204.vmdk was not found","wait":0}}] }
2013-12-05 00:09:55,762 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (secstorage-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@5022c22d), no need to delete from object in store ref table
2013-12-05 00:09:55,763 DEBUG [cloud.storage.VolumeManagerImpl] (secstorage-1:null) Unable to create Vol[204|vm=204|ROOT]:java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-204/ROOT-204.vmdk was not found
2013-12-05 00:09:55,763 INFO  [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[204|vm=204|ROOT]:java.lang.RuntimeException: File [iSCSI-Datastore-1] ROOT-204/ROOT-204.vmdk was not found
2013-12-05 00:09:55,979 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:09:56,007 WARN  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-2-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:09:56,047 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:09:56,074 WARN  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-204-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:09:56,078 INFO  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 204, will recycle it and start a new one
2013-12-05 00:10:02,419 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-7:esxi2.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: The name 'ROOT-204' already exists.
2013-12-05 00:10:02,420 DEBUG [agent.transport.Request] (DirectAgent-7:null) Seq 1-1861287947: Processing:  { Ans: , MgmtId: 146454222325, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-204' already exists.","wait":0}}] }
2013-12-05 00:10:02,435 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (secstorage-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@1d6a89e1), no need to delete from object in store ref table
2013-12-05 00:10:02,436 DEBUG [cloud.storage.VolumeManagerImpl] (secstorage-1:null) Unable to create Vol[204|vm=204|ROOT]:java.lang.RuntimeException: The name 'ROOT-204' already exists.
2013-12-05 00:10:02,436 INFO  [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[204|vm=204|ROOT]:java.lang.RuntimeException: The name 'ROOT-204' already exists.
2013-12-05 00:10:02,704 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 2
2013-12-05 00:10:02,731 WARN  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[SecondaryStorageVm|s-204-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2013-12-05 00:10:02,735 INFO  [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 204, will recycle it and start a new one
2013-12-05 00:10:03,762 ERROR [storage.resource.VmwareStorageProcessor] (DirectAgent-23:esxi2.ammscloud.com) clone volume from base image failed due to Exception: java.lang.RuntimeException
java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:10:03,766 DEBUG [agent.transport.Request] (DirectAgent-23:null) Seq 1-1861287948: Processing:  { Ans: , MgmtId: 146454222325, via: 1, Ver: v1, Flags: 110, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.lang.RuntimeException: The name 'ROOT-2' already exists.","wait":0}}] }
2013-12-05 00:10:03,780 WARN  [storage.datastore.ObjectInDataStoreManagerImpl] (consoleproxy-1:null) Unsupported data object (VOLUME, org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@53e3d60f), no need to delete from object in store ref table
2013-12-05 00:10:03,781 DEBUG [cloud.storage.VolumeManagerImpl] (consoleproxy-1:null) Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:10:03,781 INFO  [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:4] is unreachable: Unable to create Vol[2|vm=2|ROOT]:java.lang.RuntimeException: The name 'ROOT-2' already exists.
2013-12-05 00:10:04,006 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Starting to Stopped with event: OperationFailedvm's original host id: null new host id: null host id before state transition: 1
2013-12-05 00:10:04,020 WARN  [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Exception while trying to start console proxy
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[ConsoleProxy|v-2-VM]Scope=interface com.cloud.dc.DataCenter; id=1

David Vosbury, Applications Systems Analyst
Phone: (800) 893-9883 x7052
Mobile: (315) 679-7641
david.vosbury@systemsmadesimple.com<ma...@systemsmadesimple.com>

[cid:image001.jpg@01CCCA0D.B5979EA0]

One of the Inc. 500 Fastest Growing Privately Held Companies in the U.S.

This is a PRIVATE message. If you are not the intended recipient, please delete without copying and kindly advise us by telephone or e-mail of the mistake in delivery. NOTE: Regardless of content, this e-mail shall not operate to bind Systems Made Simple (SMS) to any order or other contract unless pursuant to explicit written agreement or government initiative expressly permitting the use of e-mail for such purpose.