You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by "Wwei@landhightech.com" <Ww...@landhightech.com> on 2015/01/09 08:56:53 UTC
Can not add a new virtual instance by a template
Hi，
We had an issue when we add a new virtual instance by template.we can not create the new instance.
We use cloudstack 4.4.1 + Vmware ,advanced network ,local storage.
We want to add a new virtual instance into a share network.
Message: File upload task failed to complete due to: Error writing request body to server
------------------------------------------
2015-01-09 23:30:14,876 DEBUG [o.a.c.s.RemoteHostEndPoint] (Timer-11:ctx-a09c3aac) Sending command org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 3
2015-01-09 23:30:14,878 DEBUG [c.c.a.t.Request] (Timer-11:ctx-a09c3aac) Seq 3-1751055830117010306: Sending { Cmd , MgmtId: 52230225403, via: 3(s-1-VM), Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId":"b7835acd-50af-44e7-a91c-94b715722bfc","request":"GET_STATUS","hvm":false,"description":"CentOS 5.3(64-bit) no GUI (vSphere)","checksum":"f6f881b7f2292948d8494db837fe0f47","maxDownloadSizeInBytes":53687091200,"id":7,"resourceType":"TEMPLATE","installPath":"template/tmpl/1/7","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.10.2/secondary","_role":"Image"}},"url":"http://download.cloud.com/releases/2.2.0/CentOS5.3-x86_64.ova","format":"OVA","accountId":1,"name":"centos53-x64","secUrl":"nfs://192.168.10.2/secondary","wait":0}}] }
2015-01-09 23:30:14,923 DEBUG [c.c.a.t.Request] (AgentManager-Handler-11:null) Seq 3-1751055830117010306: Processing: { Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10, [{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"b7835acd-50af-44e7-a91c-94b715722bfc","downloadPct":0,"errorString":" ","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStorage/19e03beb-309a-3316-8e6d-5f25071372e5/template/tmpl/1/7/dnld5043761750658787860tmp_","installPath":"template/tmpl/1/7","templateSize":0,"templatePhySicalSize":0,"checkSum":"f6f881b7f2292948d8494db837fe0f47","result":true,"details":" ","wait":0}}] }
2015-01-09 23:30:15,780 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-6e8835bf) ===START=== 192.168.255.102 -- GET command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&response=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
2015-01-09 23:30:15,841 DEBUG [c.c.a.ApiServlet] (catalina-exec-23:ctx-6e8835bf ctx-35fa8112) ===END=== 192.168.255.102 -- GET command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&response=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
2015-01-09 23:30:16,170 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl] (Vm-Operations-Cleanup-1:ctx-86237200) Expunge completed work job-205
2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request] (AgentManager-Handler-3:null) Seq 3-1751055830117010304: Processing: { Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"Unable to copy template to primary storage due to exception:Exception: java.lang.Exception\nMessage: File upload task failed to complete due to: Error writing request body to server\n","wait":0}}] }
2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq 3-1751055830117010304: Received: { Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2015-01-09 23:30:18,047 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-22712: Processing Seq 2-22712: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] }
2015-01-09 23:30:18,116 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-2:null) SeqA 2-22712: Sending Seq 2-22712: { Ans: , MgmtId: 52230225403, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2015-01-09 23:30:18,150 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) releasing lock for VMTemplateStoragePool 19
2015-01-09 23:30:18,151 WARN [c.c.u.d.Merovingian2] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Was unable to find lock for the key template_spool_ref19 and thread id 1216625438
2015-01-09 23:30:18,151 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable to create Vol[32|vm=27|ROOT]:Unable to copy template to primary storage due to exception:Exception: java.lang.Exception
Message: File upload task failed to complete due to: Error writing request body to server
2015-01-09 23:30:18,151 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable to contact resource.
com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[32|vm=27|ROOT]:Unable to copy template to primary storage due to exception:Exception: java.lang.Exception
Message: File upload task failed to complete due to: Error writing request body to server
at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolume(VolumeOrchestrator.java:1205)
at org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(VolumeOrchestrator.java:1257)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:988)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-01-09 23:30:18,190 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Cleaning up resources for the vm VM[User|i-2-27-VM] in Starting state
2015-01-09 23:30:18,194 DEBUG [c.c.a.t.Request] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq 1-5183080221150030303: Sending { Cmd , MgmtId: 52230225403, via: 1(192.168.10.132), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
2015-01-09 23:30:18,195 DEBUG [c.c.a.t.Request] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq 1-5183080221150030303: Executing: { Cmd , MgmtId: 52230225403, via: 1(192.168.10.132), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
2015-01-09 23:30:18,195 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Executing request
2015-01-09 23:30:18,196 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-180:ctx-c474087e 192.168.10.132) Executing resource StopCommand: {"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}
2015-01-09 23:30:18,216 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-180:ctx-c474087e 192.168.10.132) find VM i-2-27-VM on host
2015-01-09 23:30:18,217 INFO [c.c.h.v.m.HostMO] (DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM not found in host cache
2015-01-09 23:30:18,217 DEBUG [c.c.h.v.m.HostMO] (DirectAgent-180:ctx-c474087e 192.168.10.132) load VM cache on host
2015-01-09 23:30:18,248 INFO [c.c.h.v.r.VmwareResource] (DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM is no longer in vSphere
2015-01-09 23:30:18,249 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Response Received:
2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request] (DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Processing: { Ans: , MgmtId: 52230225403, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-27-VM is no longer in vSphere","wait":0}}] }
2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq 1-5183080221150030303: Received: { Ans: , MgmtId: 52230225403, via: 1, Ver: v1, Flags: 10, { StopAnswer } }
2015-01-09 23:30:18,259 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Changing active number of nics for network id=205 on -1
2015-01-09 23:30:18,289 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Successfully released network resources for the vm VM[User|i-2-27-VM]
2015-01-09 23:30:18,290 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Successfully cleanued up resources for the vm VM[User|i-2-27-VM] in Starting state
2015-01-09 23:30:18,303 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Deploy avoids pods: [], clusters: [], hosts: [1]
2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@47130493
2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:1, requested cpu: 1999, requested ram: 2147483648
2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Is ROOT volume READY (pool already allocated)?: No
2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) DeploymentPlan has host_id specified, choosing this host and making no checks on this host: 1
2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) The specified host is in avoid set
2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Cannnot deploy to specified host, returning.
2015-01-09 23:30:18,404 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) 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
2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Hosts's actual total CPU: 31984 and CPU after applying overprovisioning: 31984
2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Hosts's actual total RAM: 137357598720 and RAM after applying overprovisioning: 137357598720
2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) release cpu from host: 1, old used: 13994,reserved: 1999, actual total: 31984, total with overprovisioning: 31984; new used: 11995,reserved:1999; movedfromreserved: false,moveToReserveredfalse
2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) release mem from host: 1, old used: 14763950080,reserved: 2147483648, total: 137357598720; new used: 12616466432,reserved:2147483648; movedfromreserved: false,moveToReserveredfalse
2015-01-09 23:30:18,481 ERROR [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Invocation exception, caused by: com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-27-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-01-09 23:30:18,481 INFO [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Rethrow exception com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-27-VM]Scope=interface com.cloud.dc.DataCenter; id=1
2015-01-09 23:30:18,482 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 206
2015-01-09 23:30:18,482 ERROR [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Unable to complete AsyncJobVO {id:207, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubGFuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAAx3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52230225403, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Jan 09 23:30:09 CST 2015}, job origin:206
com.cloud.exception.InsufficientServerCapacityException: Unable to create a deployment for VM[User|i-2-27-VM]Scope=interface com.cloud.dc.DataCenter; id=1
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:947)
at com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineManagerImpl.java:5195)
at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.java:107)
at com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManagerImpl.java:5340)
at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInContext(AsyncJobManagerImpl.java:503)
at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJobManagerImpl.java:460)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2015-01-09 23:30:18,485 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Complete async job-207, jobStatus: FAILED, resultCode: 0, result: rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubGFuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsDAARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMamF2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVsZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3QAUEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95bWVudCBmb3IgVk1bVXNlcnxpLTItMjctVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbGVtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJxZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZXEAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRpc3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dAA_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5hZ2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfgALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfgALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZhdWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbHNxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwuRGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQB-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQB-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAAABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFxAH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeHIALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
2015-01-09 23:30:18,525 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done executing com.cloud.vm.VmWorkStart for job-207
2015-01-09 23:30:18,570 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Sync job-208 execution on object VmWorkJobQueue.27
2015-01-09 23:30:18,574 WARN [c.c.u.d.Merovingian2] (API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Was unable to find lock for the key vm_instance27 and thread id 1208656886
2015-01-09 23:30:18,691 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Executing sync queue item: SyncQueueItemVO {id:93, queueId: 92, contentType: AsyncJob, contentId: 208, lastProcessMsid: 52230225403, lastprocessNumber: 2, lastProcessTime: Fri Jan 09 23:30:18 CST 2015, created: Fri Jan 09 23:30:18 CST 2015}
2015-01-09 23:30:18,693 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Schedule queued job-208
2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Queue (queue id, sync type, sync id) - (92,VmWorkJobQueue, 27) is reaching concurrency limit 1
2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) There is a pending process in sync queue(id: 92)
2015-01-09 23:30:18,757 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Remove job-207 from job monitoring
2015-01-09 23:30:18,760 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Add job-208 into job monitoring
2015-01-09 23:30:18,760 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Executing AsyncJobVO {id:208, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 52230225403, completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Jan 09 23:30:18 CST 2015}
2015-01-09 23:30:18,761 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Run VM work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 206
2015-01-09 23:30:18,763 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":27,"handlerName":"VirtualMachineManagerImpl"}
2015-01-09 23:30:18,774 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) 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
2015-01-09 23:30:18,774 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Successfully transitioned to start state for VM[User|i-2-27-VM] reservation id = b7635084-3b16-421f-9049-60c455b23867
2015-01-09 23:30:18,785 DEBUG [c.c.a.ApiServlet] (catalina-exec-24:ctx-d4c2aaff) ===START=== 192.168.255.102 -- GET command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&response=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788677859
2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Trying to deploy VM, vm has dcId: 1 and podId: 1
2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy avoids pods: null, clusters: null, hosts: null
2015-01-09 23:30:18,843 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy avoids pods: [], clusters: [], hosts: []
2015-01-09 23:30:18,844 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@47130493
Thanks.
Wwei@landhightech.com
RE: Re: Can not add a new virtual instance by a template
Posted by Anshul Gangwar <an...@citrix.com>.
Try to import it in vCenter and see it works fine or not. If it works fine then try registering it again in CloudStack.
-----Original Message-----
From: Wwei@landhightech.com [mailto:Wwei@landhightech.com]
Sent: Friday, January 09, 2015 3:20 PM
To: users
Subject: Re: Re: Can not add a new virtual instance by a template
We can add virtual instances by iso and other templates which created by cloudstack.
We want to migrate VMware instances to cloudstack.We import ova from vcenter.And login in cloudstack,go to templates,click on register template.And then add a instance by the template .But we can not add a new virtual instance by the template.
Thank you very much.
Wwei@landhightech.com
From: Prashant Kumar Mishra
Date: 2015-01-09 16:42
To: users@cloudstack.apache.org
Subject: Re: Can not add a new virtual instance by a template I am suspecting problem with the template ,check ssvm log can give you details info . Can you check if template got copied properly may be try to download it,check.Also make sure you are using service offering with local storage enabled Thanks prashant
On 1/9/15, 1:26 PM, "Wwei@landhightech.com" <Ww...@landhightech.com> wrote:
>Hi，
>We had an issue when we add a new virtual instance by template.we can
>not create the new instance.
>We use cloudstack 4.4.1 + Vmware ,advanced network ,local storage.
>We want to add a new virtual instance into a share network.
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>------------------------------------------
>2015-01-09 23:30:14,876 DEBUG [o.a.c.s.RemoteHostEndPoint]
>(Timer-11:ctx-a09c3aac) Sending command
>org.apache.cloudstack.storage.command.DownloadProgressCommand to host:
>3
>2015-01-09 23:30:14,878 DEBUG [c.c.a.t.Request] (Timer-11:ctx-a09c3aac)
>Seq 3-1751055830117010306: Sending { Cmd , MgmtId: 52230225403, via:
>3(s-1-VM), Ver: v1, Flags: 100011,
>[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId"
>:"b7835acd-50af-44e7-a91c-94b715722bfc","request":"GET_STATUS","hvm":fa
>lse ,"description":"CentOS 5.3(64-bit) no GUI
>(vSphere)","checksum":"f6f881b7f2292948d8494db837fe0f47","maxDownloadSi
>zeI
>nBytes":53687091200,"id":7,"resourceType":"TEMPLATE","installPath":"tem
>pla
>te/tmpl/1/7","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://19
>2.1
>68.10.2/secondary","_role":"Image"}},"url":"http://download.cloud.com/r
>ele
>ases/2.2.0/CentOS5.3-x86_64.ova","format":"OVA","accountId":1,"name":"c
>ent os53-x64","secUrl":"nfs://192.168.10.2/secondary","wait":0}}] }
>2015-01-09 23:30:14,923 DEBUG [c.c.a.t.Request]
>(AgentManager-Handler-11:null) Seq 3-1751055830117010306: Processing: {
>Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10,
>[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"b7835acd-50af-
>44e 7-a91c-94b715722bfc","downloadPct":0,"errorString":"
>","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStora
>ge/
>19e03beb-309a-3316-8e6d-5f25071372e5/template/tmpl/1/7/dnld504376175065
>878
>7860tmp_","installPath":"template/tmpl/1/7","templateSize":0,"templateP
>hyS
>icalSize":0,"checkSum":"f6f881b7f2292948d8494db837fe0f47","result":true
>,"d
>etails":" ","wait":0}}] }
>2015-01-09 23:30:15,780 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-23:ctx-6e8835bf) ===START=== 192.168.255.102 -- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&
>res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
>2015-01-09 23:30:15,841 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-23:ctx-6e8835bf ctx-35fa8112) ===END=== 192.168.255.102
>-- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&
>res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
>2015-01-09 23:30:16,170 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl]
>(Vm-Operations-Cleanup-1:ctx-86237200) Expunge completed work job-205
>2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request]
>(AgentManager-Handler-3:null) Seq 3-1751055830117010304: Processing: {
>Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10,
>[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false
>,"d etails":"Unable to copy template to primary storage due to
>exception:Exception: java.lang.Exception\nMessage: File upload task
>failed to complete due to: Error writing request body to
>server\n","wait":0}}] }
>2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>3-1751055830117010304: Received: { Ans: , MgmtId: 52230225403, via: 3,
>Ver: v1, Flags: 10, { CopyCmdAnswer } }
>2015-01-09 23:30:18,047 DEBUG [c.c.a.m.AgentManagerImpl]
>(AgentManager-Handler-2:null) SeqA 2-22712: Processing Seq 2-22712: {
>Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"
>_lo adInfo":"{\n \"connections\": []\n}","wait":0}}] }
>2015-01-09 23:30:18,116 DEBUG [c.c.a.m.AgentManagerImpl]
>(AgentManager-Handler-2:null) SeqA 2-22712: Sending Seq 2-22712: { Ans:
>,
>MgmtId: 52230225403, via: 2, Ver: v1, Flags: 100010,
>[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
>2015-01-09 23:30:18,150 INFO [o.a.c.s.v.VolumeServiceImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>releasing lock for VMTemplateStoragePool 19
>2015-01-09 23:30:18,151 WARN [c.c.u.d.Merovingian2]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Was
>unable to find lock for the key template_spool_ref19 and thread id
>1216625438
>2015-01-09 23:30:18,151 DEBUG [o.a.c.e.o.VolumeOrchestrator]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable
>to create Vol[32|vm=27|ROOT]:Unable to copy template to primary storage
>due to exception:Exception: java.lang.Exception
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>2015-01-09 23:30:18,151 INFO [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable
>to contact resource.
>com.cloud.exception.StorageUnavailableException: Resource
>[StoragePool:1] is unreachable: Unable to create
>Vol[32|vm=27|ROOT]:Unable to copy template to primary storage due to exception:Exception:
>java.lang.Exception
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>at
>org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateV
>olu
>me(VolumeOrchestrator.java:1205)
>at
>org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(V
>olu
>meOrchestrator.java:1257)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineM
>ana
>gerImpl.java:988)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineM
>ana
>gerImpl.java:5195)
>at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source) at
>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccesso
>rIm
>pl.java:43)
>at java.lang.reflect.Method.invoke(Method.java:606)
>at
>com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProx
>y.j
>ava:107)
>at
>com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineMa
>nag
>erImpl.java:5340)
>at
>com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInCo
>nte
>xt(AsyncJobManagerImpl.java:503)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Mana
>ged
>ContextRunnable.java:49)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call
>(De
>faultManagedContext.java:56)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWi
>thC
>ontext(DefaultManagedContext.java:103)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWit
>hCo
>ntext(DefaultManagedContext.java:53)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Manage
>dCo
>ntextRunnable.java:46)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(Asy
>ncJ
>obManagerImpl.java:460)
>at
>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1145)
>at
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.j
>ava
>:615)
>at java.lang.Thread.run(Thread.java:745)
>2015-01-09 23:30:18,190 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Cleaning up resources for the vm VM[User|i-2-27-VM] in Starting state
>2015-01-09 23:30:18,194 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Sending { Cmd , MgmtId: 52230225403, via:
>1(192.168.10.132), Ver: v1, Flags: 100011,
>[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence
>":f alse,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
>2015-01-09 23:30:18,195 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Executing: { Cmd , MgmtId: 52230225403, via:
>1(192.168.10.132), Ver: v1, Flags: 100011,
>[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence
>":f alse,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
>2015-01-09 23:30:18,195 DEBUG [c.c.a.m.DirectAgentAttache]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Executing
>request
>2015-01-09 23:30:18,196 INFO [c.c.h.v.r.VmwareResource]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) Executing resource
>StopCommand:
>{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"
>vmN
>ame":"i-2-27-VM","wait":0}
>2015-01-09 23:30:18,216 DEBUG [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) find VM i-2-27-VM on host
>2015-01-09 23:30:18,217 INFO [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM not found in
>host cache
>2015-01-09 23:30:18,217 DEBUG [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) load VM cache on host
>2015-01-09 23:30:18,248 INFO [c.c.h.v.r.VmwareResource]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM is no longer
>in vSphere
>2015-01-09 23:30:18,249 DEBUG [c.c.a.m.DirectAgentAttache]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Response
>Received:
>2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Processing: {
>Ans: , MgmtId: 52230225403, via: 1, Ver: v1, Flags: 10,
>[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM
>i-2-27-VM is no longer in vSphere","wait":0}}] }
>2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Received: { Ans: , MgmtId: 52230225403, via: 1,
>Ver: v1, Flags: 10, { StopAnswer } }
>2015-01-09 23:30:18,259 DEBUG [o.a.c.e.o.NetworkOrchestrator]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Changing active number of nics for network id=205 on -1
>2015-01-09 23:30:18,289 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Successfully released network resources for the vm VM[User|i-2-27-VM]
>2015-01-09 23:30:18,290 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Successfully cleanued up resources for the vm VM[User|i-2-27-VM] in
>Starting state
>2015-01-09 23:30:18,303 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Deploy
>avoids pods: [], clusters: [], hosts: [1]
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>DeploymentPlanner allocation algorithm:
>com.cloud.deploy.FirstFitPlanner@47130493
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Trying
>to allocate a host and storage pools from dc:1, pod:1,cluster:1,
>requested cpu: 1999, requested ram: 2147483648
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Is
>ROOT volume READY (pool already allocated)?: No
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>DeploymentPlan has host_id specified, choosing this host and making no
>checks on this host: 1
>2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) The
>specified host is in avoid set
>2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Cannnot deploy to specified host, returning.
>2015-01-09 23:30:18,404 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) 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
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Hosts's actual total CPU: 31984 and CPU after applying
>overprovisioning: 31984
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Hosts's actual total RAM: 137357598720 and RAM after applying overprovisioning:
>137357598720
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>release cpu from host: 1, old used: 13994,reserved: 1999, actual total:
>31984, total with overprovisioning: 31984; new used:
>11995,reserved:1999;
>movedfromreserved: false,moveToReserveredfalse
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>release mem from host: 1, old used: 14763950080,reserved: 2147483648, total:
>137357598720; new used: 12616466432,reserved:2147483648;
>movedfromreserved: false,moveToReserveredfalse
>2015-01-09 23:30:18,481 ERROR [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Invocation exception, caused by:
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2015-01-09 23:30:18,481 INFO [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Rethrow exception
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2015-01-09 23:30:18,482 DEBUG [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done with run of VM
>work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 206
>2015-01-09 23:30:18,482 ERROR [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Unable to complete
>AsyncJobVO {id:207, userId: 2, accountId: 2, instanceType: null,
>instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZ
>hdm
>9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzd
>DtM
>AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmF
>sTm
>FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwb
>GFu
>bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF
>2YS
>91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya
>5-Z
>tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB
>-AA
>N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltc
>GwA
>AAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmE
>ubG
>FuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhL
>nV0
>aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAA
>AAA
>x3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzS
>mt4 cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0,
>resultCode: 0,
>result: null, initMsid: 52230225403, completeMsid: null, lastUpdated:
>null, lastPolled: null, created: Fri Jan 09 23:30:09 CST 2015}, job
>origin:206
>com.cloud.exception.InsufficientServerCapacityException: Unable to
>create a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1 at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineM
>ana
>gerImpl.java:947)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineM
>ana
>gerImpl.java:5195)
>at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source) at
>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccesso
>rIm
>pl.java:43)
>at java.lang.reflect.Method.invoke(Method.java:606)
>at
>com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProx
>y.j
>ava:107)
>at
>com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineMa
>nag
>erImpl.java:5340)
>at
>com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInCo
>nte
>xt(AsyncJobManagerImpl.java:503)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Mana
>ged
>ContextRunnable.java:49)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call
>(De
>faultManagedContext.java:56)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWi
>thC
>ontext(DefaultManagedContext.java:103)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWit
>hCo
>ntext(DefaultManagedContext.java:53)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable.run(Manage
>dCo
>ntextRunnable.java:46)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(Asy
>ncJ
>obManagerImpl.java:460)
>at
>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1145)
>at
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.j
>ava
>:615)
>at java.lang.Thread.run(Thread.java:745)
>2015-01-09 23:30:18,485 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Complete async
>job-207, jobStatus: FAILED, resultCode: 0, result:
>rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmE
>ubG
>FuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3u
>MsD
>AARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJ
>Mam
>F2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZ
>UVs
>ZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4
>AB3
>QAUEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwb
>G95
>bWVudCBmb3IgVk1bVXNlcnxpLTItMjctVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2V
>FbG
>VtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVud
>GEJ
>xZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmF
>tZX
>EAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvY
>kRp
>c3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH
>3dA
>A_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNY
>W5h
>Z2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3E
>Afg
>ALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZ
>ENv
>bnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3E
>Afg
>ALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZ
>WZh
>dWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2F
>sbH
>NxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0Lmltc
>Gwu
>RGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA
>1cQ
>B-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvd
>WRz
>dGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABd
>zcQ
>B-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZ
>W50
>LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgA
>LAA
>ABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphd
>mFx
>AH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V
>0b3
>J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qY
>XZh
>LnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3N
>xAH
>4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhL
>nV0
>aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgA
>GeH
>IALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9
>x4C
>AAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUx
>pc3
>R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
>2015-01-09 23:30:18,525 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done executing
>com.cloud.vm.VmWorkStart for job-207
>2015-01-09 23:30:18,570 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Sync job-208
>execution on object VmWorkJobQueue.27
>2015-01-09 23:30:18,574 WARN [c.c.u.d.Merovingian2]
>(API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Was unable to
>find lock for the key vm_instance27 and thread id 1208656886
>2015-01-09 23:30:18,691 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Executing sync
>queue
>item: SyncQueueItemVO {id:93, queueId: 92, contentType: AsyncJob,
>contentId: 208, lastProcessMsid: 52230225403, lastprocessNumber: 2,
>lastProcessTime: Fri Jan 09 23:30:18 CST 2015, created: Fri Jan 09
>23:30:18 CST 2015}
>2015-01-09 23:30:18,693 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Schedule queued
>job-208
>2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Queue (queue id,
>sync type, sync id) - (92,VmWorkJobQueue, 27) is reaching concurrency
>limit 1
>2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) There is a pending
>process in sync queue(id: 92)
>2015-01-09 23:30:18,757 INFO [o.a.c.f.j.i.AsyncJobMonitor]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Remove job-207 from
>job monitoring
>2015-01-09 23:30:18,760 INFO [o.a.c.f.j.i.AsyncJobMonitor]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Add job-208 into
>job monitoring
>2015-01-09 23:30:18,760 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Executing
>AsyncJobVO {id:208, userId: 2, accountId: 2, instanceType: null,
>instanceId: null,
>cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZ
>hdm
>9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzd
>DtM
>AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmF
>sTm
>FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwb
>GFu
>bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF
>2YS
>91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya
>5-Z
>tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB
>-AA
>N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltc
>GwA
>AAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2F
>kRm
>FjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcc
>k8w QUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status:
>IN_PROGRESS,
>processStatus: 0, resultCode: 0, result: null, initMsid: 52230225403,
>completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri
>Jan
>09 23:30:18 CST 2015}
>2015-01-09 23:30:18,761 DEBUG [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Run VM work job:
>com.cloud.vm.VmWorkStart for VM 27, job origin: 206
>2015-01-09 23:30:18,763 DEBUG [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>Execute VM work job:
>com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADn
>Nhd
>mVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":27,"handlerName":"Vir
>tua
>lMachineManagerImpl"}
>2015-01-09 23:30:18,774 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) 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
>2015-01-09 23:30:18,774 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>Successfully transitioned to start state for VM[User|i-2-27-VM]
>reservation id = b7635084-3b16-421f-9049-60c455b23867
>2015-01-09 23:30:18,785 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-24:ctx-d4c2aaff) ===START=== 192.168.255.102 -- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&
>res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788677859
>2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Trying
>to deploy VM, vm has dcId: 1 and podId: 1
>2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy
>avoids pods: null, clusters: null, hosts: null
>2015-01-09 23:30:18,843 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy
>avoids pods: [], clusters: [], hosts: []
>2015-01-09 23:30:18,844 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>DeploymentPlanner allocation algorithm:
>com.cloud.deploy.FirstFitPlanner@47130493
>
>Thanks.
>
>
>
>Wwei@landhightech.com
Re: Re: Can not add a new virtual instance by a template
Posted by "Wwei@landhightech.com" <Ww...@landhightech.com>.
We can add virtual instances by iso and other templates which created by cloudstack.
We want to migrate VMware instances to cloudstack.We import ova from vcenter.And login in cloudstack,go to templates,click on register template.And then add a instance by the template .But we can not add a new virtual instance by the template.
Thank you very much.
Wwei@landhightech.com
From: Prashant Kumar Mishra
Date: 2015-01-09 16:42
To: users@cloudstack.apache.org
Subject: Re: Can not add a new virtual instance by a template
I am suspecting problem with the template ,check ssvm log can give you
details info . Can you check if template got copied properly may be try
to download it,check.Also make sure you are using service offering with
local storage enabled
Thanks
prashant
On 1/9/15, 1:26 PM, "Wwei@landhightech.com" <Ww...@landhightech.com> wrote:
>Hi，
>We had an issue when we add a new virtual instance by template.we can not
>create the new instance.
>We use cloudstack 4.4.1 + Vmware ,advanced network ,local storage.
>We want to add a new virtual instance into a share network.
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>------------------------------------------
>2015-01-09 23:30:14,876 DEBUG [o.a.c.s.RemoteHostEndPoint]
>(Timer-11:ctx-a09c3aac) Sending command
>org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 3
>2015-01-09 23:30:14,878 DEBUG [c.c.a.t.Request] (Timer-11:ctx-a09c3aac)
>Seq 3-1751055830117010306: Sending { Cmd , MgmtId: 52230225403, via:
>3(s-1-VM), Ver: v1, Flags: 100011,
>[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId"
>:"b7835acd-50af-44e7-a91c-94b715722bfc","request":"GET_STATUS","hvm":false
>,"description":"CentOS 5.3(64-bit) no GUI
>(vSphere)","checksum":"f6f881b7f2292948d8494db837fe0f47","maxDownloadSizeI
>nBytes":53687091200,"id":7,"resourceType":"TEMPLATE","installPath":"templa
>te/tmpl/1/7","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.1
>68.10.2/secondary","_role":"Image"}},"url":"http://download.cloud.com/rele
>ases/2.2.0/CentOS5.3-x86_64.ova","format":"OVA","accountId":1,"name":"cent
>os53-x64","secUrl":"nfs://192.168.10.2/secondary","wait":0}}] }
>2015-01-09 23:30:14,923 DEBUG [c.c.a.t.Request]
>(AgentManager-Handler-11:null) Seq 3-1751055830117010306: Processing: {
>Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10,
>[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"b7835acd-50af-44e
>7-a91c-94b715722bfc","downloadPct":0,"errorString":"
>","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStorage/
>19e03beb-309a-3316-8e6d-5f25071372e5/template/tmpl/1/7/dnld504376175065878
>7860tmp_","installPath":"template/tmpl/1/7","templateSize":0,"templatePhyS
>icalSize":0,"checkSum":"f6f881b7f2292948d8494db837fe0f47","result":true,"d
>etails":" ","wait":0}}] }
>2015-01-09 23:30:15,780 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-23:ctx-6e8835bf) ===START=== 192.168.255.102 -- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
>2015-01-09 23:30:15,841 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-23:ctx-6e8835bf ctx-35fa8112) ===END=== 192.168.255.102 --
>GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
>2015-01-09 23:30:16,170 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl]
>(Vm-Operations-Cleanup-1:ctx-86237200) Expunge completed work job-205
>2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request]
>(AgentManager-Handler-3:null) Seq 3-1751055830117010304: Processing: {
>Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10,
>[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"d
>etails":"Unable to copy template to primary storage due to
>exception:Exception: java.lang.Exception\nMessage: File upload task
>failed to complete due to: Error writing request body to
>server\n","wait":0}}] }
>2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>3-1751055830117010304: Received: { Ans: , MgmtId: 52230225403, via: 3,
>Ver: v1, Flags: 10, { CopyCmdAnswer } }
>2015-01-09 23:30:18,047 DEBUG [c.c.a.m.AgentManagerImpl]
>(AgentManager-Handler-2:null) SeqA 2-22712: Processing Seq 2-22712: { Cmd
>, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_lo
>adInfo":"{\n \"connections\": []\n}","wait":0}}] }
>2015-01-09 23:30:18,116 DEBUG [c.c.a.m.AgentManagerImpl]
>(AgentManager-Handler-2:null) SeqA 2-22712: Sending Seq 2-22712: { Ans: ,
>MgmtId: 52230225403, via: 2, Ver: v1, Flags: 100010,
>[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
>2015-01-09 23:30:18,150 INFO [o.a.c.s.v.VolumeServiceImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>releasing lock for VMTemplateStoragePool 19
>2015-01-09 23:30:18,151 WARN [c.c.u.d.Merovingian2]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Was
>unable to find lock for the key template_spool_ref19 and thread id
>1216625438
>2015-01-09 23:30:18,151 DEBUG [o.a.c.e.o.VolumeOrchestrator]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable
>to create Vol[32|vm=27|ROOT]:Unable to copy template to primary storage
>due to exception:Exception: java.lang.Exception
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>2015-01-09 23:30:18,151 INFO [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable
>to contact resource.
>com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1]
>is unreachable: Unable to create Vol[32|vm=27|ROOT]:Unable to copy
>template to primary storage due to exception:Exception:
>java.lang.Exception
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>at
>org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolu
>me(VolumeOrchestrator.java:1205)
>at
>org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(Volu
>meOrchestrator.java:1257)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:988)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:5195)
>at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source)
>at
>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm
>pl.java:43)
>at java.lang.reflect.Method.invoke(Method.java:606)
>at
>com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j
>ava:107)
>at
>com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag
>erImpl.java:5340)
>at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte
>xt(AsyncJobManagerImpl.java:503)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed
>ContextRunnable.java:49)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De
>faultManagedContext.java:56)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC
>ontext(DefaultManagedContext.java:103)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo
>ntext(DefaultManagedContext.java:53)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo
>ntextRunnable.java:46)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ
>obManagerImpl.java:460)
>at
>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1145)
>at
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>:615)
>at java.lang.Thread.run(Thread.java:745)
>2015-01-09 23:30:18,190 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Cleaning
>up resources for the vm VM[User|i-2-27-VM] in Starting state
>2015-01-09 23:30:18,194 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Sending { Cmd , MgmtId: 52230225403, via:
>1(192.168.10.132), Ver: v1, Flags: 100011,
>[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":f
>alse,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
>2015-01-09 23:30:18,195 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Executing: { Cmd , MgmtId: 52230225403, via:
>1(192.168.10.132), Ver: v1, Flags: 100011,
>[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":f
>alse,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
>2015-01-09 23:30:18,195 DEBUG [c.c.a.m.DirectAgentAttache]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Executing
>request
>2015-01-09 23:30:18,196 INFO [c.c.h.v.r.VmwareResource]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) Executing resource
>StopCommand:
>{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmN
>ame":"i-2-27-VM","wait":0}
>2015-01-09 23:30:18,216 DEBUG [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) find VM i-2-27-VM on host
>2015-01-09 23:30:18,217 INFO [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM not found in
>host cache
>2015-01-09 23:30:18,217 DEBUG [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) load VM cache on host
>2015-01-09 23:30:18,248 INFO [c.c.h.v.r.VmwareResource]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM is no longer
>in vSphere
>2015-01-09 23:30:18,249 DEBUG [c.c.a.m.DirectAgentAttache]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Response
>Received:
>2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Processing: {
>Ans: , MgmtId: 52230225403, via: 1, Ver: v1, Flags: 10,
>[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-27-VM
>is no longer in vSphere","wait":0}}] }
>2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Received: { Ans: , MgmtId: 52230225403, via: 1,
>Ver: v1, Flags: 10, { StopAnswer } }
>2015-01-09 23:30:18,259 DEBUG [o.a.c.e.o.NetworkOrchestrator]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Changing
>active number of nics for network id=205 on -1
>2015-01-09 23:30:18,289 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Successfully released network resources for the vm VM[User|i-2-27-VM]
>2015-01-09 23:30:18,290 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Successfully cleanued up resources for the vm VM[User|i-2-27-VM] in
>Starting state
>2015-01-09 23:30:18,303 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Deploy
>avoids pods: [], clusters: [], hosts: [1]
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>DeploymentPlanner allocation algorithm:
>com.cloud.deploy.FirstFitPlanner@47130493
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Trying
>to allocate a host and storage pools from dc:1, pod:1,cluster:1,
>requested cpu: 1999, requested ram: 2147483648
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Is ROOT
>volume READY (pool already allocated)?: No
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>DeploymentPlan has host_id specified, choosing this host and making no
>checks on this host: 1
>2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) The
>specified host is in avoid set
>2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Cannnot
>deploy to specified host, returning.
>2015-01-09 23:30:18,404 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) 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
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Hosts's
>actual total CPU: 31984 and CPU after applying overprovisioning: 31984
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Hosts's
>actual total RAM: 137357598720 and RAM after applying overprovisioning:
>137357598720
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) release
>cpu from host: 1, old used: 13994,reserved: 1999, actual total: 31984,
>total with overprovisioning: 31984; new used: 11995,reserved:1999;
>movedfromreserved: false,moveToReserveredfalse
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) release
>mem from host: 1, old used: 14763950080,reserved: 2147483648, total:
>137357598720; new used: 12616466432,reserved:2147483648;
>movedfromreserved: false,moveToReserveredfalse
>2015-01-09 23:30:18,481 ERROR [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Invocation exception, caused by:
>com.cloud.exception.InsufficientServerCapacityException: Unable to create
>a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2015-01-09 23:30:18,481 INFO [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Rethrow
>exception com.cloud.exception.InsufficientServerCapacityException: Unable
>to create a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2015-01-09 23:30:18,482 DEBUG [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done with run of VM
>work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 206
>2015-01-09 23:30:18,482 ERROR [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Unable to complete
>AsyncJobVO {id:207, userId: 2, accountId: 2, instanceType: null,
>instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm
>9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtM
>AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTm
>FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFu
>bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS
>91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-Z
>tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AA
>N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA
>AAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubG
>FuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0
>aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAA
>x3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4
>cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
>result: null, initMsid: 52230225403, completeMsid: null, lastUpdated:
>null, lastPolled: null, created: Fri Jan 09 23:30:09 CST 2015}, job
>origin:206
>com.cloud.exception.InsufficientServerCapacityException: Unable to create
>a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:947)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:5195)
>at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source)
>at
>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm
>pl.java:43)
>at java.lang.reflect.Method.invoke(Method.java:606)
>at
>com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j
>ava:107)
>at
>com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag
>erImpl.java:5340)
>at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte
>xt(AsyncJobManagerImpl.java:503)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed
>ContextRunnable.java:49)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De
>faultManagedContext.java:56)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC
>ontext(DefaultManagedContext.java:103)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo
>ntext(DefaultManagedContext.java:53)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo
>ntextRunnable.java:46)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ
>obManagerImpl.java:460)
>at
>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1145)
>at
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>:615)
>at java.lang.Thread.run(Thread.java:745)
>2015-01-09 23:30:18,485 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Complete async
>job-207, jobStatus: FAILED, resultCode: 0, result:
>rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubG
>FuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsD
>AARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMam
>F2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVs
>ZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3
>QAUEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95
>bWVudCBmb3IgVk1bVXNlcnxpLTItMjctVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbG
>VtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJ
>xZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZX
>EAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRp
>c3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dA
>A_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5h
>Z2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfg
>ALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENv
>bnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfg
>ALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZh
>dWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbH
>NxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwu
>RGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQ
>B-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRz
>dGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQ
>B-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50
>LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAA
>ABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFx
>AH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3
>J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZh
>LnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH
>4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0
>aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeH
>IALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4C
>AAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3
>R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
>2015-01-09 23:30:18,525 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done executing
>com.cloud.vm.VmWorkStart for job-207
>2015-01-09 23:30:18,570 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Sync job-208
>execution on object VmWorkJobQueue.27
>2015-01-09 23:30:18,574 WARN [c.c.u.d.Merovingian2]
>(API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Was unable to
>find lock for the key vm_instance27 and thread id 1208656886
>2015-01-09 23:30:18,691 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Executing sync queue
>item: SyncQueueItemVO {id:93, queueId: 92, contentType: AsyncJob,
>contentId: 208, lastProcessMsid: 52230225403, lastprocessNumber: 2,
>lastProcessTime: Fri Jan 09 23:30:18 CST 2015, created: Fri Jan 09
>23:30:18 CST 2015}
>2015-01-09 23:30:18,693 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Schedule queued
>job-208
>2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Queue (queue id, sync
>type, sync id) - (92,VmWorkJobQueue, 27) is reaching concurrency limit 1
>2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) There is a pending
>process in sync queue(id: 92)
>2015-01-09 23:30:18,757 INFO [o.a.c.f.j.i.AsyncJobMonitor]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Remove job-207 from
>job monitoring
>2015-01-09 23:30:18,760 INFO [o.a.c.f.j.i.AsyncJobMonitor]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Add job-208 into job
>monitoring
>2015-01-09 23:30:18,760 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Executing AsyncJobVO
>{id:208, userId: 2, accountId: 2, instanceType: null, instanceId: null,
>cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm
>9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtM
>AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTm
>FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFu
>bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS
>91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-Z
>tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AA
>N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA
>AAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRm
>FjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8w
>QUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS,
>processStatus: 0, resultCode: 0, result: null, initMsid: 52230225403,
>completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Jan
>09 23:30:18 CST 2015}
>2015-01-09 23:30:18,761 DEBUG [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Run VM work job:
>com.cloud.vm.VmWorkStart for VM 27, job origin: 206
>2015-01-09 23:30:18,763 DEBUG [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Execute
>VM work job:
>com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhd
>mVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":27,"handlerName":"Virtua
>lMachineManagerImpl"}
>2015-01-09 23:30:18,774 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) 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
>2015-01-09 23:30:18,774 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>Successfully transitioned to start state for VM[User|i-2-27-VM]
>reservation id = b7635084-3b16-421f-9049-60c455b23867
>2015-01-09 23:30:18,785 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-24:ctx-d4c2aaff) ===START=== 192.168.255.102 -- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788677859
>2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Trying
>to deploy VM, vm has dcId: 1 and podId: 1
>2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy
>avoids pods: null, clusters: null, hosts: null
>2015-01-09 23:30:18,843 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy
>avoids pods: [], clusters: [], hosts: []
>2015-01-09 23:30:18,844 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>DeploymentPlanner allocation algorithm:
>com.cloud.deploy.FirstFitPlanner@47130493
>
>Thanks.
>
>
>
>Wwei@landhightech.com
Re: Can not add a new virtual instance by a template
Posted by Prashant Kumar Mishra <pr...@citrix.com>.
I am suspecting problem with the template ,check ssvm log can give you
details info . Can you check if template got copied properly may be try
to download it,check.Also make sure you are using service offering with
local storage enabled
Thanks
prashant
On 1/9/15, 1:26 PM, "Wwei@landhightech.com" <Ww...@landhightech.com> wrote:
>Hi，
>We had an issue when we add a new virtual instance by template.we can not
>create the new instance.
>We use cloudstack 4.4.1 + Vmware ,advanced network ,local storage.
>We want to add a new virtual instance into a share network.
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>------------------------------------------
>2015-01-09 23:30:14,876 DEBUG [o.a.c.s.RemoteHostEndPoint]
>(Timer-11:ctx-a09c3aac) Sending command
>org.apache.cloudstack.storage.command.DownloadProgressCommand to host: 3
>2015-01-09 23:30:14,878 DEBUG [c.c.a.t.Request] (Timer-11:ctx-a09c3aac)
>Seq 3-1751055830117010306: Sending { Cmd , MgmtId: 52230225403, via:
>3(s-1-VM), Ver: v1, Flags: 100011,
>[{"org.apache.cloudstack.storage.command.DownloadProgressCommand":{"jobId"
>:"b7835acd-50af-44e7-a91c-94b715722bfc","request":"GET_STATUS","hvm":false
>,"description":"CentOS 5.3(64-bit) no GUI
>(vSphere)","checksum":"f6f881b7f2292948d8494db837fe0f47","maxDownloadSizeI
>nBytes":53687091200,"id":7,"resourceType":"TEMPLATE","installPath":"templa
>te/tmpl/1/7","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.1
>68.10.2/secondary","_role":"Image"}},"url":"http://download.cloud.com/rele
>ases/2.2.0/CentOS5.3-x86_64.ova","format":"OVA","accountId":1,"name":"cent
>os53-x64","secUrl":"nfs://192.168.10.2/secondary","wait":0}}] }
>2015-01-09 23:30:14,923 DEBUG [c.c.a.t.Request]
>(AgentManager-Handler-11:null) Seq 3-1751055830117010306: Processing: {
>Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10,
>[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"b7835acd-50af-44e
>7-a91c-94b715722bfc","downloadPct":0,"errorString":"
>","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStorage/
>19e03beb-309a-3316-8e6d-5f25071372e5/template/tmpl/1/7/dnld504376175065878
>7860tmp_","installPath":"template/tmpl/1/7","templateSize":0,"templatePhyS
>icalSize":0,"checkSum":"f6f881b7f2292948d8494db837fe0f47","result":true,"d
>etails":" ","wait":0}}] }
>2015-01-09 23:30:15,780 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-23:ctx-6e8835bf) ===START=== 192.168.255.102 -- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
>2015-01-09 23:30:15,841 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-23:ctx-6e8835bf ctx-35fa8112) ===END=== 192.168.255.102 --
>GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788674854
>2015-01-09 23:30:16,170 DEBUG [o.a.c.f.j.d.VmWorkJobDaoImpl]
>(Vm-Operations-Cleanup-1:ctx-86237200) Expunge completed work job-205
>2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request]
>(AgentManager-Handler-3:null) Seq 3-1751055830117010304: Processing: {
>Ans: , MgmtId: 52230225403, via: 3, Ver: v1, Flags: 10,
>[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"d
>etails":"Unable to copy template to primary storage due to
>exception:Exception: java.lang.Exception\nMessage: File upload task
>failed to complete due to: Error writing request body to
>server\n","wait":0}}] }
>2015-01-09 23:30:18,022 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>3-1751055830117010304: Received: { Ans: , MgmtId: 52230225403, via: 3,
>Ver: v1, Flags: 10, { CopyCmdAnswer } }
>2015-01-09 23:30:18,047 DEBUG [c.c.a.m.AgentManagerImpl]
>(AgentManager-Handler-2:null) SeqA 2-22712: Processing Seq 2-22712: { Cmd
>, MgmtId: -1, via: 2, Ver: v1, Flags: 11,
>[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_lo
>adInfo":"{\n \"connections\": []\n}","wait":0}}] }
>2015-01-09 23:30:18,116 DEBUG [c.c.a.m.AgentManagerImpl]
>(AgentManager-Handler-2:null) SeqA 2-22712: Sending Seq 2-22712: { Ans: ,
>MgmtId: 52230225403, via: 2, Ver: v1, Flags: 100010,
>[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
>2015-01-09 23:30:18,150 INFO [o.a.c.s.v.VolumeServiceImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>releasing lock for VMTemplateStoragePool 19
>2015-01-09 23:30:18,151 WARN [c.c.u.d.Merovingian2]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Was
>unable to find lock for the key template_spool_ref19 and thread id
>1216625438
>2015-01-09 23:30:18,151 DEBUG [o.a.c.e.o.VolumeOrchestrator]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable
>to create Vol[32|vm=27|ROOT]:Unable to copy template to primary storage
>due to exception:Exception: java.lang.Exception
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>2015-01-09 23:30:18,151 INFO [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Unable
>to contact resource.
>com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1]
>is unreachable: Unable to create Vol[32|vm=27|ROOT]:Unable to copy
>template to primary storage due to exception:Exception:
>java.lang.Exception
>Message: File upload task failed to complete due to: Error writing
>request body to server
>
>at
>org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.recreateVolu
>me(VolumeOrchestrator.java:1205)
>at
>org.apache.cloudstack.engine.orchestration.VolumeOrchestrator.prepare(Volu
>meOrchestrator.java:1257)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:988)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:5195)
>at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source)
>at
>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm
>pl.java:43)
>at java.lang.reflect.Method.invoke(Method.java:606)
>at
>com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j
>ava:107)
>at
>com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag
>erImpl.java:5340)
>at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte
>xt(AsyncJobManagerImpl.java:503)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed
>ContextRunnable.java:49)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De
>faultManagedContext.java:56)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC
>ontext(DefaultManagedContext.java:103)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo
>ntext(DefaultManagedContext.java:53)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo
>ntextRunnable.java:46)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ
>obManagerImpl.java:460)
>at
>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1145)
>at
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>:615)
>at java.lang.Thread.run(Thread.java:745)
>2015-01-09 23:30:18,190 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Cleaning
>up resources for the vm VM[User|i-2-27-VM] in Starting state
>2015-01-09 23:30:18,194 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Sending { Cmd , MgmtId: 52230225403, via:
>1(192.168.10.132), Ver: v1, Flags: 100011,
>[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":f
>alse,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
>2015-01-09 23:30:18,195 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Executing: { Cmd , MgmtId: 52230225403, via:
>1(192.168.10.132), Ver: v1, Flags: 100011,
>[{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":f
>alse,"checkBeforeCleanup":false,"vmName":"i-2-27-VM","wait":0}}] }
>2015-01-09 23:30:18,195 DEBUG [c.c.a.m.DirectAgentAttache]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Executing
>request
>2015-01-09 23:30:18,196 INFO [c.c.h.v.r.VmwareResource]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) Executing resource
>StopCommand:
>{"isProxy":false,"executeInSequence":false,"checkBeforeCleanup":false,"vmN
>ame":"i-2-27-VM","wait":0}
>2015-01-09 23:30:18,216 DEBUG [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) find VM i-2-27-VM on host
>2015-01-09 23:30:18,217 INFO [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM not found in
>host cache
>2015-01-09 23:30:18,217 DEBUG [c.c.h.v.m.HostMO]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) load VM cache on host
>2015-01-09 23:30:18,248 INFO [c.c.h.v.r.VmwareResource]
>(DirectAgent-180:ctx-c474087e 192.168.10.132) VM i-2-27-VM is no longer
>in vSphere
>2015-01-09 23:30:18,249 DEBUG [c.c.a.m.DirectAgentAttache]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Response
>Received:
>2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request]
>(DirectAgent-180:ctx-c474087e) Seq 1-5183080221150030303: Processing: {
>Ans: , MgmtId: 52230225403, via: 1, Ver: v1, Flags: 10,
>[{"com.cloud.agent.api.StopAnswer":{"result":true,"details":"VM i-2-27-VM
>is no longer in vSphere","wait":0}}] }
>2015-01-09 23:30:18,249 DEBUG [c.c.a.t.Request]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Seq
>1-5183080221150030303: Received: { Ans: , MgmtId: 52230225403, via: 1,
>Ver: v1, Flags: 10, { StopAnswer } }
>2015-01-09 23:30:18,259 DEBUG [o.a.c.e.o.NetworkOrchestrator]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Changing
>active number of nics for network id=205 on -1
>2015-01-09 23:30:18,289 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Successfully released network resources for the vm VM[User|i-2-27-VM]
>2015-01-09 23:30:18,290 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Successfully cleanued up resources for the vm VM[User|i-2-27-VM] in
>Starting state
>2015-01-09 23:30:18,303 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Deploy
>avoids pods: [], clusters: [], hosts: [1]
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>DeploymentPlanner allocation algorithm:
>com.cloud.deploy.FirstFitPlanner@47130493
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Trying
>to allocate a host and storage pools from dc:1, pod:1,cluster:1,
>requested cpu: 1999, requested ram: 2147483648
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Is ROOT
>volume READY (pool already allocated)?: No
>2015-01-09 23:30:18,305 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>DeploymentPlan has host_id specified, choosing this host and making no
>checks on this host: 1
>2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) The
>specified host is in avoid set
>2015-01-09 23:30:18,307 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Cannnot
>deploy to specified host, returning.
>2015-01-09 23:30:18,404 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) 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
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Hosts's
>actual total CPU: 31984 and CPU after applying overprovisioning: 31984
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Hosts's
>actual total RAM: 137357598720 and RAM after applying overprovisioning:
>137357598720
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) release
>cpu from host: 1, old used: 13994,reserved: 1999, actual total: 31984,
>total with overprovisioning: 31984; new used: 11995,reserved:1999;
>movedfromreserved: false,moveToReserveredfalse
>2015-01-09 23:30:18,413 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) release
>mem from host: 1, old used: 14763950080,reserved: 2147483648, total:
>137357598720; new used: 12616466432,reserved:2147483648;
>movedfromreserved: false,moveToReserveredfalse
>2015-01-09 23:30:18,481 ERROR [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b)
>Invocation exception, caused by:
>com.cloud.exception.InsufficientServerCapacityException: Unable to create
>a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2015-01-09 23:30:18,481 INFO [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207 ctx-be9a377b) Rethrow
>exception com.cloud.exception.InsufficientServerCapacityException: Unable
>to create a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>2015-01-09 23:30:18,482 DEBUG [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done with run of VM
>work job: com.cloud.vm.VmWorkStart for VM 27, job origin: 206
>2015-01-09 23:30:18,482 ERROR [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Unable to complete
>AsyncJobVO {id:207, userId: 2, accountId: 2, instanceType: null,
>instanceId: null, cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm
>9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtM
>AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTm
>FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFu
>bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS
>91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-Z
>tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AA
>N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA
>AAAAAAAAAXBzcgAOamF2YS5sYW5nLkxvbmc7i-SQzI8j3wIAAUoABXZhbHVleHIAEGphdmEubG
>FuZy5OdW1iZXKGrJUdC5TgiwIAAHhwAAAAAAAAAAFxAH4ACnBwcHEAfgAKcHNyABFqYXZhLnV0
>aWwuSGFzaE1hcAUH2sHDFmDRAwACRgAKbG9hZEZhY3RvckkACXRocmVzaG9sZHhwP0AAAAAAAA
>x3CAAAABAAAAABdAAKVm1QYXNzd29yZHQAHHJPMEFCWFFBRG5OaGRtVmtYM0JoYzNOM2IzSmt4
>cA, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0,
>result: null, initMsid: 52230225403, completeMsid: null, lastUpdated:
>null, lastPolled: null, created: Fri Jan 09 23:30:09 CST 2015}, job
>origin:206
>com.cloud.exception.InsufficientServerCapacityException: Unable to create
>a deployment for VM[User|i-2-27-VM]Scope=interface
>com.cloud.dc.DataCenter; id=1
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:947)
>at
>com.cloud.vm.VirtualMachineManagerImpl.orchestrateStart(VirtualMachineMana
>gerImpl.java:5195)
>at sun.reflect.GeneratedMethodAccessor465.invoke(Unknown Source)
>at
>sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorIm
>pl.java:43)
>at java.lang.reflect.Method.invoke(Method.java:606)
>at
>com.cloud.vm.VmWorkJobHandlerProxy.handleVmWorkJob(VmWorkJobHandlerProxy.j
>ava:107)
>at
>com.cloud.vm.VirtualMachineManagerImpl.handleVmWorkJob(VirtualMachineManag
>erImpl.java:5340)
>at com.cloud.vm.VmWorkJobDispatcher.runJob(VmWorkJobDispatcher.java:102)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.runInConte
>xt(AsyncJobManagerImpl.java:503)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(Managed
>ContextRunnable.java:49)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(De
>faultManagedContext.java:56)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithC
>ontext(DefaultManagedContext.java:103)
>at
>org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithCo
>ntext(DefaultManagedContext.java:53)
>at
>org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedCo
>ntextRunnable.java:46)
>at
>org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl$5.run(AsyncJ
>obManagerImpl.java:460)
>at
>java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
>at java.util.concurrent.FutureTask.run(FutureTask.java:262)
>at
>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:
>1145)
>at
>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java
>:615)
>at java.lang.Thread.run(Thread.java:745)
>2015-01-09 23:30:18,485 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Complete async
>job-207, jobStatus: FAILED, resultCode: 0, result:
>rO0ABXNyABpqYXZhLmxhbmcuUnVudGltZUV4Y2VwdGlvbp5fBkcKNIPlAgAAeHIAE2phdmEubG
>FuZy5FeGNlcHRpb27Q_R8-GjscxAIAAHhyABNqYXZhLmxhbmcuVGhyb3dhYmxl1cY1Jzl3uMsD
>AARMAAVjYXVzZXQAFUxqYXZhL2xhbmcvVGhyb3dhYmxlO0wADWRldGFpbE1lc3NhZ2V0ABJMam
>F2YS9sYW5nL1N0cmluZztbAApzdGFja1RyYWNldAAeW0xqYXZhL2xhbmcvU3RhY2tUcmFjZUVs
>ZW1lbnQ7TAAUc3VwcHJlc3NlZEV4Y2VwdGlvbnN0ABBMamF2YS91dGlsL0xpc3Q7eHBxAH4AB3
>QAUEpvYiBmYWlsZWQgZHVlIHRvIGV4Y2VwdGlvbiBVbmFibGUgdG8gY3JlYXRlIGEgZGVwbG95
>bWVudCBmb3IgVk1bVXNlcnxpLTItMjctVk1ddXIAHltMamF2YS5sYW5nLlN0YWNrVHJhY2VFbG
>VtZW50OwJGKjw8_SI5AgAAeHAAAAANc3IAG2phdmEubGFuZy5TdGFja1RyYWNlRWxlbWVudGEJ
>xZomNt2FAgAESQAKbGluZU51bWJlckwADmRlY2xhcmluZ0NsYXNzcQB-AARMAAhmaWxlTmFtZX
>EAfgAETAAKbWV0aG9kTmFtZXEAfgAEeHAAAABydAAgY29tLmNsb3VkLnZtLlZtV29ya0pvYkRp
>c3BhdGNoZXJ0ABhWbVdvcmtKb2JEaXNwYXRjaGVyLmphdmF0AAZydW5Kb2JzcQB-AAsAAAH3dA
>A_b3JnLmFwYWNoZS5jbG91ZHN0YWNrLmZyYW1ld29yay5qb2JzLmltcGwuQXN5bmNKb2JNYW5h
>Z2VySW1wbCQ1dAAYQXN5bmNKb2JNYW5hZ2VySW1wbC5qYXZhdAAMcnVuSW5Db250ZXh0c3EAfg
>ALAAAAMXQAPm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENv
>bnRleHRSdW5uYWJsZSQxdAAbTWFuYWdlZENvbnRleHRSdW5uYWJsZS5qYXZhdAADcnVuc3EAfg
>ALAAAAOHQAQm9yZy5hcGFjaGUuY2xvdWRzdGFjay5tYW5hZ2VkLmNvbnRleHQuaW1wbC5EZWZh
>dWx0TWFuYWdlZENvbnRleHQkMXQAGkRlZmF1bHRNYW5hZ2VkQ29udGV4dC5qYXZhdAAEY2FsbH
>NxAH4ACwAAAGd0AEBvcmcuYXBhY2hlLmNsb3Vkc3RhY2subWFuYWdlZC5jb250ZXh0LmltcGwu
>RGVmYXVsdE1hbmFnZWRDb250ZXh0cQB-ABp0AA9jYWxsV2l0aENvbnRleHRzcQB-AAsAAAA1cQ
>B-AB1xAH4AGnQADnJ1bldpdGhDb250ZXh0c3EAfgALAAAALnQAPG9yZy5hcGFjaGUuY2xvdWRz
>dGFjay5tYW5hZ2VkLmNvbnRleHQuTWFuYWdlZENvbnRleHRSdW5uYWJsZXEAfgAWcQB-ABdzcQ
>B-AAsAAAHMcQB-ABFxAH4AEnEAfgAXc3EAfgALAAAB13QALmphdmEudXRpbC5jb25jdXJyZW50
>LkV4ZWN1dG9ycyRSdW5uYWJsZUFkYXB0ZXJ0AA5FeGVjdXRvcnMuamF2YXEAfgAbc3EAfgALAA
>ABBnQAH2phdmEudXRpbC5jb25jdXJyZW50LkZ1dHVyZVRhc2t0AA9GdXR1cmVUYXNrLmphdmFx
>AH4AF3NxAH4ACwAABHl0ACdqYXZhLnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3
>J0ABdUaHJlYWRQb29sRXhlY3V0b3IuamF2YXQACXJ1bldvcmtlcnNxAH4ACwAAAmd0AC5qYXZh
>LnV0aWwuY29uY3VycmVudC5UaHJlYWRQb29sRXhlY3V0b3IkV29ya2VycQB-ACxxAH4AF3NxAH
>4ACwAAAul0ABBqYXZhLmxhbmcuVGhyZWFkdAALVGhyZWFkLmphdmFxAH4AF3NyACZqYXZhLnV0
>aWwuQ29sbGVjdGlvbnMkVW5tb2RpZmlhYmxlTGlzdPwPJTG17I4QAgABTAAEbGlzdHEAfgAGeH
>IALGphdmEudXRpbC5Db2xsZWN0aW9ucyRVbm1vZGlmaWFibGVDb2xsZWN0aW9uGUIAgMte9x4C
>AAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3
>R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4
>2015-01-09 23:30:18,525 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Done executing
>com.cloud.vm.VmWorkStart for job-207
>2015-01-09 23:30:18,570 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Sync job-208
>execution on object VmWorkJobQueue.27
>2015-01-09 23:30:18,574 WARN [c.c.u.d.Merovingian2]
>(API-Job-Executor-101:ctx-22f197b7 job-206 ctx-49df178b) Was unable to
>find lock for the key vm_instance27 and thread id 1208656886
>2015-01-09 23:30:18,691 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Executing sync queue
>item: SyncQueueItemVO {id:93, queueId: 92, contentType: AsyncJob,
>contentId: 208, lastProcessMsid: 52230225403, lastprocessNumber: 2,
>lastProcessTime: Fri Jan 09 23:30:18 CST 2015, created: Fri Jan 09
>23:30:18 CST 2015}
>2015-01-09 23:30:18,693 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Schedule queued
>job-208
>2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Queue (queue id, sync
>type, sync id) - (92,VmWorkJobQueue, 27) is reaching concurrency limit 1
>2015-01-09 23:30:18,756 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) There is a pending
>process in sync queue(id: 92)
>2015-01-09 23:30:18,757 INFO [o.a.c.f.j.i.AsyncJobMonitor]
>(Work-Job-Executor-92:ctx-cf7cb5f7 job-206/job-207) Remove job-207 from
>job monitoring
>2015-01-09 23:30:18,760 INFO [o.a.c.f.j.i.AsyncJobMonitor]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Add job-208 into job
>monitoring
>2015-01-09 23:30:18,760 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Executing AsyncJobVO
>{id:208, userId: 2, accountId: 2, instanceType: null, instanceId: null,
>cmd: com.cloud.vm.VmWorkStart, cmdInfo:
>rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm
>9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtM
>AAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTm
>FtZXQAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFu
>bmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS
>91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-Z
>tlbwJWdrAgAESgAJYWNjb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AA
>N4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAG3QAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwA
>AAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRm
>FjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAADHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8w
>QUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS,
>processStatus: 0, resultCode: 0, result: null, initMsid: 52230225403,
>completeMsid: null, lastUpdated: null, lastPolled: null, created: Fri Jan
>09 23:30:18 CST 2015}
>2015-01-09 23:30:18,761 DEBUG [c.c.v.VmWorkJobDispatcher]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208) Run VM work job:
>com.cloud.vm.VmWorkStart for VM 27, job origin: 206
>2015-01-09 23:30:18,763 DEBUG [c.c.v.VmWorkJobHandlerProxy]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Execute
>VM work job:
>com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhd
>mVkX3Bhc3N3b3Jk"},"userId":2,"accountId":2,"vmId":27,"handlerName":"Virtua
>lMachineManagerImpl"}
>2015-01-09 23:30:18,774 DEBUG [c.c.c.CapacityManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) 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
>2015-01-09 23:30:18,774 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>Successfully transitioned to start state for VM[User|i-2-27-VM]
>reservation id = b7635084-3b16-421f-9049-60c455b23867
>2015-01-09 23:30:18,785 DEBUG [c.c.a.ApiServlet]
>(catalina-exec-24:ctx-d4c2aaff) ===START=== 192.168.255.102 -- GET
>command=queryAsyncJobResult&jobId=dde8c83e-63fc-4b49-b70d-27b3faca7883&res
>ponse=json&sessionkey=SST2qsGww2SbQBYEsnO7%2BoMlQWU%3D&_=1420788677859
>2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Trying
>to deploy VM, vm has dcId: 1 and podId: 1
>2015-01-09 23:30:18,828 DEBUG [c.c.v.VirtualMachineManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy
>avoids pods: null, clusters: null, hosts: null
>2015-01-09 23:30:18,843 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb) Deploy
>avoids pods: [], clusters: [], hosts: []
>2015-01-09 23:30:18,844 DEBUG [c.c.d.DeploymentPlanningManagerImpl]
>(Work-Job-Executor-93:ctx-69a2c541 job-206/job-208 ctx-a48025cb)
>DeploymentPlanner allocation algorithm:
>com.cloud.deploy.FirstFitPlanner@47130493
>
>Thanks.
>
>
>
>Wwei@landhightech.com