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, "w...@landhightech.com" <w...@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.
>
>
>
>w...@landhightech.com
