Hi all, I'm not sure if this has already been answered on here but I'm having issues with creating VMs on ACS 4.4.1. When I register a template it resgisters successfully, downloads and installs the template. However when I try to create an instance based on the template it fails. In the log, it shows it can't find the template in the secondary storage. When I look in the seondary storage location I find two VHDs with the same size but different names. The template.properties file shows the name of one of the VHDs with its unique name.
I'm not sure why it's creating two VHDs or why it is returing an error about not finding the VDI in the secondary storage location. I have cleaned out all the templates and re-registered them but still not show. I don't know where to look now. Any pointers will be much appreciated. ACS 4.4.1 release version download from http://cloudstack.apt-get.eu/rhel/4.4/. Using community version of Mysql Database server version 5.6.21-2, java and tomcat installed as dependencies when installing cloud-client. Below relevant snippets of logs a WFibGVDb2xsZWN0aW9uGUIAgMte9x4CAAFMAAFjdAAWTGphdmEvdXRpbC9Db2xsZWN0aW9uO3hwc3IAE2phdmEudXRpbC5BcnJheUxpc3R4gdIdmcdhnQMAAUkABHNpemV4cAAAAAB3BAAAAAB4cQB-ADh4 2014-11-13 10:34:25,520 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-5:ctx-51bf3172 job-271/job-272) Done executing com.cloud.vm.VmWorkStart for job-272 2014-11-13 10:34:25,583 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-5:ctx-51bf3172 job-271/job-272) Sync queue (194) is currently empty 2014-11-13 10:34:25,585 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-5:ctx-51bf3172 job-271/job-272) Remove job-272 from job monitoring 2014-11-13 10:34:25,612 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (API-Job-Executor-3:ctx-ae269a9e job-271 ctx-63ef8bc9) Sync job-273 execution on object VmWorkJobQueue.42 2014-11-13 10:34:25,624 WARN [c.c.u.d.Merovingian2] (API-Job-Executor-3:ctx-ae269a9e job-271 ctx-63ef8bc9) Was unable to find lock for the key vm_instance42 and thread id 1065301798 2014-11-13 10:34:27,354 DEBUG [c.c.s.StatsCollector] (StatsCollector-2:ctx-934c4816) StorageCollector is running... 2014-11-13 10:34:27,464 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-934c4816) Seq 3-5590374512450339104: Received: { Ans: , MgmtId: 28963322701010, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2014-11-13 10:34:27,492 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9b277599) Execute sync-queue item: SyncQueueItemVO {id:195, queueId: 194, contentType: AsyncJob, contentId: 273, lastProcessMsid: null, lastproc essNumber: null, lastProcessTime: null, created: Thu Nov 13 10:34:25 SAST 2014} 2014-11-13 10:34:27,500 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-9b277599) Schedule queued job-273 2014-11-13 10:34:27,515 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273) Add job-273 into job monitoring 2014-11-13 10:34:27,516 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273) Executing AsyncJobVO {id:273, userId: 2, accountId: 2, instanceType: null, instanceId: null, cmd: com.cloud.vm.VmWorkStart , cmdInfo: rO0ABXNyABhjb20uY2xvdWQudm0uVm1Xb3JrU3RhcnR9cMGsvxz73gIAC0oABGRjSWRMAAZhdm9pZHN0ADBMY29tL2Nsb3VkL2RlcGxveS9EZXBsb3ltZW50UGxhbm5lciRFeGNsdWRlTGlzdDtMAAljbHVzdGVySWR0ABBMamF2YS9sYW5nL0xvbmc7TAAGaG9zdElkcQB-AAJMAAtqb3VybmFsTmFtZX QAEkxqYXZhL2xhbmcvU3RyaW5nO0wAEXBoeXNpY2FsTmV0d29ya0lkcQB-AAJMAAdwbGFubmVycQB-AANMAAVwb2RJZHEAfgACTAAGcG9vbElkcQB-AAJMAAlyYXdQYXJhbXN0AA9MamF2YS91dGlsL01hcDtMAA1yZXNlcnZhdGlvbklkcQB-AAN4cgATY29tLmNsb3VkLnZtLlZtV29ya5-ZtlbwJWdrAgAESgAJYWN jb3VudElkSgAGdXNlcklkSgAEdm1JZEwAC2hhbmRsZXJOYW1lcQB-AAN4cAAAAAAAAAACAAAAAAAAAAIAAAAAAAAAKnQAGVZpcnR1YWxNYWNoaW5lTWFuYWdlckltcGwAAAAAAAAAAHBwcHBwcHBwc3IAEWphdmEudXRpbC5IYXNoTWFwBQfawcMWYNEDAAJGAApsb2FkRmFjdG9ySQAJdGhyZXNob2xkeHA_QAAAAAAA DHcIAAAAEAAAAAF0AApWbVBhc3N3b3JkdAAcck8wQUJYUUFEbk5oZG1Wa1gzQmhjM04zYjNKa3hw, cmdVersion: 0, status: IN_PROGRESS, processStatus: 0, resultCode: 0, result: null, initMsid: 28963322701010, completeMsid: null, lastUpdated: null, lastPolled: null, created: Thu Nov 13 10:34:25 SAST 2014} 2014-11-13 10:34:27,518 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273) Run VM work job: com.cloud.vm.VmWorkStart for VM 42, job origin: 271 2014-11-13 10:34:27,523 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Execute VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"rawParams":{"VmPassword":"rO0ABXQADnNhdmVkX3Bhc3N3b3Jk"}, "userId":2,"accountId":2,"vmId":42,"handlerName":"VirtualMachineManagerImpl"} 2014-11-13 10:34:27,555 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) VM state transitted from :Stopped to Starting with event: StartRequestedvm's original host id: null new host id: nu ll host id before state transition: null 2014-11-13 10:34:27,556 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Successfully transitioned to start state for VM[User|i-2-42-VM] reservation id = 9a9c4a17-494b-4d2c-8d59-5c92 aec584fb 2014-11-13 10:34:27,567 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Trying to deploy VM, vm has dcId: 1 and podId: 1 2014-11-13 10:34:27,567 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Deploy avoids pods: null, clusters: null, hosts: null 2014-11-13 10:34:27,581 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-934c4816) Seq 3-5590374512450339105: Received: { Ans: , MgmtId: 28963322701010, via: 3, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2014-11-13 10:34:27,600 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-154:ctx-367e44f0) Seq 1-5222486717889511733: Executing request 2014-11-13 10:34:27,635 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Deploy avoids pods: [], clusters: [], hosts: [] 2014-11-13 10:34:27,639 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) DeploymentPlanner allocation algorithm: com.cloud.deploy.FirstFitPlanner@5ce4f79f 2014-11-13 10:34:27,639 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Trying to allocate a host and storage pools from dc:1, pod:1,cluster:null, requested cpu: 1000, requested ram: 1073741824 2014-11-13 10:34:27,639 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Is ROOT volume READY (pool already allocated)?: No 2014-11-13 10:34:27,640 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Searching resources only under specified Pod: 1 2014-11-13 10:34:27,640 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Listing clusters in order of aggregate capacity, that have (atleast one host with) enough CPU and RAM capacity under th is Pod: 1 2014-11-13 10:34:27,652 DEBUG [c.c.d.FirstFitPlanner] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Removing from the clusterId list these clusters from avoid set: [] 2014-11-13 10:34:27,687 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking resources in Cluster: 1 under Pod: 1 2014-11-13 10:34:27,688 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Looking for hosts in dc: 1 pod:1 cluster:1 2014-11-13 10:34:27,700 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) FirstFitAllocator has 1 hosts to check for allocation: [Host[-1-Routing]] 2014-11-13 10:34:27,717 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Found 1 hosts for allocation after prioritization: [Host[-1-Routing]] 2014-11-13 10:34:27,717 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Looking for speed=1000Mhz, Ram=1024 2014-11-13 10:34:27,743 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Host: 1 has cpu capability (cpu:48, speed:2200) to support requested CPU: 1 and requested speed: 1000 2014-11-13 10:34:27,743 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Checking if host: 1 has enough capacity for requested CPU: 1000 and requested RAM: 1073741 824 , cpuOverprovisioningFactor: 1.0 2014-11-13 10:34:27,752 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Hosts's actual total CPU: 105600 and CPU after applying overprovisioning: 105600 2014-11-13 10:34:27,752 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Free CPU: 104100 , Requested CPU: 1000 2014-11-13 10:34:27,752 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Free RAM: 260241932288 , Requested RAM: 1073741824 2014-11-13 10:34:27,752 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Host has enough CPU and RAM available 2014-11-13 10:34:27,752 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) STATS: Can alloc CPU from host: 1, used: 1500, reserved: 0, actual total: 105600, total wi th overprovisioning: 105600; requested cpu:1000,alloc_from_last_host?:false ,considerReservedCapacity?: true 2014-11-13 10:34:27,753 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) STATS: Can alloc MEM from host: 1, used: 1744830464, reserved: 0, total: 261986762752; req uested mem: 1073741824,alloc_from_last_host?:false ,considerReservedCapacity?: true 2014-11-13 10:34:27,753 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Found a suitable host, adding to list: 1 2014-11-13 10:34:27,753 DEBUG [c.c.a.m.a.i.FirstFitAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7 FirstFitRoutingAllocator) Host Allocator returning 1 suitable hosts 2014-11-13 10:34:27,758 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking suitable pools for volume (Id, Type): (42,ROOT) 2014-11-13 10:34:27,758 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) We need to allocate new storagepool for this volume 2014-11-13 10:34:27,762 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Calling StoragePoolAllocators to find suitable pools 2014-11-13 10:34:27,763 DEBUG [o.a.c.s.a.LocalStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) LocalStoragePoolAllocator trying to find storage pool to fit the vm 2014-11-13 10:34:27,763 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) ClusterScopeStoragePoolAllocator looking for storage pool 2014-11-13 10:34:27,763 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Looking for pools in dc: 1 pod:1 cluster:1 2014-11-13 10:34:27,768 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Found pools matching tags: [Pool[1|PreSetup]] 2014-11-13 10:34:27,772 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Removing pool Pool[1|PreSetup] from avoid set, must have been inserted when searching for another disk's tag 2014-11-13 10:34:27,777 DEBUG [o.a.c.s.a.AbstractStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking if storage pool is suitable, name: null ,poolId: 1 2014-11-13 10:34:27,790 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking pool 1 for storage, totalSize: 2199010672640, usedBytes: 10552868864, usedPct: 0.004798916619777411, disabl e threshold: 0.85 2014-11-13 10:34:27,805 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Found storage pool afdbXSPrimaryStorage of type PreSetup 2014-11-13 10:34:27,805 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Total capacity of the pool afdbXSPrimaryStorage id: 1 is 2199010672640 2014-11-13 10:34:27,809 DEBUG [c.c.s.StorageManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking pool: 1 for volume allocation [Vol[42|vm=42|ROOT]], maxSize : 2199010672640, totalAllocatedSize : 786432000 0, askingSize : 53687091200, allocated disable threshold: 0.85 2014-11-13 10:34:27,809 DEBUG [o.a.c.s.a.ClusterScopeStoragePoolAllocator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) ClusterScopeStoragePoolAllocator returning 1 suitable storage pools 2014-11-13 10:34:27,809 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Trying to find a potenial host and associated storage pools from the suitable host/pool lists for this VM 2014-11-13 10:34:27,809 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking if host: 1 can access any suitable storage pool for volume: ROOT 2014-11-13 10:34:27,812 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Host: 1 can access pool: 1 2014-11-13 10:34:27,814 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Found a potential host id: 1 name: cloudsrv3.afdb.org and associated storage pools for this VM 2014-11-13 10:34:27,817 DEBUG [c.c.d.DeploymentPlanningManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Returning Deployment Destination: Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Type-->Poo l(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(42|ROOT-->Pool(1))] 2014-11-13 10:34:27,817 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Deployment found - P0=VM[User|i-2-42-VM], P0=Dest[Zone(Id)-Pod(Id)-Cluster(Id)-Host(Id)-Storage(Volume(Id|Ty pe-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(42|ROOT-->Pool(1))] 2014-11-13 10:34:27,841 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) VM state transitted from :Starting to Starting with event: OperationRetryvm's original host id: null new host id: 1 host id before state transition: null 2014-11-13 10:34:27,850 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-9997f10c) ===START=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=95c705dd-9676-44c4-89fa-ee1455bbaeec&response=json&sessionkey=s17pGimwklt%2BNd2WbB7C1bK onpo%3D&_=1415867666616 2014-11-13 10:34:27,872 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Hosts's actual total CPU: 105600 and CPU after applying overprovisioning: 105600 2014-11-13 10:34:27,872 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) We are allocating VM, increasing the used capacity of this host:1 2014-11-13 10:34:27,872 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Current Used CPU: 1500 , Free CPU:104100 ,Requested CPU: 1000 2014-11-13 10:34:27,872 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Current Used RAM: 1744830464 , Free RAM:260241932288 ,Requested RAM: 1073741824 2014-11-13 10:34:27,873 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) CPU STATS after allocation: for host: 1, old used: 1500, old reserved: 0, actual total: 105600, total with overprov isioning: 105600; new used:2500, reserved:0; requested cpu:1000,alloc_from_last:false 2014-11-13 10:34:27,873 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) RAM STATS after allocation: for host: 1, old used: 1744830464, old reserved: 0, total: 261986762752; new used: 2818 572288, reserved: 0; requested mem: 1073741824,alloc_from_last:false 2014-11-13 10:34:27,881 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) VM is being created in podId: 1 2014-11-13 10:34:27,914 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Network id=205 is already implemented 2014-11-13 10:34:27,921 DEBUG [c.c.a.ApiServlet] (catalina-exec-10:ctx-9997f10c ctx-725db863) ===END=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=95c705dd-9676-44c4-89fa-ee1455bbaeec&response=json&sessionkey=s17pGimwklt%2B Nd2WbB7C1bKonpo%3D&_=1415867666616 2014-11-13 10:34:27,948 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Service SecurityGroup is not supported in the network id=205 2014-11-13 10:34:27,960 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Changing active number of nics for network id=205 on 1 2014-11-13 10:34:27,983 DEBUG [o.a.c.e.o.NetworkOrchestrator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Asking VirtualRouter to prepare for Nic[153-42-null-192.168.52.84] 2014-11-13 10:34:28,022 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Lock is acquired for network id 205 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(I d)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(42|ROOT-->Pool(1))] 2014-11-13 10:34:28,032 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Lock is released for network id 205 as a part of router startup in Dest[Zone(Id)-Pod(Id)-Cluster(I d)-Host(Id)-Storage(Volume(Id|Type-->Pool(Id))] : Dest[Zone(1)-Pod(1)-Cluster(1)-Host(1)-Storage(Volume(42|ROOT-->Pool(1))] 2014-11-13 10:34:28,059 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Service SecurityGroup is not supported in the network id=205 2014-11-13 10:34:28,106 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Service SecurityGroup is not supported in the network id=205 2014-11-13 10:34:28,126 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Applying dhcp entry in network Ntwk[642b04c9-b875-45ba-a566-266b7a2302e1|Guest|7] 2014-11-13 10:34:28,197 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511734: Sending { Cmd , MgmtId: 28963322701010, via: 1( cloudsrv3.afdb.org), Ver: v1, Flags: 100011, [{"co m.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:6b:02:00:00:ba","vmIpAddress":"192.168.52.84","vmName":"TestApacheTomcat7-OOY","defaultRouter":"192.168.52.1","defaultDns":"192.168.52.10","duid":"00:03:00:01:06:6b:02:00:00:ba","i sDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.52.10","router.ip":"169.254.0.11"," router.name":"r-39-VM"},"wait":0}}] } 2014-11-13 10:34:28,198 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511734: Executing: { Cmd , MgmtId: 28963322701010, via: 1( cloudsrv3.afdb.org), Ver: v1, Flags: 100011, [{ "com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"06:6b:02:00:00:ba","vmIpAddress":"192.168.52.84","vmName":"TestApacheTomcat7-OOY","defaultRouter":"192.168.52.1","defaultDns":"192.168.52.10","duid":"00:03:00:01:06:6b:02:00:00:ba" ,"isDefault":true,"executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router.guest.ip":"192.168.52.10","router.ip":"169.254.0.11"," router.name":"r-39-VM"},"wait":0}}] } 2014-11-13 10:34:28,199 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-39:ctx-34b0dd21) Seq 1-5222486717889511734: Executing request 2014-11-13 10:34:28,200 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-39:ctx-34b0dd21) Executing command in VR: /opt/cloud/bin/router_proxy.sh edithosts.sh 169.254.0.11 -m 06:6b:02:00:00:ba -4 192.168.52.84 -h TestApacheTomcat7-OOY -d 192.168.52.1 -n 192.168.52.10 2014-11-13 10:34:28,563 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-154:ctx-367e44f0) Seq 1-5222486717889511733: Response Received: 2014-11-13 10:34:28,564 DEBUG [c.c.a.t.Request] (StatsCollector-2:ctx-934c4816) Seq 1-5222486717889511733: Received: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, { GetStorageStatsAnswer } } 2014-11-13 10:34:28,724 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 2-11211: Processing Seq 2-11211: { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxy VmId":2,"_loadInfo":"{\n \"connections\": []\n}","wait":0}}] } 2014-11-13 10:34:28,738 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) SeqA 2-11211: Sending Seq 2-11211: { Ans: , MgmtId: 28963322701010, via: 2, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"res ult":true,"wait":0}}] } 2014-11-13 10:34:29,606 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-39:ctx-34b0dd21) Seq 1-5222486717889511734: Response Received: 2014-11-13 10:34:29,609 DEBUG [c.c.a.t.Request] (DirectAgent-39:ctx-34b0dd21) Seq 1-5222486717889511734: Processing: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":"" ,"wait":0}}] } 2014-11-13 10:34:29,611 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511734: Received: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, { Answer } } 2014-11-13 10:34:29,639 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Service SecurityGroup is not supported in the network id=205 2014-11-13 10:34:29,659 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Applying userdata and password entry in network Ntwk[642b04c9-b875-45ba-a566-266b7a2302e1|Guest|7] 2014-11-13 10:34:29,731 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511735: Sending { Cmd , MgmtId: 28963322701010, via: 1( cloudsrv3.afdb.org), Ver: v1, Flags: 100011, [{"co m.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.52.84","vmName":"TestApacheTomcat7-OOY","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-39-VM","router.ip":"169.254.0.11", "router.guest.ip":"192.168.52.10"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.52.84","vmName":"TestApacheTomcat7-OOY","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","router. name":"r-39-VM","router.ip":"169.254.0.11","router.guest.ip":"192.168.52.10"},"wait":0}}] } 2014-11-13 10:34:29,733 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511735: Executing: { Cmd , MgmtId: 28963322701010, via: 1( cloudsrv3.afdb.org), Ver: v1, Flags: 100011, [{ "com.cloud.agent.api.routing.SavePasswordCommand":{,"vmIpAddress":"192.168.52.84","vmName":"TestApacheTomcat7-OOY","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced"," router.name":"r-39-VM","router.ip":"169.254.0.1 1","router.guest.ip":"192.168.52.10"},"wait":0}},{"com.cloud.agent.api.routing.VmDataCommand":{"vmIpAddress":"192.168.52.84","vmName":"TestApacheTomcat7-OOY","executeInSequence":false,"accessDetails":{"zone.network.type":"Advanced","rout er.name":"r-39-VM","router.ip":"169.254.0.11","router.guest.ip":"192.168.52.10"},"wait":0}}] } 2014-11-13 10:34:29,734 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-155:ctx-31b81a59) Seq 1-5222486717889511735: Executing request 2014-11-13 10:34:29,734 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-155:ctx-31b81a59) Executing command in VR: /opt/cloud/bin/router_proxy.sh savepassword.sh 169.254.0.11 -v 192.168.52.84 -p fnirq_cnffjbeq 2014-11-13 10:34:30,849 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-1d55d973) ===START=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=95c705dd-9676-44c4-89fa-ee1455bbaeec&response=json&sessionkey=s17pGimwklt%2BNd2WbB7C1bK onpo%3D&_=1415867669614 2014-11-13 10:34:30,915 DEBUG [c.c.a.ApiServlet] (catalina-exec-14:ctx-1d55d973 ctx-560a2a27) ===END=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=95c705dd-9676-44c4-89fa-ee1455bbaeec&response=json&sessionkey=s17pGimwklt%2B Nd2WbB7C1bKonpo%3D&_=1415867669614 2014-11-13 10:34:31,017 DEBUG [c.c.a.r.v.VirtualRoutingResource] (DirectAgent-155:ctx-31b81a59) JSON IS:{"192.168.52.84":[["userdata","user-data",null],["metadata","service-offering","Medium Instance"],["metadata","availability-zone","af dbXSZone"],["metadata","local-ipv4","192.168.52.84"],["metadata","local-hostname","TestApacheTomcat7-OOY"],["metadata","public-ipv4","192.168.52.84"],["metadata","public-hostname",null],["metadata","instance-id","26403c32-5f97-47c2-81d2- dc67587c8f5f"],["metadata","vm-id","26403c32-5f97-47c2-81d2-dc67587c8f5f"],["metadata","public-keys",null],["metadata","cloud-identifier","CloudStack-{0b22eaa1-218f-448c-9911-2fd89fe2a21d}"]]} 2014-11-13 10:34:31,018 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-155:ctx-31b81a59) Executing command in VR: /opt/cloud/bin/router_proxy.sh vmdata.py 169.254.0.11 -d eyIxOTIuMTY4LjUyLjg0IjpbWyJ1c2VyZGF0YSIsInVzZXItZGF0YSIsbnVsbF0 sWyJtZXRhZGF0YSIsInNlcnZpY2Utb2ZmZXJpbmciLCJNZWRpdW0gSW5zdGFuY2UiXSxbIm1ldGFkYXRhIiwiYXZhaWxhYmlsaXR5LXpvbmUiLCJhZmRiWFNab25lIl0sWyJtZXRhZGF0YSIsImxvY2FsLWlwdjQiLCIxOTIuMTY4LjUyLjg0Il0sWyJtZXRhZGF0YSIsImxvY2FsLWhvc3RuYW1lIiwiVGVzdEFwYWNo ZVRvbWNhdDctT09ZIl0sWyJtZXRhZGF0YSIsInB1YmxpYy1pcHY0IiwiMTkyLjE2OC41Mi44NCJdLFsibWV0YWRhdGEiLCJwdWJsaWMtaG9zdG5hbWUiLG51bGxdLFsibWV0YWRhdGEiLCJpbnN0YW5jZS1pZCIsIjI2NDAzYzMyLTVmOTctNDdjMi04MWQyLWRjNjc1ODdjOGY1ZiJdLFsibWV0YWRhdGEiLCJ2bS1pZ CIsIjI2NDAzYzMyLTVmOTctNDdjMi04MWQyLWRjNjc1ODdjOGY1ZiJdLFsibWV0YWRhdGEiLCJwdWJsaWMta2V5cyIsbnVsbF0sWyJtZXRhZGF0YSIsImNsb3VkLWlkZW50aWZpZXIiLCJDbG91ZFN0YWNrLXswYjIyZWFhMS0yMThmLTQ0OGMtOTkxMS0yZmQ4OWZlMmEyMWR9Il1dfQ== 2014-11-13 10:34:32,064 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-155:ctx-31b81a59) Seq 1-5222486717889511735: Response Received: 2014-11-13 10:34:32,065 DEBUG [c.c.a.t.Request] (DirectAgent-155:ctx-31b81a59) Seq 1-5222486717889511735: Processing: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.Answer":{"result":true,"details":" ","wait":0}},{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] } 2014-11-13 10:34:32,066 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511735: Received: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, { Answer, Answer } } 2014-11-13 10:34:32,075 DEBUG [c.c.n.NetworkModelImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Service SecurityGroup is not supported in the network id=205 2014-11-13 10:34:32,081 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Checking if we need to prepare 1 volumes for VM[User|i-2-42-VM] 2014-11-13 10:34:32,134 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) template 207 is already in store:3, type:Image 2014-11-13 10:34:32,150 DEBUG [o.a.c.s.d.PrimaryDataStoreImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Not found (templateId:207poolId:1) in template_spool_ref, persisting it 2014-11-13 10:34:32,169 DEBUG [o.a.c.s.i.TemplateDataFactoryImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) template 207 is already in store:1, type:Primary 2014-11-13 10:34:32,173 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Found template 207-2-3fe7a43d-b329-3b3a-b47a-974ba6e62ed9 in storage pool 1 with VMTemplateStoragePool id: 77 2014-11-13 10:34:32,177 DEBUG [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Acquire lock on VMTemplateStoragePool 77 with timeout 3600 seconds 2014-11-13 10:34:32,183 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) lock is acquired for VMTemplateStoragePool 77 2014-11-13 10:34:32,201 DEBUG [o.a.c.s.m.AncientDataMotionStrategy] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE 2014-11-13 10:34:32,238 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511736: Sending { Cmd , MgmtId: 28963322701010, via: 1( cloudsrv3.afdb.org), Ver: v1, Flags: 100011, [{"or g.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/207/5d42e263-94be-3755-b365-e43773543a43.vhd","origUrl":" http://dns2.afdb.org/ApacheTomcat7Server.vhd .gz","uuid":"9d975e9b-3d87-400e-a279-1f958a172bec","id":207,"format":"VHD","accountId":2,"checksum":"dde6f21d9588c108f61c4be5fac5c5ee","hvm":true,"displayText":"CentOS 6.5 with Apache Tomcat7","imageDataStore":{"com.cloud.agent.api.to.Nf sTO":{"_url":"nfs://cloudmgr2.afdb.org/export/secondary ","_role":"Image"}},"name":"207-2-3fe7a43d-b329-3b3a-b47a-974ba6e62ed9","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http: //dns2.afdb.org/ApacheTomcat7Server.vhd.gz","uuid":"9d975e9b-3d87-400e-a279-1f958a172bec","id":207,"format":"VHD","accountId":2,"checksum":"dde6f21d9588c108f61c4be5fac5c5ee","hvm":true,"displayText":"CentOS 6.5 with Apache Tomcat7","imag eDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DGC_SR10080","id":1,"poolType":"PreSetup","host":"localhost","path":"/DGC_SR10080","port":0,"url":"PreSetup://localhost/DGC_SR10080/?ROLE=Primary&STOREUUID=DGC_S R10080"}},"name":"207-2-3fe7a43d-b329-3b3a-b47a-974ba6e62ed9","hypervisorType":"XenServer"}},"executeInSequence":false,"options":{},"wait":10800}}] } 2014-11-13 10:34:32,240 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511736: Executing: { Cmd , MgmtId: 28963322701010, via: 1( cloudsrv3.afdb.org), Ver: v1, Flags: 100011, [{ "org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/207/5d42e263-94be-3755-b365-e43773543a43.vhd","origUrl":" http://dns2.afdb.org/ApacheTomcat7Server. vhd.gz","uuid":"9d975e9b-3d87-400e-a279-1f958a172bec","id":207,"format":"VHD","accountId":2,"checksum":"dde6f21d9588c108f61c4be5fac5c5ee","hvm":true,"displayText":"CentOS 6.5 with Apache Tomcat7","imageDataStore":{"com.cloud.agent.api.to .NfsTO":{"_url":"nfs://cloudmgr2.afdb.org/export/secondary ","_role":"Image"}},"name":"207-2-3fe7a43d-b329-3b3a-b47a-974ba6e62ed9","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"ht tp://dns2.afdb.org/ApacheTomcat7Server.vhd.gz","uuid":"9d975e9b-3d87-400e-a279-1f958a172bec","id":207,"format":"VHD","accountId":2,"checksum":"dde6f21d9588c108f61c4be5fac5c5ee","hvm":true,"displayText":"CentOS 6.5 with Apache Tomcat7","i mageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"DGC_SR10080","id":1,"poolType":"PreSetup","host":"localhost","path":"/DGC_SR10080","port":0,"url":"PreSetup://localhost/DGC_SR10080/?ROLE=Primary&STOREUUID=DG C_SR10080"}},"name":"207-2-3fe7a43d-b329-3b3a-b47a-974ba6e62ed9","hypervisorType":"XenServer"}},"executeInSequence":false,"options":{},"wait":10800}}] } 2014-11-13 10:34:32,241 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-78:ctx-b5d0bbfc) Seq 1-5222486717889511736: Executing request 2014-11-13 10:34:33,850 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-78a4e04c) ===START=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=95c705dd-9676-44c4-89fa-ee1455bbaeec&response=json&sessionkey=s17pGimwklt%2BNd2WbB7C1bK onpo%3D&_=1415867672616 2014-11-13 10:34:33,921 DEBUG [c.c.a.ApiServlet] (catalina-exec-12:ctx-78a4e04c ctx-65574617) ===END=== 10.29.128.147 -- GET command=queryAsyncJobResult&jobId=95c705dd-9676-44c4-89fa-ee1455bbaeec&response=json&sessionkey=s17pGimwklt%2B Nd2WbB7C1bKonpo%3D&_=1415867672616 2014-11-13 10:34:34,306 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-78:ctx-b5d0bbfc) Host 192.168.40.141 OpaqueRef:3f09bb03-fec6-f11e-36f5-f94998514b63: Removing SR 2014-11-13 10:34:34,346 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-78:ctx-b5d0bbfc) Host 192.168.40.141 OpaqueRef:03c6beb7-5892-5701-caae-3e7923bc9b97: Unplugging pbd 2014-11-13 10:34:34,797 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-78:ctx-b5d0bbfc) Host 192.168.40.141 OpaqueRef:3f09bb03-fec6-f11e-36f5-f94998514b63: Forgetting 2014-11-13 10:34:34,821 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-78:ctx-b5d0bbfc) Seq 1-5222486717889511736: Response Received: 2014-11-13 10:34:34,822 DEBUG [c.c.a.t.Request] (DirectAgent-78:ctx-b5d0bbfc) Seq 1-5222486717889511736: Processing: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{" result":false,"details":"Can't find template VDI under: cloudmgr2.afdb.org:/export/secondary/template/tmpl/2/207","wait":0}}] } 2014-11-13 10:34:34,822 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Seq 1-5222486717889511736: Received: { Ans: , MgmtId: 28963322701010, via: 1, Ver: v1, Flags: 10, { CopyCmdAnswer } } 2014-11-13 10:34:34,853 INFO [o.a.c.s.v.VolumeServiceImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) releasing lock for VMTemplateStoragePool 77 2014-11-13 10:34:34,855 WARN [c.c.u.d.Merovingian2] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Was unable to find lock for the key template_spool_ref77 and thread id 397636713 2014-11-13 10:34:34,859 DEBUG [o.a.c.e.o.VolumeOrchestrator] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Unable to create Vol[42|vm=42|ROOT]:Can't find template VDI under: cloudmgr2.afdb.org: /export/secondary/template /tmpl/2/207 2014-11-13 10:34:34,859 INFO [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-efe2f3bc job-271/job-273 ctx-c6fba5e7) Unable to contact resource. com.cloud.exception.StorageUnavailableException: Resource [StoragePool:1] is unreachable: Unable to create Vol[42|vm=42|ROOT]:Can't find template VDI under: cloudmgr2.afdb.org:/export/secondary/template/tmpl/2/207
