Did you verify the template you are launching the VM from is completely downloaded and it's integrity.
-----Original Message----- From: w...@landhightech.com [mailto:w...@landhightech.com] Sent: Friday, January 09, 2015 3:17 AM To: dev Subject: 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. w...@landhightech.com
