[
https://issues.apache.org/jira/browse/CLOUDSTACK-2481?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Sanjeev N reopened CLOUDSTACK-2481:
-----------------------------------
Verified this bug on the latest ACS 4.2 build. I still see the issue.
Template creation failed with CloudRuntimeException: Failed to create
templatetimeout
Log snippet from management server log file:
===================================
2013-07-25 01:49:15,300 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
===START=== 10.146.0.20 -- GET
command=createTemplate&response=json&sessionkey=WZF71LaQge%2FCxbMvbNdG7KLOOkM%3D&snapshotid=0c8fccb2-8804-45ad-a245-00c4a0e117b0&name=CS-2481&displayText=CS-2481&osTypeId=c893a654-f367-11e2-97d7-06045a000066&isPublic=true&passwordEnabled=false&isdynamicallyscalable=false&_=1374731355190
2013-07-25 01:49:15,459 DEBUG [cloud.template.TemplateManagerImpl]
(catalina-exec-13:null) This template is getting created from other template,
setting source template Id to: 5
2013-07-25 01:49:15,523 DEBUG [cloud.async.AsyncJobManagerImpl]
(catalina-exec-13:null) submit async job-93 = [
a0ada67d-899c-4147-9adb-2d5a0fc15c91 ], details: AsyncJobVO {id:93, userId: 2,
accountId: 2, sessionKey: null, instanceType: Template, instanceId: 202, cmd:
org.apache.cloudstack.api.command.user.template.CreateTemplateCmd,
cmdOriginator: null, cmdInfo:
{"sessionkey":"WZF71LaQge/CxbMvbNdG7KLOOkM\u003d","cmdEventType":"TEMPLATE.CREATE","ctxUserId":"2","httpmethod":"GET","osTypeId":"c893a654-f367-11e2-97d7-06045a000066","isPublic":"true","isdynamicallyscalable":"false","response":"json","id":"202","displayText":"CS-2481","snapshotid":"0c8fccb2-8804-45ad-a245-00c4a0e117b0","passwordEnabled":"false","name":"CS-2481","_":"1374731355190","ctxAccountId":"2","ctxStartEventId":"366"},
cmdVersion: 0, callbackType: 0, callbackAddress: null, status: 0,
processStatus: 0, resultCode: 0, result: null, initMsid: 6615759585382,
completeMsid: null, lastUpdated: null, lastPolled: null, created: null}
2013-07-25 01:49:15,527 DEBUG [cloud.api.ApiServlet] (catalina-exec-13:null)
===END=== 10.146.0.20 -- GET
command=createTemplate&response=json&sessionkey=WZF71LaQge%2FCxbMvbNdG7KLOOkM%3D&snapshotid=0c8fccb2-8804-45ad-a245-00c4a0e117b0&name=CS-2481&displayText=CS-2481&osTypeId=c893a654-f367-11e2-97d7-06045a000066&isPublic=true&passwordEnabled=false&isdynamicallyscalable=false&_=1374731355190
2013-07-25 01:49:15,530 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-19:job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) Executing
org.apache.cloudstack.api.command.user.template.CreateTemplateCmd for job-93 =
[ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]
2013-07-25 01:49:15,580 DEBUG [storage.image.TemplateDataFactoryImpl]
(Job-Executor-19:job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) template
202 is already in store:1, type:Image
2013-07-25 01:49:15,596 DEBUG [storage.motion.AncientDataMotionStrategy]
(Job-Executor-19:job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) copyAsync
inspecting src type SNAPSHOT copyAsync inspecting dest type TEMPLATE
2013-07-25 01:49:15,663 DEBUG [agent.transport.Request] (Job-Executor-19:job-93
= [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) Seq 3-875365393: Sending { Cmd ,
MgmtId: 6615759585382, via: 3, Ver: v1, Flags: 100011,
[{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":"snapshots/2/24/53c10659-48cd-4c45-9da2-2b53bab80b3d","volume":{"uuid":"beb7a932-aa9c-45a4-ba62-ee54b284cf6d","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"c65a038a-750c-3b4f-bf26-7ce3b74e1c85","id":1,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/sanjeev/pri_xen_os","port":2049}},"name":"ROOT-14","size":21474836480,"path":"10eb79a0-3d16-49e6-84f3-92f5767a30bd","volumeId":24,"vmName":"i-2-14-VM","accountId":2,"format":"VHD","id":24},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"Image"}},"vmName":"i-2-14-VM","name":"storage-gc_ROOT-14_20130725054019","hypervisorType":"XenServer","id":22}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/202","uuid":"90bac93d-b873-4042-aa7d-f1adfbd71d36","id":202,"format":"RAW","accountId":2,"hvm":true,"displayText":"CS-2481","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"Image"}},"name":"246cb2165-0311-3110-bb89-b64e553bb510"}},"executeInSequence":false,"wait":10800}}]
}
2013-07-25 01:49:27,004 DEBUG [agent.transport.Request] (Job-Executor-19:job-93
= [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) Seq 3-875365393: Received: { Ans:
, MgmtId: 6615759585382, via: 3, Ver: v1, Flags: 10, { CopyCmdAnswer } }
2013-07-25 01:49:27,021 DEBUG [cloud.template.TemplateManagerImpl]
(Job-Executor-19:job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) Failed to
create templatetimeout
2013-07-25 01:49:27,041 ERROR [cloud.async.AsyncJobManagerImpl]
(Job-Executor-19:job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) Unexpected
exception while executing
org.apache.cloudstack.api.command.user.template.CreateTemplateCmd
com.cloud.utils.exception.CloudRuntimeException: Failed to create
templatetimeout
at
com.cloud.template.TemplateManagerImpl.createPrivateTemplate(TemplateManagerImpl.java:1369)
at
com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at
org.apache.cloudstack.api.command.user.template.CreateTemplateCmd.execute(CreateTemplateCmd.java:263)
at com.cloud.api.ApiDispatcher.dispatch(ApiDispatcher.java:158)
at
com.cloud.async.AsyncJobManagerImpl$1.run(AsyncJobManagerImpl.java:531)
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)
2013-07-25 01:49:27,049 DEBUG [cloud.async.AsyncJobManagerImpl]
(Job-Executor-19:job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ]) Complete
async job-93 = [ a0ada67d-899c-4147-9adb-2d5a0fc15c91 ], jobStatus: 2,
resultCode: 530, result: Error Code: 530 Error text: Failed to create
templatetimeout
I din't see any entries got created in vm_template or template_store_ref when
the template creation was in progress.
However I see the template file present in the backend in the
path(template/tmpl/2/202) specified in CopyCommand.
> Object_Store_Refactor - Templates - Not able to create a template from
> snapshot.
> --------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-2481
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-2481
> 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
> Assignee: edison su
> Priority: Critical
> Fix For: 4.2.0
>
>
> Steps to reproduce the problem:
> Deploy a VM.
> Take a snapshot of the root volume.
> Create a template from this snapshot.
> API fails with following error message:
> "DB Exception on: com.mysql.jdbc.JDBC4PreparedStatement@bb917d1: DELETE FROM
> vm_template WHERE vm_template.id= 203"
> Management server logs:
> 2013-05-14 09:32:33,964 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
> ===START=== 10.217.252.128 -- GET command=createTemplate&response=json
> &sessionkey=X%2FK09rgZ%2BYIUuGYkv7UGa0FoBEc%3D&snapshotid=d44ae73f-3cbd-49d3-8964-6c3325c24286&name=template1&displayText=template1&osTypeId=fce76ff
> 6-bc28-11e2-8a23-6a01c7e420f0&isPublic=true&passwordEnabled=false&_=1368552572710
> 2013-05-14 09:32:34,059 DEBUG [cloud.template.TemplateManagerImpl]
> (catalina-exec-3:null) This template is getting created from other template,
> sett
> ing source template Id to: 202
> 2013-05-14 09:32:34,118 DEBUG [cloud.async.AsyncJobManagerImpl]
> (catalina-exec-3:null) submit async job-18, details: AsyncJobVO {id:18,
> userId: 2, a
> ccountId: 2, sessionKey: null, instanceType: Template, instanceId: 203, cmd:
> org.apache.cloudstack.api.command.user.template.CreateTemplateCmd, cmdO
> riginator: null, cmdInfo:
> {"sessionkey":"X/K09rgZ+YIUuGYkv7UGa0FoBEc\u003d","ctxUserId":"2","httpmethod":"GET","osTypeId":"fce76ff6-bc28-11e2-8a23-6
> a01c7e420f0","isPublic":"true","response":"json","id":"203","displayText":"template1","snapshotid":"d44ae73f-3cbd-49d3-8964-6c3325c24286","passwordE
> nabled":"false","name":"template1","_":"1368552572710","ctxAccountId":"2","ctxStartEventId":"61"},
> 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 09:32:34,119 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-20:job-18) Executing
> org.apache.cloudstack.api.command.user.template.C
> reateTemplateCmd for job-18
> 2013-05-14 09:32:34,122 DEBUG [cloud.api.ApiServlet] (catalina-exec-3:null)
> ===END=== 10.217.252.128 -- GET command=createTemplate&response=json&s
> essionkey=X%2FK09rgZ%2BYIUuGYkv7UGa0FoBEc%3D&snapshotid=d44ae73f-3cbd-49d3-8964-6c3325c24286&name=template1&displayText=template1&osTypeId=fce76ff6-
> bc28-11e2-8a23-6a01c7e420f0&isPublic=true&passwordEnabled=false&_=1368552572710
> 2013-05-14 09:32:34,207 DEBUG [agent.transport.Request]
> (Job-Executor-20:job-18) Seq 3-178062289: Sending { Cmd , MgmtId:
> 206915885079359, via: 3,
> Ver: v1, Flags: 100111,
> [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.SnapshotObjectTO":{"path":
> "snapshots/2/1/29d8dd25-c221-4bbc-bc8b-b89d37e362de","volume":{"uuid":"5d0bd6d7-4ebe-4fb6-98ad-5df52850e739","volumeType":"ROOT","dataStore":{"org.a
> pache.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-5","size":8589934592,"path":"86b8d3a8-44c9-4bb0-b4fb-1ba
> 98d3e4f75","volumeId":5,"vmName":"i-2-5-VM","accountId":2,"id":5},"dataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.232/export/h
> ome/sangeetha/campo-systemp-1/secondary","_role":"Image"}},"vmName":"i-2-5-VM","name":"test-2_ROOT-5_20130514161859","hypervisorType":"XenServer","i
> d":1}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/203","uuid":"7f10ae7a-0e78-40ed-9b51-3a6a23c9dc66","id
> ":203,"format":"RAW","accountId":2,"hvm":true,"displayText":"template1","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.223.110.2
> 32/export/home/sangeetha/campo-systemp-1/secondary","_role":"Image"}},"name":"25860e266-0bd4-3eab-abe5-190cd2cafb8b"}},"wait":10800}}]
> }
> 2013-05-14 09:32:37,151 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
> ===START=== 10.217.252.128 -- GET command=queryAsyncJobResult&jobId=8
> 21ce4f1-c8a8-42ce-a095-70144886b536&response=json&sessionkey=X%2FK09rgZ%2BYIUuGYkv7UGa0FoBEc%3D&_=1368552575986
> 2013-05-14 09:32:37,203 DEBUG [cloud.api.ApiServlet] (catalina-exec-18:null)
> ===END=== 10.217.252.128 -- GET command=queryAsyncJobResult&jobId=821
> ce4f1-c8a8-42ce-a095-70144886b536&response=json&sessionkey=X%2FK09rgZ%2BYIUuGYkv7UGa0FoBEc%3D&_=1368552575986
> 2013-05-14 09:32:38,145 DEBUG [cloud.server.StatsCollector]
> (StatsCollector-1:null) VmStatsCollector is running...
> 2013-05-14 09:32:38,161 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-329:null) Seq 1-738331920: Executing request
> 2013-05-14 09:32:38,400 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-329:null) Vm cpu utilization 0.0010937499999999999
> 2013-05-14 09:32:38,400 DEBUG [xen.resource.CitrixResourceBase]
> (DirectAgent-329:null) Vm cpu utilization 0.00125
> 2013-05-14 09:32:38,400 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-329:null) Seq 1-738331920: Response Received:
> 2013-05-14 09:32:38,400 DEBUG [agent.transport.Request]
> (StatsCollector-1:null) Seq 1-738331920: Received: { Ans: , MgmtId:
> 206915885079359, via: 1
> , Ver: v1, Flags: 10, { GetVmStatsAnswer } }
> 2013-05-14 09:32:39,181 DEBUG [agent.manager.DirectAgentAttache]
> (DirectAgent-111:null) Ping from 1
> 2013-05-14 09:32:39,549 DEBUG [agent.transport.Request]
> (AgentManager-Handler-5:null) Seq 3-178062289: Processing: { Ans: , MgmtId:
> 206915885079359
> , via: 3, Ver: v1, Flags: 110,
> [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"result":false,"details":"java.io.FileNotFoundException:
> /mn
> t/SecStorage/6cbcf976-4416-3c80-8c9e-319590e1d160/template/tmpl/2/203/template.properties
> (No such file or directory)","wait":0}}] }
> 2013-05-14 09:32:39,549 DEBUG [agent.manager.AgentAttache]
> (AgentManager-Handler-5:null) Seq 3-178062289: No more commands found
> 2013-05-14 09:32:39,549 DEBUG [agent.transport.Request]
> (Job-Executor-20:job-18) Seq 3-178062289: Received: { Ans: , MgmtId:
> 206915885079359, via:
> 3, Ver: v1, Flags: 110, { CopyCmdAnswer } }
> 2013-05-14 09:32:39,609 DEBUG [cloud.template.TemplateManagerImpl]
> (Job-Executor-20:job-18) Failed to create
> templatejava.io.FileNotFoundException:
> /mnt/SecStorage/6cbcf976-4416-3c80-8c9e-319590e1d160/template/tmpl/2/203/template.properties
> (No such file or directory)
> 2013-05-14 09:32:39,615 DEBUG [db.Transaction.Transaction]
> (Job-Executor-20:job-18) Rolling back the transaction: Time = 4 Name =
> -AsyncJobManagerI
> mpl$1.run:401-Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334-FutureTask.run:166-ThreadPoolExecutor.runWorker:1110-ThreadPoolExecuto
> r$Worker.run:603-Thread.run:679; called by
> -Transaction.rollback:890-Transaction.removeUpTo:833-Transaction.close:657-TransactionContextBuilder.inte
> rceptException:63-ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept:133-TemplateManagerImpl.createPrivateTemplate:1424-ComponentIn
> stantiationPostProcessor$InterceptorDispatcher.intercept:125-CreateTemplateCmd.execute:258-ApiDispatcher.dispatch:155-AsyncJobManagerImpl$1.run:437-
> Executors$RunnableAdapter.call:471-FutureTask$Sync.innerRun:334
> 2013-05-14 09:32:39,636 ERROR [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-20:job-18) Unexpected exception while executing
> org.apache.cloudstack.
> api.command.user.template.CreateTemplateCmd
> com.cloud.utils.exception.CloudRuntimeException: DB Exception on:
> com.mysql.jdbc.JDBC4PreparedStatement@bb917d1: DELETE FROM vm_template WHERE
> vm_te
> mplate.id= 203
> at com.cloud.utils.db.GenericDaoBase.expunge(GenericDaoBase.java:1137)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12
> 5)
> at
> com.cloud.template.TemplateManagerImpl.createPrivateTemplate(TemplateManagerImpl.java:1424)
> at
> com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:12
> 5)
> 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 constrain
> t 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 09:32:39,637 DEBUG [cloud.async.AsyncJobManagerImpl]
> (Job-Executor-20:job-18) Complete async job-18, jobStatus: 2, resultCode:
> 530, resul
> t: Error Code: 530 Error text: DB Exception on:
> com.mysql.jdbc.JDBC4PreparedStatement@bb917d1: DELETE FROM vm_template WHERE
> vm_template.id= 203
--
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
