You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Sailaja Mada (JIRA)" <ji...@apache.org> on 2013/07/26 09:17:48 UTC
[jira] [Updated] (CLOUDSTACK-3844) System VMs are failed to start
first time
[ https://issues.apache.org/jira/browse/CLOUDSTACK-3844?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Sailaja Mada updated CLOUDSTACK-3844:
-------------------------------------
Attachment: management-server.log
apilog.log
> System VMs are failed to start first time
> ------------------------------------------
>
> Key: CLOUDSTACK-3844
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3844
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: VMware
> Affects Versions: 4.2.0
> Reporter: Sailaja Mada
> Attachments: apilog.log, management-server.log
>
>
> Setup: VMWARE 5.1 , Zone wide primary storage , Adv networking Zone
> 1. Configure Adv Zone with zone wide primary storage
> 2. Add VMWARE 5.1 host
> 3.After Zone configuration is completed CloudStack started to bring up system VM's (SSVM/CPVM)
> Observation:
> For the first time system VM's failed to start with NPE. But later they started with no issues.
> Details :
> 2013-07-26 12:33:55,906 INFO [vmware.resource.VmwareResource] (DirectAgent-8:10.102.192.19) Executing resource StartCommand: {"vm":{"id":2,"name":"v-2-VM","bootloader":"HVM","type":"ConsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"i686","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy host=10.102.192.184 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=10.102.197.221 eth2mask=255.255.255.0 gateway=10.102.197.1 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=10.102.195.134 eth1mask=255.255.252.0 mgmtcidr=10.102.192.0/22 localgw=10.102.192.1 internaldns1=10.103.128.15 dns1=10.103.128.15","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"8823662ee1fe9390","params":{"nicAdapter":"E1000"},"uuid":"82d53a61-c755-461c-8d80-34116e72cc8e","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0954dc10-510a-4fa7-b842-332bbbf09faf","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a5d175a7-fc4b-3184-879a-9c1c475311c0","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/vmware51ps1","port":2049}},"name":"ROOT-2","size":0,"path":"ROOT-2-2","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"OVA","id":2,"hypervisorType":"None"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"e8c43cf4-e017-4d3b-8072-5aaf8053caf5","ip":"10.102.197.221","netmask":"255.255.255.0","gateway":"10.102.197.1","mac":"06:83:92:00:00:08","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://101","isolationUri":"vlan://101","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"bbe64574-9fc6-4f4f-a8ab-31728491825e","mac":"02:00:5d:95:00:02","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"f6ddb54a-5890-4c95-8ba1-06ce75ff5b70","ip":"10.102.195.134","netmask":"255.255.252.0","gateway":"10.102.192.1","mac":"06:31:e8:00:00:05","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"hostIp":"10.102.192.19","executeInSequence":false,"wait":0}
> 2013-07-26 12:33:55,906 DEBUG [vmware.resource.VmwareResource] (DirectAgent-8:10.102.192.19) VM v-2-VM will be started with NIC device type: E1000
> 2013-07-26 12:33:55,965 DEBUG [vmware.mo.HostMO] (DirectAgent-8:10.102.192.19) find VM v-2-VM on host
> 2013-07-26 12:33:55,965 DEBUG [vmware.mo.HostMO] (DirectAgent-8:10.102.192.19) load VM cache on host
> 2013-07-26 12:33:56,003 INFO [vmware.mo.HypervisorHostHelper] (DirectAgent-8:10.102.192.19) Create blank VM. cpuCount: 1, cpuSpeed(MHz): 500, mem(Mb): 1024
> 2013-07-26 12:33:56,499 DEBUG [vmware.mo.HostMO] (DirectAgent-8:10.102.192.19) find VM v-2-VM on host
> 2013-07-26 12:33:56,499 DEBUG [vmware.mo.HostMO] (DirectAgent-8:10.102.192.19) load VM cache on host
> 2013-07-26 12:33:56,503 INFO [storage.resource.VmwareStorageProcessor] (DirectAgent-7:10.102.192.19) detach disks from volume-wrapper VM ROOT-1-1
> 2013-07-26 12:33:56,541 WARN [vmware.resource.VmwareResource] (DirectAgent-8:10.102.192.19) StartCommand failed due to Exception: java.lang.NullPointerException
> Message: null
> java.lang.NullPointerException
> at com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.createBlankVm(HypervisorHostHelper.java:1165)
> at com.cloud.hypervisor.vmware.mo.HostMO.createBlankVm(HostMO.java:700)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2638)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:520)
> at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-07-26 12:33:56,547 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-8:null) Seq 1-107151372: Cancelling because one of the answers is false and it is stop on error.
> 2013-07-26 12:33:56,547 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-8:null) Seq 1-107151372: Response Received:
> 2013-07-26 12:33:56,551 DEBUG [agent.transport.Request] (DirectAgent-8:null) Seq 1-107151372: Processing: { Ans: , MgmtId: 55638679939377, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":2,"name":"v-2-VM","bootloader":"HVM","type":"ConsoleProxy","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":1073741824,"maxRam":1073741824,"arch":"i686","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=consoleproxy host=10.102.192.184 port=8250 name=v-2-VM premium=true zone=1 pod=1 guid=Proxy.2 proxy_vm=2 disable_rp_filter=true eth2ip=10.102.197.221 eth2mask=255.255.255.0 gateway=10.102.197.1 eth0ip=0.0.0.0 eth0mask=0.0.0.0 eth1ip=10.102.195.134 eth1mask=255.255.252.0 mgmtcidr=10.102.192.0/22 localgw=10.102.192.1 internaldns1=10.103.128.15 dns1=10.103.128.15","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"8823662ee1fe9390","params":{"nicAdapter":"E1000"},"uuid":"82d53a61-c755-461c-8d80-34116e72cc8e","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"0954dc10-510a-4fa7-b842-332bbbf09faf","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a5d175a7-fc4b-3184-879a-9c1c475311c0","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/vmware51ps1","port":2049}},"name":"ROOT-2","size":0,"path":"ROOT-2-2","volumeId":2,"vmName":"v-2-VM","accountId":1,"format":"OVA","id":2,"hypervisorType":"None"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"e8c43cf4-e017-4d3b-8072-5aaf8053caf5","ip":"10.102.197.221","netmask":"255.255.255.0","gateway":"10.102.197.1","mac":"06:83:92:00:00:08","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://101","isolationUri":"vlan://101","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"bbe64574-9fc6-4f4f-a8ab-31728491825e","mac":"02:00:5d:95:00:02","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"f6ddb54a-5890-4c95-8ba1-06ce75ff5b70","ip":"10.102.195.134","netmask":"255.255.252.0","gateway":"10.102.192.1","mac":"06:31:e8:00:00:05","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false}]},"result":false,"details":"StartCommand failed due to Exception: java.lang.NullPointerException\nMessage: null\n","wait":0}}] }
> 2013-07-26 12:33:56,552 DEBUG [agent.transport.Request] (consoleproxy-1:null) Seq 1-107151372: Received: { Ans: , MgmtId: 55638679939377, via: 1, Ver: v1, Flags: 10, { StartAnswer } }
> 2013-07-26 12:33:56,560 INFO [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Unable to start VM on Host[-1-Routing] due to StartCommand failed due to Exception: java.lang.NullPointerException
> Message: null
> 2013-07-26 12:33:56,725 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release cpu from host: 1, old used: 1000,reserved: 0, actual total: 9572, total with overprovisioning: 9572; new used: 500,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-26 12:33:56,725 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) release mem from host: 1, old used: 1342177280,reserved: 0, total: 17166258176; new used: 268435456,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-26 12:33:56,735 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
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:882)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:618)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:611)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.startProxy(ConsoleProxyManagerImpl.java:556)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.allocCapacity(ConsoleProxyManagerImpl.java:927)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:1664)
> at com.cloud.consoleproxy.ConsoleProxyManagerImpl.expandPool(ConsoleProxyManagerImpl.java:157)
> at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:111)
> at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-07-26 12:33:56,761 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
> 2013-07-26 12:33:56,762 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Expand console proxy standby capacity for zone vmware51zone
> 2013-07-26 12:33:56,766 INFO [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Found a stopped console proxy, bring it up to running pool. proxy vm id : 2
> 2013-07-26 12:33:56,777 DEBUG [cloud.capacity.CapacityManagerImpl] (consoleproxy-1:null) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
> 2013-07-26 12:33:56,777 DEBUG [cloud.vm.VirtualMachineManagerImpl] (consoleproxy-1:null) Successfully transitioned to start state for VM[ConsoleProxy|v-2-VM] reservation id = 98765ac3-4250-415d-924b-a54fbe1b36a5
> 2013-07-26 12:34:15,601 INFO [vmware.resource.VmwareResource] (DirectAgent-9:10.102.192.19) Prepare NIC device based on NicTO: {"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"004bab44-a130-4777-8a52-ae1a1f623966","ip":"10.102.197.220","netmask":"255.255.255.0","gateway":"10.102.197.1","mac":"06:77:ae:00:00:07","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://101","isolationUri":"vlan://101","isSecurityGroupEnabled":false}
> 2013-07-26 12:34:15,607 INFO [vmware.resource.VmwareResource] (DirectAgent-9:10.102.192.19) Prepare network on vmwaresvs P[vSwitch0:untagged] with name prefix: cloud.public
> 2013-07-26 12:34:15,726 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers to update status.
> 2013-07-26 12:34:15,728 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
> 2013-07-26 12:34:17,370 INFO [vmware.mo.HypervisorHostHelper] (DirectAgent-10:10.102.192.19) Waiting for network cloud.public.101.0.1-vSwitch0 to be ready
> 2013-07-26 12:34:17,625 WARN [vmware.resource.VmwareResource] (DirectAgent-9:10.102.192.19) StartCommand failed due to Exception: com.vmware.vim25.AlreadyExists
> message: []
> com.vmware.vim25.AlreadyExistsFaultMsg: The specified key, name, or identifier already exists.
> at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
> at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
> at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
> at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
> at com.sun.xml.internal.ws.fault.SOAPFaultBuilder.createException(SOAPFaultBuilder.java:130)
> at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:108)
> at com.sun.xml.internal.ws.client.sei.SyncMethodHandler.invoke(SyncMethodHandler.java:78)
> at com.sun.xml.internal.ws.client.sei.SEIStub.invoke(SEIStub.java:107)
> at $Proxy90.addPortGroup(Unknown Source)
> at com.cloud.hypervisor.vmware.mo.HostNetworkSystemMO.addPortGroup(HostNetworkSystemMO.java:38)
> at com.cloud.hypervisor.vmware.mo.HostMO.createPortGroup(HostMO.java:389)
> at com.cloud.hypervisor.vmware.mo.HypervisorHostHelper.prepareNetwork(HypervisorHostHelper.java:961)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.prepareNetworkFromNicInfo(VmwareResource.java:3227)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.execute(VmwareResource.java:2853)
> at com.cloud.hypervisor.vmware.resource.VmwareResource.executeRequest(VmwareResource.java:520)
> at com.cloud.agent.manager.DirectAgentAttache$Task.run(DirectAgentAttache.java:186)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:165)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-07-26 12:34:17,631 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-9:null) Seq 1-107151375: Cancelling because one of the answers is false and it is stop on error.
> 2013-07-26 12:34:17,631 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-9:null) Seq 1-107151375: Response Received:
> 2013-07-26 12:34:17,635 DEBUG [agent.transport.Request] (DirectAgent-9:null) Seq 1-107151375: Processing: { Ans: , MgmtId: 55638679939377, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":1,"name":"s-1-VM","bootloader":"HVM","type":"SecondaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":268435456,"maxRam":268435456,"arch":"i686","os":"Debian GNU/Linux 5.0 (32-bit)","bootArgs":" template=domP type=secstorage host=10.102.192.184 port=8250 name=s-1-VM zone=1 pod=1 guid=s-1-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=true role=templateProcessor mtu=1500 eth2ip=10.102.197.220 eth2mask=255.255.255.0 gateway=10.102.197.1 public.network.device=eth2 eth0mask=0.0.0.0 eth0ip=0.0.0.0 eth1ip=10.102.195.131 eth1mask=255.255.252.0 mgmtcidr=10.102.192.0/22 localgw=10.102.192.1 private.network.device=eth1 eth3ip=10.102.195.132 eth3mask=255.255.252.0 storageip=10.102.195.132 storagenetmask=255.255.252.0 storagegateway=10.102.192.1 internaldns1=10.103.128.15 dns1=10.103.128.15","rebootOnCrash":false,"enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"335ab3de528f823f","params":{"nicAdapter":"E1000"},"uuid":"22ec4ee1-38be-4881-b66b-c301e09570f6","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"4f3e9847-16e0-45b6-8e76-191d6597d530","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"a5d175a7-fc4b-3184-879a-9c1c475311c0","id":1,"poolType":"NetworkFilesystem","host":"10.102.192.100","path":"/cpg_vol/sailaja/vmware51ps1","port":2049}},"name":"ROOT-1","size":0,"path":"ROOT-1-1","volumeId":1,"vmName":"s-1-VM","accountId":1,"format":"OVA","id":1,"hypervisorType":"None"}},"diskSeq":0,"type":"ROOT"}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"uuid":"004bab44-a130-4777-8a52-ae1a1f623966","ip":"10.102.197.220","netmask":"255.255.255.0","gateway":"10.102.197.1","mac":"06:77:ae:00:00:07","dns1":"10.103.128.15","broadcastType":"Vlan","type":"Public","broadcastUri":"vlan://101","isolationUri":"vlan://101","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"uuid":"603100b5-b362-4e9e-97f0-301418b3cc71","mac":"02:00:73:4a:00:01","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"uuid":"b9f565be-fc33-43c0-84a2-150c05815b45","ip":"10.102.195.131","netmask":"255.255.252.0","gateway":"10.102.192.1","mac":"06:9f:c6:00:00:02","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"uuid":"fb21b81b-11cc-4141-960e-86e8c1c3fcd1","ip":"10.102.195.132","netmask":"255.255.252.0","gateway":"10.102.192.1","mac":"06:9d:24:00:00:03","broadcastType":"Native","type":"Storage","isSecurityGroupEnabled":false}]},"result":false,"details":"StartCommand failed due to Exception: com.vmware.vim25.AlreadyExists\nmessage: []\n","wait":0}}] }
> 2013-07-26 12:34:17,636 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-107151375: Received: { Ans: , MgmtId: 55638679939377, via: 1, Ver: v1, Flags: 10, { StartAnswer } }
> 2013-07-26 12:34:17,650 INFO [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Unable to start VM on Host[-1-Routing] due to StartCommand failed due to Exception: com.vmware.vim25.AlreadyExists
> message: []
> 2013-07-26 12:34:17,659 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Cleaning up resources for the vm VM[SecondaryStorageVm|s-1-VM] in Starting state
> 2013-07-26 12:34:17,662 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-107151377: Sending { Cmd , MgmtId: 55638679939377, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"s-1-VM","wait":0}}] }
> 2013-07-26 12:34:17,662 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 1-107151377: Executing: { Cmd , MgmtId: 55638679939377, via: 1, Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"vmName":"s-1-VM","wait":0}}] }
> 2013-07-26 12:34:17,896 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) release mem from host: 1, old used: 1342177280,reserved: 0, total: 17166258176; new used: 1073741824,reserved:0; movedfromreserved: false,moveToReserveredfalse
> 2013-07-26 12:34:17,906 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-1-VM]Scope=interface com.cloud.dc.DataCenter; id=1
> at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:882)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:618)
> at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:611)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:265)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:690)
> at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1297)
> at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:123)
> at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50)
> at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:104)
> at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:33)
> at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:81)
> at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:72)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
> at java.lang.Thread.run(Thread.java:679)
> 2013-07-26 12:34:17,911 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 1, will recycle it and start a new one
> 2013-07-26 12:34:17,911 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn
> 2013-07-26 12:34:17,964 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
> 2013-07-26 12:34:17,972 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) No running secondary storage vms found in datacenter id=1, starting one
> 2013-07-26 12:34:17,984 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Found a stopped secondary storage vm, bring it up to running pool. secStorageVm vm id : 1
> 2013-07-26 12:34:17,998 DEBUG [cloud.capacity.CapacityManagerImpl] (secstorage-1:null) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: null host id before state transition: null
> 2013-07-26 12:34:17,998 DEBUG [cloud.vm.VirtualMachineManagerImpl] (secstorage-1:null) Successfully transitioned to start state for VM[SecondaryStorageVm|s-1-VM] reservation id = 7b15e385-2e98-4681-bcbe-e106a673efab
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira