Sangeetha Hariharan created CLOUDSTACK-2498:
-----------------------------------------------
Summary: Object_Store_Refactor - Templates - Not able to create a
template from root volume.
Key: CLOUDSTACK-2498
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2498
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Management Server
Affects Versions: 4.2.0
Environment: Build from object_store
Reporter: Sangeetha Hariharan
Fix For: 4.2.0
Object_Store_Refactor - Templates - Not able to create a template from root
volume.
Steps to reproduce the problem:
1. Deploy a Vm.
2. Stop the Vm.
3.Create template from the ROOT volume of the vm
Template creation fails.
Management server logs:
2013-05-14 16:58:59,710 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
===START=== 10.217.252.128 -- GET
command=createTemplate&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&volumeId=edbc637b-d4cc-46a6-b332-8278469258fc&name=TemplatefromVolume&displayText=TemplatefromVolume&osTypeId=fce76ff6-bc28-11e2-8a23-6a01c7e420f0&isPublic=true&passwordEnabled=false&isfeatured=true&_=1368579358661
2013-05-14 16:58:59,779 DEBUG [cloud.template.TemplateManagerImpl]
(catalina-exec-1:null) This template is getting created from other template,
setting source template Id to: 5
2013-05-14 16:58:59,827 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-1:null) submit async job-42, details: AsyncJobVO {id:42, userId:
2, accountId: 2, sessionKey: null, instanceType: Template, instanceId: 207,
cmd: org.apache.cloudstack.api.command.user.template.CreateTemplateCmd,
cmdOriginator: null, cmdInfo:
{"sessionkey":"qgY9GFmKNylox/ssl8BEOS8nFvs\u003d","volumeId":"edbc637b-d4cc-46a6-b332-8278469258fc","ctxUserId":"2","httpmethod":"GET","osTypeId":"fce76ff6-bc28-11e2-8a23-6a01c7e420f0","isPublic":"true","isfeatured":"true","response":"json","id":"207","displayText":"TemplatefromVolume","passwordEnabled":"false","name":"TemplatefromVolume","_":"1368579358661","ctxAccountId":"2","ctxStartEventId":"174"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 206915885079359,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-05-14 16:58:59,828 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-9:job-42) Executing
org.apache.cloudstack.api.command.user.template.CreateTemplateCmd for job-42
2013-05-14 16:58:59,830 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
===END=== 10.217.252.128 -- GET
command=createTemplate&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&volumeId=edbc637b-d4cc-46a6-b332-8278469258fc&name=TemplatefromVolume&displayText=TemplatefromVolume&osTypeId=fce76ff6-bc28-11e2-8a23-6a01c7e420f0&isPublic=true&passwordEnabled=false&isfeatured=true&_=1368579358661
2013-05-14 16:58:59,899 DEBUG [agent.transport.Request] (Job-Executor-9:job-42)
Seq 1-900399343: Sending { Cmd , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"edbc637b-d4cc-46a6-b332-8278469258fc","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e97b5727-d157-3dc1-b32c-065b99806623","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/sangeetha/campo-systemp-1/primary","port":2049}},"name":"ROOT-9","size":21474836480,"path":"49643ed0-d428-4ba3-bb84-a0e0f742dc39","volumeId":11,"vmName":"i-2-9-VM","accountId":2,"id":11}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/207","uuid":"83950a32-7938-4d9a-86d7-649d3eb1f0e0","id":207,"format":"RAW","accountId":2,"hvm":true,"displayText":"TemplatefromVolume","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232/export/home/sangeetha/campo-systemp-1/secondary","_role":"Image"}},"name":"244c28c5a-52b9-39a5-a945-3db48a5cb644"}},"wait":10800}}]
}
2013-05-14 16:58:59,900 DEBUG [agent.transport.Request] (Job-Executor-9:job-42)
Seq 1-900399343: Executing: { Cmd , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 100111,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"edbc637b-d4cc-46a6-b332-8278469258fc","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"e97b5727-d157-3dc1-b32c-065b99806623","id":1,"poolType":"NetworkFilesystem","host":"10.223.110.232","path":"/export/home/sangeetha/campo-systemp-1/primary","port":2049}},"name":"ROOT-9","size":21474836480,"path":"49643ed0-d428-4ba3-bb84-a0e0f742dc39","volumeId":11,"vmName":"i-2-9-VM","accountId":2,"id":11}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/207","uuid":"83950a32-7938-4d9a-86d7-649d3eb1f0e0","id":207,"format":"RAW","accountId":2,"hvm":true,"displayText":"TemplatefromVolume","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232/export/home/sangeetha/campo-systemp-1/secondary","_role":"Image"}},"name":"244c28c5a-52b9-39a5-a945-3db48a5cb644"}},"wait":10800}}]
}
2013-05-14 16:58:59,900 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-316:null) Seq 1-900399343: Executing request
2013-05-14 16:58:59,927 DEBUG [cloud.server.StatsCollector]
(StatsCollector-3:null) StorageCollector is running...
2013-05-14 16:59:01,001 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 5-1883045927: Received: { Ans: , MgmtId: 206915885079359, via: 5, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-05-14 16:59:01,008 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-21:null) Seq 1-900399344: Executing request
2013-05-14 16:59:01,370 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Creating a not shared SR for
nfs://10.223.110.232/export/home/sangeetha/campo-systemp-1/secondary/template/tmpl/2/207
2013-05-14 16:59:01,481 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-21:null) Seq 1-900399344: Response Received:
2013-05-14 16:59:01,481 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 1-900399344: Received: { Ans: , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-05-14 16:59:02,051 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Checking 33fef15a-475f-3a2f-a4f1-bf81ea5afd8a or SR
070bc979-8fd1-5772-cb01-7901abcaff69 on
XS[c5a85f60-1e15-40f5-9e7f-436bac0c8b63-10.223.56.194]
2013-05-14 16:59:02,066 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Host 10.223.56.194
OpaqueRef:6863588d-0107-fb13-0bbd-9188709eec8e: Created a SR; UUID is
070bc979-8fd1-5772-cb01-7901abcaff69 device config is
{serverpath=/export/home/sangeetha/campo-systemp-1/secondary/template/tmpl/2/207,
server=10.223.110.232}
2013-05-14 16:59:02,864 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579361900
2013-05-14 16:59:02,890 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579361900
2013-05-14 16:59:05,859 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579364901
2013-05-14 16:59:06,000 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579364901
2013-05-14 16:59:08,888 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579367905
2013-05-14 16:59:09,095 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-230:null) Seq 1-900399109: Response Received:
2013-05-14 16:59:09,096 DEBUG [agent.transport.Request] (DirectAgent-230:null)
Seq 1-900399109: Processing: { Ans: , MgmtId: 206915885079359, via: 1, Ver:
v1, Flags: 10,
[{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}]
}
2013-05-14 16:59:11,899 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579370933
2013-05-14 16:59:11,929 DEBUG [cloud.api.ApiServlet] (catalina-exec-7:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579370933
2013-05-14 16:59:14,886 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579373921
2013-05-14 16:59:14,912 DEBUG [cloud.api.ApiServlet] (catalina-exec-5:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579373921
2013-05-14 16:59:17,871 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579376905
2013-05-14 16:59:17,897 DEBUG [cloud.api.ApiServlet] (catalina-exec-9:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579376905
2013-05-14 16:59:20,899 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579379905
2013-05-14 16:59:20,931 DEBUG [cloud.api.ApiServlet] (catalina-exec-16:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579379905
2013-05-14 16:59:23,867 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579382907
2013-05-14 16:59:23,896 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579382907
2013-05-14 16:59:26,871 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579385907
2013-05-14 16:59:26,904 DEBUG [cloud.api.ApiServlet] (catalina-exec-24:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579385907
2013-05-14 16:59:27,917 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-05-14 16:59:28,036 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-05-14 16:59:29,622 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers to update status.
2013-05-14 16:59:29,623 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-14 16:59:29,649 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers to update status.
2013-05-14 16:59:29,651 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-14 16:59:29,877 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579388910
2013-05-14 16:59:29,904 DEBUG [cloud.api.ApiServlet] (catalina-exec-21:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579388910
2013-05-14 16:59:30,466 DEBUG [cloud.server.StatsCollector]
(StatsCollector-3:null) HostStatsCollector is running...
2013-05-14 16:59:30,477 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-340:null) Seq 1-900399345: Executing request
2013-05-14 16:59:30,822 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-340:null) Seq 1-900399345: Response Received:
2013-05-14 16:59:30,823 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 1-900399345: Received: { Ans: , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 10, { GetHostStatsAnswer } }
2013-05-14 16:59:31,011 DEBUG [cloud.server.StatsCollector]
(StatsCollector-3:null) VmStatsCollector is running...
2013-05-14 16:59:31,022 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-24:null) Seq 1-900399346: Executing request
2013-05-14 16:59:31,303 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-24:null) Vm cpu utilization 0.0010937499999999999
2013-05-14 16:59:31,303 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-24:null) Seq 1-900399346: Response Received:
2013-05-14 16:59:31,304 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 1-900399346: Received: { Ans: , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 10, { GetVmStatsAnswer } }
2013-05-14 16:59:31,396 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-6:null) Ping from 5
2013-05-14 16:59:32,897 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579391934
2013-05-14 16:59:32,928 DEBUG [cloud.api.ApiServlet] (catalina-exec-15:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-966
9-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579391934
2013-05-14 16:59:35,672 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-7:null) Ping from 4
2013-05-14 16:59:35,900 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579394933
2013-05-14 16:59:35,930 DEBUG [cloud.api.ApiServlet] (catalina-exec-8:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579394933
2013-05-14 16:59:38,873 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579397910
2013-05-14 16:59:38,905 DEBUG [cloud.api.ApiServlet] (catalina-exec-14:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579397910
2013-05-14 16:59:41,914 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579400953
2013-05-14 16:59:41,946 DEBUG [cloud.api.ApiServlet] (catalina-exec-10:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579400953
2013-05-14 16:59:44,901 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579403942
2013-05-14 16:59:44,920 DEBUG [cloud.api.ApiServlet] (catalina-exec-25:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579403942
2013-05-14 16:59:47,916 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579406955
2013-05-14 16:59:48,004 DEBUG [cloud.api.ApiServlet] (catalina-exec-12:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579406955
2013-05-14 16:59:50,910 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579409947
2013-05-14 16:59:50,938 DEBUG [cloud.api.ApiServlet] (catalina-exec-4:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579409947
2013-05-14 16:59:53,944 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579412946
2013-05-14 16:59:53,971 DEBUG [cloud.api.ApiServlet] (catalina-exec-19:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579412946
2013-05-14 16:59:56,909 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579415949
2013-05-14 16:59:56,938 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579415949
2013-05-14 16:59:57,917 DEBUG [storage.secondary.SecondaryStorageManagerImpl]
(secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-05-14 16:59:58,036 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl]
(consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-05-14 16:59:59,622 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers to update status.
2013-05-14 16:59:59,623 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-14 16:59:59,649 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 1 routers to update status.
2013-05-14 16:59:59,651 DEBUG
[network.router.VirtualNetworkApplianceManagerImpl]
(RouterStatusMonitor-1:null) Found 0 networks to update RvR status.
2013-05-14 16:59:59,912 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579418948
2013-05-14 16:59:59,944 DEBUG [cloud.api.ApiServlet] (catalina-exec-17:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579418948
2013-05-14 17:00:01,482 DEBUG [cloud.server.StatsCollector]
(StatsCollector-3:null) StorageCollector is running...
2013-05-14 17:00:02,339 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 5-1883045928: Received: { Ans: , MgmtId: 206915885079359, via: 5, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-05-14 17:00:02,346 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-343:null) Seq 1-900399347: Executing request
2013-05-14 17:00:02,915 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579421949
2013-05-14 17:00:02,945 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579421949
2013-05-14 17:00:03,608 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-343:null) Seq 1-900399347: Response Received:
2013-05-14 17:00:03,609 DEBUG [agent.transport.Request] (StatsCollector-3:null)
Seq 1-900399347: Received: { Ans: , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 1
0, { GetStorageStatsAnswer } }
2013-05-14 17:00:05,981 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579424949
2013-05-14 17:00:06,010 DEBUG [cloud.api.ApiServlet] (catalina-exec-6:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579424949
2013-05-14 17:00:07,475 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-163:null) Ping from 1
2013-05-14 17:00:08,860 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-217:null) Seq 1-900399109: Executing request
2013-05-14 17:00:08,912 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579427952
2013-05-14 17:00:08,935 DEBUG [cloud.api.ApiServlet] (catalina-exec-11:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579427952
2013-05-14 17:00:09,115 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-217:null) Seq 1-900399109: Response Received:
2013-05-14 17:00:09,116 DEBUG [agent.transport.Request] (DirectAgent-217:null)
Seq 1-900399109: Processing: { Ans: , MgmtId: 206915885079359, via: 1, Ver:
v1, Flags: 10,
[{"com.cloud.agent.api.ClusterSyncAnswer":{"_clusterId":1,"_newStates":{},"_isExecuted":false,"result":true,"wait":0}}]
}
2013-05-14 17:00:11,907 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579430949
2013-05-14 17:00:11,936 DEBUG [cloud.api.ApiServlet] (catalina-exec-2:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579430949
2013-05-14 17:00:14,910 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579433951
2013-05-14 17:00:14,937 DEBUG [cloud.api.ApiServlet] (catalina-exec-1:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579433951
2013-05-14 17:00:17,947 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579437018
2013-05-14 17:00:17,978 DEBUG [cloud.api.ApiServlet] (catalina-exec-23:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579437018
2013-05-14 17:00:20,942 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579439992
2013-05-14 17:00:20,970 DEBUG [cloud.api.ApiServlet] (catalina-exec-20:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579439992
2013-05-14 17:00:23,948 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===START=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579443017
2013-05-14 17:00:23,977 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
===END=== 10.217.252.128 -- GET
command=queryAsyncJobResult&jobId=8f36cb34-1920-4ba3-9669-9d09cbe27ce7&response=json&sessionkey=qgY9GFmKNylox%2Fssl8BEOS8nFvs%3D&_=1368579443017
2013-05-14 17:00:26,298 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Successfully created template.properties file on
secondary storage for 99d89e76-d94a-4cde-ae61-4509af3c0fcf.vhd
2013-05-14 17:00:26,298 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Host 10.223.56.194
OpaqueRef:6863588d-0107-fb13-0bbd-9188709eec8e: Removing SR
2013-05-14 17:00:26,329 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Host 10.223.56.194
OpaqueRef:ea6dfb0a-08c6-47ae-76fe-3dabd8080e22: Unplugging pbd
2013-05-14 17:00:26,841 DEBUG [xen.resource.CitrixResourceBase]
(DirectAgent-316:null) Host 10.223.56.194
OpaqueRef:6863588d-0107-fb13-0bbd-9188709eec8e: Forgetting
2013-05-14 17:00:26,867 DEBUG [agent.manager.DirectAgentAttache]
(DirectAgent-316:null) Seq 1-900399343: Response Received:
2013-05-14 17:00:26,868 DEBUG [agent.transport.Request] (DirectAgent-316:null)
Seq 1-900399343: Processing: { Ans: , MgmtId: 206915885079359, via: 1, Ver:
v1, Flags: 110,
[{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/207/99d89e76-d94a-4cde-ae61-4509af3c0fcf.vhd","id":0,"format":"VHD","accountId":0,"hvm":false}},"result":true,"wait":0}}]
}
2013-05-14 17:00:26,868 DEBUG [agent.manager.AgentAttache]
(DirectAgent-316:null) Seq 1-900399343: No more commands found
2013-05-14 17:00:26,868 DEBUG [agent.transport.Request] (Job-Executor-9:job-42)
Seq 1-900399343: Received: { Ans: , MgmtId: 206915885079359, via: 1, Ver: v1,
Flags: 110, { CopyCmdAnswer } }
2013-05-14 17:00:26,869 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-9:job-42) Failed to create templatejava.lang.NullPointerException
2013-05-14 17:00:26,873 DEBUG [db.Transaction.Transaction]
(Job-Executor-9:job-42) Rolling back the transaction: Time = 1 Name =
-AsyncJobManagerImpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecutor$Worker.run:603-Thread.run:679;
called by
-Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657-TransactionContextBuilder.interceptException:63-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:133-TemplateManagerImpl.createPrivateTemplate:1424-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:125-CreateTemplateCmd.execute:258-ApiDispatcher.dispatch:155-AsyncJobManagerImpl$1.run:437-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334
2013-05-14 17:00:26,899 ERROR [cloud.async.AsyncJobManagerImpl]
(Job-Executor-9:job-42) Unexpected exception while executing
org.apache.cloudstack.api.command.user.tem
plate.CreateTemplateCmd
com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@13b8f5c6: DELETE FROM vm_template WHERE
vm_template.id= 207
at com.cloud.utils.db.GenericDaoBase.expunge(GenericDaoBase.java:1137)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
com.cloud.template.TemplateManagerImpl.createPrivateTemplate(TemplateManagerImpl.java:1424)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.template.CreateTemplateCmd.execute(CreateTemplateCmd.java:258)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:155)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:437)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)
Caused by:
com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException:
Cannot delete or update a parent row: a foreign key constraint fails
(`cloud`.`template_store_ref`, CONSTRAINT `fk_template_store_ref__template_id`
FOREIGN KEY (`template_id`) REFERENCES `vm_template` (`id`))
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:532)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at com.mysql.jdbc.Util.getInstance(Util.java:386)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1040)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4074)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4006)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2468)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2629)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2719)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2155)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2450)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2371)
at
com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2355)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
at com.cloud.utils.db.GenericDaoBase.expunge(GenericDaoBase.java:1128)
... 20 more
2013-05-14 17:00:26,901 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-9:job-42) Complete async job-42, jobStatus: 2, resultCode: 530,
result: Error Code: 530 Error text: DB Exception on:
com.mysql.jdbc.JDBC4PreparedStatement@13b8f5c6: DELETE FROM vm_template WHERE
vm_template.id= 207
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
