You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Min Chen (JIRA)" <ji...@apache.org> on 2013/07/26 00:19:48 UTC
[jira] [Commented] (CLOUDSTACK-3805) [object_store_Refactor]
prepareTemplate cmd destroys the template from primary at the end of
prepareTemplate process
[ https://issues.apache.org/jira/browse/CLOUDSTACK-3805?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13720138#comment-13720138 ]
Min Chen commented on CLOUDSTACK-3805:
--------------------------------------
If you look at the management-server.log after this line:
2013-07-25 06:25:17,562 INFO [cloud.template.TemplateManagerImpl] (Template-Preloader-4:null) End of preloading template 204 into primary storage 2
You will see that StorageManager gc collection process kicked in:
2013-07-25 06:25:48,598 DEBUG [cloud.storage.StorageManagerImpl] (StorageManager-Scavenger-1:null) Storage pool garbage collector found 1 templates to clean up in storage
pool: pri_xen_os
2013-07-25 06:25:48,603 DEBUG [cloud.storage.StorageManagerImpl] (StorageManager-Scavenger-1:null) Storage pool garbage collector has marked templatePoolVO with ID: 11 fo
r garbage collection.
2013-07-25 06:25:48,613 DEBUG [cloud.storage.StorageManagerImpl] (StorageManager-Scavenger-1:null) Storage pool garbage collector found 1 templates to clean up in storage
pool: pri_xen_os2
2013-07-25 06:25:48,618 DEBUG [cloud.storage.StorageManagerImpl] (StorageManager-Scavenger-1:null) Storage pool garbage collector has marked templatePoolVO with ID: 12 for garbage collection.
It will find those two newly downloaded template entry from template_spool_ref (11 and 12), which are currently not in use, so, it will mark it for GC. Then the next storage GC run will delete these templates from primary storage, also remove it from template_spool_ref, which are seen from your log below:
2013-07-25 06:26:48,664 DEBUG [cloud.template.TemplateManagerImpl] (StorageManager-Scavenger-2:null) Evicting TmplPool[11-204-1-54a2b028-c97c-4790-bd8f-f91032dc64cd]
2013-07-25 06:26:48,670 DEBUG [agent.transport.Request] (StorageManager-Scavenger-2:null) Seq 1-513676347: Sending { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.DestroyCommand":{"volume":{"id":11,"mountPoint":"/export/home/sanjeev/pri_xen_os","path":"54a2b028-c97c-4790-bd8f-f91032dc64cd","size":0,"storagePoolType":"NetworkFilesystem","storagePoolUuid":"c65a038a-750c-3b4f-bf26-7ce3b74e1c85","deviceId":0},"wait":0}}] }
2013-07-25 06:26:48,671 DEBUG [agent.transport.Request] (StorageManager-Scavenger-2:null) Seq 1-513676347: Executing: { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.DestroyCommand":{"volume":{"id":11,"mountPoint":"/export/home/sanjeev/pri_xen_os","path":"54a2b028-c97c-4790-bd8f-f91032dc64cd","size":0,"storagePoolType":"NetworkFilesystem","storagePoolUuid":"c65a038a-750c-3b4f-bf26-7ce3b74e1c85","deviceId":0},"wait":0}}] }
That is why you saw that template is removed from primary storage. This storage GC process is controlled by the following two variables:
storage.template.cleanup.enabled
storage.cleanup.interval
you can either disable storage.template.cleanup.enabled to see if you will see if template is removed after prepareTemplate.
> [object_store_Refactor] prepareTemplate cmd destroys the template from primary at the end of prepareTemplate process
> --------------------------------------------------------------------------------------------------------------------
>
> Key: CLOUDSTACK-3805
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3805
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Components: Storage Controller, Template
> Affects Versions: 4.2.0
> Environment: Latest build from ACS 4.2 branch.
> Storage: NFS for both primary and secondary
> Cluster: Xen
> Reporter: Sanjeev N
> Assignee: Min Chen
> Priority: Critical
> Fix For: 4.2.0
>
> Attachments: management-server.rar, SMlog, xensource.rar
>
>
> [object_store_Refactor] prepareTemplate cmd destroys the template from primary at the end of prepareTemplate process.
> When prepare template command was executed, an entry was made in template_spool_ref table with state as "Creatin". After copying the template from secondary to primary template was destroyed(removed) from the primary and template entry was also removed from the template_spool_ref table.
> Steps to Reproduce:
> ===============
> 1.Bring up CS in advanced zone.
> 2.Create a xen cluster with two primary storages.
> 3.Register any cent os template to CS
> 4.When the template is in ready state, fire prepareTemplate API:
> http://10.147.59.126:8096/client/api?command=prepareTemplate&templateid=b6e88731-9a28-4856-b640-9740bd142c2e&zoneid=5c5c0b8a-9d5a-4b95-8f13-b31058ffdb37
> Observations:
> ===========
> After issueing the above API,two entries were created in template_spool_ref table with two pool ids (pood_id 1&2 , there are the two primary storages added in the cluster) with state="Creating":
> *************************** 5. row ***************************
> id: 11
> pool_id: 1
> template_id: 204
> created: 2013-07-25 10:03:54
> last_updated: NULL
> job_id: NULL
> download_pct: 0
> download_state: NOT_DOWNLOADED
> error_str: NULL
> local_path: NULL
> install_path: NULL
> template_size: 0
> marked_for_gc: 0
> state: Creating
> update_count: 1
> updated: 2013-07-25 10:03:54
> *************************** 6. row ***************************
> id: 12
> pool_id: 2
> template_id: 204
> created: 2013-07-25 10:03:54
> last_updated: NULL
> job_id: NULL
> download_pct: 0
> download_state: NOT_DOWNLOADED
> error_str: NULL
> local_path: NULL
> install_path: NULL
> template_size: 0
> marked_for_gc: 0
> state: Creating
> update_count: 1
> updated: 2013-07-25 10:03:54
> 6 rows in set (0.00 sec)
> ERROR:
> No query specified
> Even though there are two entries in the template_spool_ref table, template was copied to only one primary storage.
> When the State was in Creating state, I could see the template copy progress in primary storage(template size was increasing).
> After completing the template copy, immediately template was disappeared from the primary storage and entry from template_store_ref table was also deleted.
> I see vdi_destroy command executin in SMlog and xensource log file on xenserver.
> Here is the log snippet from management server log:
> ========================================
> 2013-07-25 06:03:53,996 INFO [cloud.template.TemplateManagerImpl] (Template-Preloader-4:null) Start to preload template 204 into primary storage 2
> 2013-07-25 06:03:54,025 DEBUG [cloud.template.TemplateManagerImpl] (Template-Preloader-3:null) Downloading template 204 to pool 1
> 2013-07-25 06:03:54,028 DEBUG [cloud.template.TemplateManagerImpl] (Template-Preloader-4:null) Downloading template 204 to pool 2
> 2013-07-25 06:03:54,033 DEBUG [storage.image.TemplateDataFactoryImpl] (Template-Preloader-3:null) template 204 is already in store:1, type:Image
> 2013-07-25 06:03:54,037 DEBUG [storage.image.TemplateDataFactoryImpl] (Template-Preloader-4:null) template 204 is already in store:1, type:Image
> 2013-07-25 06:03:54,039 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Template-Preloader-3:null) Not found (templateId: 204, poolId: 1) in template_spool_ref
> 2013-07-25 06:03:54,039 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Template-Preloader-3:null) Persisting (templateId: 204, poolId: 1) to template_spool_ref
> 2013-07-25 06:03:54,042 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Template-Preloader-4:null) Not found (templateId: 204, poolId: 2) in template_spool_ref
> 2013-07-25 06:03:54,042 DEBUG [storage.datastore.PrimaryDataStoreImpl] (Template-Preloader-4:null) Persisting (templateId: 204, poolId: 2) to template_spool_ref
> 2013-07-25 06:03:54,158 DEBUG [storage.image.TemplateDataFactoryImpl] (Template-Preloader-4:null) template 204 is already in store:2, type:Primary
> 2013-07-25 06:03:54,159 DEBUG [storage.image.TemplateDataFactoryImpl] (Template-Preloader-3:null) template 204 is already in store:1, type:Primary
> 2013-07-25 06:03:54,185 DEBUG [storage.motion.AncientDataMotionStrategy] (Template-Preloader-4:null) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
> 2013-07-25 06:03:54,191 DEBUG [storage.motion.AncientDataMotionStrategy] (Template-Preloader-3:null) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type TEMPLATE
> 2013-07-25 06:03:54,227 DEBUG [agent.transport.Request] (Template-Preloader-4:null) Seq 1-513676275: Sending { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/204/f6d220c1-efc4-3e14-90f5-92c77f111215.vhd","origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"Image"}},"name":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"05820c30-2a0e-33f7-b358-cc9c08864e10","id":2,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/sanjeev/pri_xen_os2","port":2049}},"name":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"executeInSequence":false,"wait":10800}}] }
> 2013-07-25 06:03:54,229 DEBUG [agent.transport.Request] (Template-Preloader-4:null) Seq 1-513676275: Executing: { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/204/f6d220c1-efc4-3e14-90f5-92c77f111215.vhd","origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"Image"}},"name":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"05820c30-2a0e-33f7-b358-cc9c08864e10","id":2,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/sanjeev/pri_xen_os2","port":2049}},"name":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"executeInSequence":false,"wait":10800}}] }
> 2013-07-25 06:03:54,230 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-393:null) Seq 1-513676275: Executing request
> 2013-07-25 06:03:54,242 DEBUG [agent.transport.Request] (Template-Preloader-3:null) Seq 1-513676276: Sending { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/204/f6d220c1-efc4-3e14-90f5-92c77f111215.vhd","origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"Image"}},"name":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"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":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"executeInSequence":false,"wait":10800}}] }
> 2013-07-25 06:03:54,245 DEBUG [agent.transport.Request] (Template-Preloader-3:null) Seq 1-513676276: Executing: { Cmd , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"template/tmpl/2/204/f6d220c1-efc4-3e14-90f5-92c77f111215.vhd","origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/sanjeev/sec_xen_os","_role":"Image"}},"name":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"destTO":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"origUrl":"http://10.147.28.7/templates/CentOS5.3/CentOS5.3HVM.vhd","uuid":"b6e88731-9a28-4856-b640-9740bd142c2e","id":204,"format":"VHD","accountId":2,"checksum":"34b5f768be3fbcbfd96436a093e432e5","hvm":true,"displayText":"cent53","imageDataStore":{"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":"204-2-d126fab8-efcd-30c6-9f47-5f9c4999a41f"}},"executeInSequence":false,"wait":10800}}] }
> 2013-07-25 06:25:17,421 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-393:null) Seq 1-513676275: Response Received:
> 2013-07-25 06:25:17,421 DEBUG [agent.transport.Request] (DirectAgent-393:null) Seq 1-513676275: Processing: { Ans: , MgmtId: 6615759585382, via: 1, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.storage.to.TemplateObjectTO":{"path":"c94e51ae-a5e0-4be0-b212-a700525ae9af","uuid":"c94e51ae-a5e0-4be0-b212-a700525ae9af","id":0,"format":"VHD","accountId":0,"hvm":false}},"result":true,"wait":0}}] }
> 2013-07-25 06:25:17,562 INFO [cloud.template.TemplateManagerImpl] (Template-Preloader-4:null) End of preloading template 204 into primary storage 2
> Log snippet from SMlog:
> ===================
> [root@Rack1Pod1Host14 ~]# zgrep -i 8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85 /var/log/SMlog*
> /var/log/SMlog:[26826] 2013-07-25 10:03:53.105185 ['/usr/sbin/td-util', 'create', 'vhd', '20480', '/var/run/sr-mount/d014bd96-e7d8-c7b8-de19-6a916bd2d308/8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85.vhd']
> /var/log/SMlog:[26826] 2013-07-25 10:03:53.372981 ['/usr/sbin/td-util', 'query', 'vhd', '-v', '/var/run/sr-mount/d014bd96-e7d8-c7b8-de19-6a916bd2d308/8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85.vhd']
> /var/log/SMlog:[26981] 2013-07-25 10:04:30.081270 VDIs changed on disk: ['e46a9134-de42-4e33-81f4-b5aa9190aa2c', '8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85']
> [root@Rack1Pod1Host14 ~]# zgrep -i 8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85 /var/log/SMlog*
> /var/log/SMlog:[26826] 2013-07-25 10:03:53.105185 ['/usr/sbin/td-util', 'create', 'vhd', '20480', '/var/run/sr-mount/d014bd96-e7d8-c7b8-de19-6a916bd2d308/8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85.vhd']
> /var/log/SMlog:[26826] 2013-07-25 10:03:53.372981 ['/usr/sbin/td-util', 'query', 'vhd', '-v', '/var/run/sr-mount/d014bd96-e7d8-c7b8-de19-6a916bd2d308/8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85.vhd']
> /var/log/SMlog:[26981] 2013-07-25 10:04:30.081270 VDIs changed on disk: ['e46a9134-de42-4e33-81f4-b5aa9190aa2c', '8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85']
> /var/log/SMlog:[2096] 2013-07-25 10:24:56.184399 vdi_delete {'sr_uuid': 'd014bd96-e7d8-c7b8-de19-6a916bd2d308', 'subtask_of': 'DummyRef:|04ddc78e-25a7-e50a-248b-1d81d9a40fa0|VDI.destroy', 'vdi_ref': 'OpaqueRef:59f2abcf-aa29-d3ab-c9d0-590ce3e749de', 'vdi_on_boot': 'persist', 'args': [], 'vdi_location': '8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85', 'host_ref': 'OpaqueRef:ed811e29-954f-d12e-291b-002885716796', 'session_ref': 'OpaqueRef:3ce255d4-a5ca-e3f7-e248-2b175fe85d7b', 'device_config': {'SRmaster': 'true', 'serverpath': '/export/home/sanjeev/pri_xen_os', 'server': '10.147.28.7'}, 'command': 'vdi_delete', 'vdi_allow_caching': 'false', 'sr_ref': 'OpaqueRef:2ba7d8d2-7ce5-0ba1-dab3-c3f7e70705d3', 'vdi_uuid': '8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85'}
> /var/log/SMlog:[2096] 2013-07-25 10:24:56.194862 ['/usr/bin/vhd-util', 'set', '--debug', '-n', '/var/run/sr-mount/d014bd96-e7d8-c7b8-de19-6a916bd2d308/8c632f6f-0d76-4ac4-a0d6-cc8433d8bd85.vhd', '-f', 'hidden', '-v', '1']
--
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