You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by Osay Osman Yuuni <oy...@gmail.com> on 2014/11/13 10:23:18 UTC
ACS 4.4.1 Creation of VM instance fails, Wierd template issues
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