You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "venkata swamybabu budumuru (JIRA)" <ji...@apache.org> on 2013/07/26 09:39:48 UTC
[jira] [Created] (CLOUDSTACK-3845) [SystemVMTemplate] Unable to
deploy router VM due to "Template 1 has not been completely downloaded to
zone 2"
venkata swamybabu budumuru created CLOUDSTACK-3845:
------------------------------------------------------
Summary: [SystemVMTemplate] Unable to deploy router VM due to "Template 1 has not been completely downloaded to zone 2"
Key: CLOUDSTACK-3845
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-3845
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: Storage Controller
Affects Versions: 4.2.0
Environment: commit # ca474d0e09f772cb22abf2802a308a2da5351592
Reporter: venkata swamybabu budumuru
Priority: Critical
Fix For: 4.2.0
Steps to reproduce :
===============
NOTE : Not really sure whether it is always reproducible
(1) CloudStack latest build with zone1 (advanced) with KVM already existing in the setup.
(2) Created Zone2 (advanced) with XenServer
(3) By mistake, added a wrong secondary storage to Zone2 (when I say wrong, I mean it doesn't have template/tmpl/1/1 folder at all in this secondary storage) hence, removed the wrongly added one and added a right secondary store.
Note : I am including the above step for your reference though it is not really required to mention.
(4) Enabled zone2
Observations:
(i) It tried to bring up s-9-VM and v-8-VM. Mentioned below are the log snippets
(a.) It initiated a copy command from secondary to primary for template 1
36025 2013-07-26 10:14:42,891 DEBUG [cloud.storage.StorageManagerImpl] (consoleproxy-1:null) Checking pool 4 for storage, totalSize: 5902284816384, usedBytes: 3898521288704, usedPct: 0.6605105327825244, disable threshold: 0.85
36026 2013-07-26 10:14:42,906 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 5-498335767: Sending { Cmd , MgmtId: 7280707764394, via: 5, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to .TemplateObjectTO":{"path":"template/tmpl/1/1/","origUrl":"http://10.147.28.7/templates/acton/acton-systemvm-02062012.vhd.bz2","uuid":"4cdfb5c8-f4ef-11e2-a91c-069f2c0000aa","id":1,"format":"VHD","accountId":1,"checksum":"f613f38c96bf039f2e5cbf92fa8ad4f8","hvm":f alse,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/swamy/secondary.campo.xen.1","_role":"Image"}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.clou dstack.storage.to.TemplateObjectTO":{"origUrl":"http://10.147.28.7/templates/acton/acton-systemvm-02062012.vhd.bz2","uuid":"4cdfb5c8-f4ef-11e2-a91c-069f2c0000aa","id":1,"format":"VHD","accountId":1,"checksum":"f613f38c96bf039f2e5cbf92fa8ad4f8","hvm":false,"displ ayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"34044426-5416-39e0-b313-0bc2c0c216da","id":4,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/swamy/primary.campo.kvm .1.cluster","port":2049}},"name":"routing-1","hypervisorType":"XenServer"}},"executeInSequence":false,"wait":10800}}] }
36336 2013-07-26 10:16:54,438 DEBUG [agent.transport.Request] (DirectAgent-15:null) Seq 5-498335767: Processing: { Ans: , MgmtId: 7280707764394, via: 5, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.sto rage.to.TemplateObjectTO":{"path":"60158049-e78a-467f-8ea9-d2e64601b949","uuid":"60158049-e78a-467f-8ea9-d2e64601b949","id":0,"format":"VHD","accountId":0,"hvm":false}},"result":true,"wait":0}}] }
36337 2013-07-26 10:16:54,438 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 5-498335767: Received: { Ans: , MgmtId: 7280707764394, via: 5, Ver: v1, Flags: 10, { CopyCmdAnswer } }
(b.) one of the snippet from mgmt server log that says that it tried to create volumes for both s-9-VM and v-8-VM
36338 2013-07-26 10:16:54,489 DEBUG [storage.motion.AncientDataMotionStrategy] (secstorage-1:null) copyAsync inspecting src type TEMPLATE copyAsync inspecting dest type VOLUME
36339 2013-07-26 10:16:54,541 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 5-498335773: Sending { Cmd , MgmtId: 7280707764394, via: 5, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage.to .TemplateObjectTO":{"path":"60158049-e78a-467f-8ea9-d2e64601b949","origUrl":"http://10.147.28.7/templates/acton/acton-systemvm-02062012.vhd.bz2","uuid":"4cdfb5c8-f4ef-11e2-a91c-069f2c0000aa","id":1,"format":"VHD","accountId":1,"checksum":"f613f38c96bf039f2e5cbf9 2fa8ad4f8","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"34044426-5416-39e0-b313-0bc2c0c216da","id":4,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export /home/swamy/primary.campo.kvm.1.cluster","port":2049}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"9e8b2e87-9ec3-4bf9-a3f9-b52f9d5887f9","volumeType":"ROOT","dataStore":{"org.apache.cloud stack.storage.to.PrimaryDataStoreTO":{"uuid":"34044426-5416-39e0-b313-0bc2c0c216da","id":4,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/swamy/primary.campo.kvm.1.cluster","port":2049}},"name":"ROOT-9","size":0,"volumeId":11,"vmName":" s-9-VM","accountId":1,"format":"VHD","id":11,"hypervisorType":"None"}},"executeInSequence":false,"wait":0}}] }
36340 2013-07-26 10:16:54,544 DEBUG [agent.transport.Request] (secstorage-1:null) Seq 5-498335773: Executing: { Cmd , MgmtId: 7280707764394, via: 5, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.CopyCommand":{"srcTO":{"org.apache.cloudstack.storage .to.TemplateObjectTO":{"path":"60158049-e78a-467f-8ea9-d2e64601b949","origUrl":"http://10.147.28.7/templates/acton/acton-systemvm-02062012.vhd.bz2","uuid":"4cdfb5c8-f4ef-11e2-a91c-069f2c0000aa","id":1,"format":"VHD","accountId":1,"checksum":"f613f38c96bf039f2e5c bf92fa8ad4f8","hvm":false,"displayText":"SystemVM Template (XenServer)","imageDataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"34044426-5416-39e0-b313-0bc2c0c216da","id":4,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/exp ort/home/swamy/primary.campo.kvm.1.cluster","port":2049}},"name":"routing-1","hypervisorType":"XenServer"}},"destTO":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"9e8b2e87-9ec3-4bf9-a3f9-b52f9d5887f9","volumeType":"ROOT","dataStore":{"org.apache.cl oudstack.storage.to.PrimaryDataStoreTO":{"uuid":"34044426-5416-39e0-b313-0bc2c0c216da","id":4,"poolType":"NetworkFilesystem","host":"10.147.28.7","path":"/export/home/swamy/primary.campo.kvm.1.cluster","port":2049}},"name":"ROOT-9","size":0,"volumeId":11,"vmName ":"s-9-VM","accountId":1,"format":"VHD","id":11,"hypervisorType":"None"}},"executeInSequence":false,"wait":0}}] }
36355 2013-07-26 10:16:55,403 DEBUG [xen.resource.XenServerStorageProcessor] (DirectAgent-20:null) Succesfully created VDI: Uuid = b8dfbcbb-46c9-4d12-a738-7e7e539ff418
36356 2013-07-26 10:16:55,412 DEBUG [agent.manager.DirectAgentAttache] (DirectAgent-20:null) Seq 5-498335773: Response Received:
36357 2013-07-26 10:16:55,414 DEBUG [agent.transport.Request] (DirectAgent-20:null) Seq 5-498335773: Processing: { Ans: , MgmtId: 7280707764394, via: 5, Ver: v1, Flags: 10, [{"org.apache.cloudstack.storage.command.CopyCmdAnswer":{"newData":{"org.apache.cloudstack.sto rage.to.VolumeObjectTO":{"name":"ROOT-9","size":2097152000,"path":"b8dfbcbb-46c9-4d12-a738-7e7e539ff418","accountId":0,"id":0}},"result":true,"wait":0}}] }
****** (c.) Once the SSVM is up, it initiated template sync. mentioned below is the snippet for the same
36969 2013-07-26 10:19:17,670 DEBUG [agent.transport.Request] (AgentConnectTaskPool-5:null) Seq 6-1226899461: Received: { Ans: , MgmtId: 7280707764394, via: 6, Ver: v1, Flags: 110, { ListTemplateAnswer } }
36970 2013-07-26 10:19:17,698 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Template Sync did not find routing-1 on image store 3, may request download based on available hypervisor types
36971 2013-07-26 10:19:17,698 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Removing leftover template routing-1 entry from template store table
36972 2013-07-26 10:19:17,707 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Template Sync did not find routing-3 on image store 3, may request download based on available hypervisor types
36973 2013-07-26 10:19:17,707 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Removing leftover template routing-3 entry from template store table
36974 2013-07-26 10:19:17,727 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Template Sync did not find routing-8 on image store 3, may request download based on available hypervisor types
36975 2013-07-26 10:19:17,727 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Removing leftover template routing-8 entry from template store table
36976 2013-07-26 10:19:17,734 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Template Sync did not find routing-9 on image store 3, may request download based on available hypervisor types
36977 2013-07-26 10:19:17,735 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Removing leftover template routing-9 entry from template store table
36978 2013-07-26 10:19:17,745 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Template Sync did not find routing-10 on image store 3, may request download based on available hypervisor types
36979 2013-07-26 10:19:17,746 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Removing leftover template routing-10 entry from template store table
36980 2013-07-26 10:19:17,755 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Downloading template centos56-x86_64-xen to image store secondary2
36981 2013-07-26 10:19:17,793 DEBUG [storage.image.TemplateDataFactoryImpl] (AgentConnectTaskPool-5:null) template 5 is already in store:3, type:Image
36982 2013-07-26 10:19:17,842 DEBUG [storage.image.BaseImageStoreDriverImpl] (AgentConnectTaskPool-5:null) Downloading template to data store 3
36983 2013-07-26 10:19:17,882 DEBUG [storage.image.BaseImageStoreDriverImpl] (AgentConnectTaskPool-5:null) Performing image store createTemplate async callback
36984 2013-07-26 10:19:17,910 DEBUG [cloudstack.storage.RemoteHostEndPoint] (AgentConnectTaskPool-5:null) Sending command org.apache.cloudstack.storage.command.DownloadCommand to host: 6
36985 2013-07-26 10:19:17,926 DEBUG [agent.transport.Request] (AgentConnectTaskPool-5:null) Seq 6-1226899462: Sending { Cmd , MgmtId: 7280707764394, via: 6, Ver: v1, Flags: 100011, [{"org.apache.cloudstack.storage.command.DownloadCommand":{"hvm":false,"description":" CentOS 5.6(64-bit) no GUI (XenServer)","checksum":"905cec879afd9c9d22ecc8036131a180","maxDownloadSizeInBytes":53687091200,"id":5,"resourceType":"TEMPLATE","installPath":"template/tmpl/1/5","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/expor t/home/swamy/secondary.campo.xen.1","_role":"Image"}},"url":"http://10.147.28.7/templates/builtin/centos56-x86_64.vhd.bz2","format":"VHD","accountId":1,"name":"centos56-x86_64-xen","secUrl":"nfs://10.147.28.7/export/home/swamy/secondary.campo.xen.1","wait":0}}] }
(d.) It successfully downloaded Centos for zone2.
37167 2013-07-26 10:21:32,577 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 6-1226899473: Processing: { Ans: , MgmtId: 7280707764394, via: 6, Ver: v1, Flags: 10, [{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"ed2afd45-561b-4116-a1a5-f8d dad687b12","downloadPct":100,"errorString":"Install completed successfully at 7/26/13 4:51 AM","downloadStatus":"DOWNLOADED","downloadPath":"/mnt/SecStorage/b814c66e-9d67-3f4a-bf26-51e9c8a20324/template/tmpl/1/5/dnld1552778138062074368tmp_","installPath":"templa te/tmpl/1/5/16ee261c-6992-3f95-9c81-14073a9cef61.vhd","templateSize":21474836480,"templatePhySicalSize":1758786048,"checkSum":"905cec879afd9c9d22ecc8036131a180","result":true,"details":"Install completed successfully at 7/26/13 4:51 AM","wait":0}}] }
37513 2013-07-26 10:24:30,410 INFO [context.support.XmlWebApplicationContext] (main:null) Bean 'actionEventInterceptor' of type [class com.cloud.event.ActionEventInterceptor] is not eligible for getting processed by all BeanPostProcessors (for example: not eligible f or auto-proxying)
(e) At this moment, I found both my system vms in zone2 (s-9-VM and v-8-VM) up and running.
(f) Installed usage server on the same machine and restarted management server after this.
(g) Tried to deploy User VM on Zone2 and it failed with the following error.
com.cloud.utils.exception.CloudRuntimeException: Template 1 has not been completely downloaded to zone 2
at com.cloud.template.TemplateManagerImpl.getTemplateSize(TemplateManagerImpl.java:1648)
at com.cloud.storage.VolumeManagerImpl.allocateTemplatedVolume(VolumeManagerImpl.java:1451)
at com.cloud.vm.VirtualMachineManagerImpl.allocate(VirtualMachineManagerImpl.java:389)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.vm.VirtualMachineManagerImpl.allocate(VirtualMachineManagerImpl.java:417)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployRouter(VirtualNetworkApplianceManagerImpl.java:1648)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.findOrDeployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1548)
at com.cloud.utils.component.ComponentInstantiationPostProcessor$InterceptorDispatcher.intercept(ComponentInstantiationPostProcessor.java:125)
at com.cloud.network.router.VirtualNetworkApplianceManagerImpl.deployVirtualRouterInGuestNetwork(VirtualNetworkApplianceManagerImpl.java:1946)
at com.cloud.network.element.VirtualRouterElement.implement(VirtualRouterElement.java:203)
(h) At this moment, verified the cloud.template_store_ref and found that "template 1" is not present.
mysql> select * from template_store_ref where template_id=1;
Empty set (0.00 sec)
(i) Tried to restart SSVM to see what happens when it issues template sync. here is the snippet for the same.
39047 2013-07-26 10:25:27,933 DEBUG [agent.transport.Request] (AgentConnectTaskPool-5:null) Seq 6-341835782: Sending { Cmd , MgmtId: 7280707764394, via: 6, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.ListTemplateCommand":{"store":{"com.cloud.agent.api.to.N fsTO":{"_url":"nfs://10.147.28.7/export/home/swamy/secondary.campo.xen.1","_role":"Image"}},"wait":0}}] }
39048 2013-07-26 10:25:27,936 DEBUG [xen.resource.CitrixResourceBase] (AgentTaskPool-1:null) Found a network called Pool-wide network associated with eth0 on host=10.147.40.31; Network=d9e8cc59-cdef-6ed9-6bc7-82b92d0be44c; pif=c33fec9b-70a8-04d4-21e9-8a6a48a6b0c3
39049 2013-07-26 10:25:27,936 INFO [xen.resource.CitrixResourceBase] (AgentTaskPool-1:null) Private Network is Pool-wide network associated with eth0 for host 10.147.40.31
39050 2013-07-26 10:25:27,937 INFO [xen.resource.CitrixResourceBase] (AgentTaskPool-1:null) Guest Network is Pool-wide network associated with eth0 for host 10.147.40.31
39051 2013-07-26 10:25:27,937 INFO [xen.resource.CitrixResourceBase] (AgentTaskPool-1:null) Public Network is Pool-wide network associated with eth0 for host 10.147.40.31
39052 2013-07-26 10:25:28,016 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 6-341835782: Processing: { Ans: , MgmtId: 7280707764394, via: 6, Ver: v1, Flags: 110, [{"com.cloud.agent.api.storage.ListTemplateAnswer":{"secUrl":"nfs://10.147.28.7/expo rt/home/swamy/secondary.campo.xen.1","templateInfos":{"centos56-x86_64-xen":{"templateName":"centos56-x86_64-xen","installPath":"template/tmpl/1/5/16ee261c-6992-3f95-9c81-14073a9cef61.vhd","size":21474836480,"physicalSize":1758786048,"id":5,"isPublic":true,"isCo rrupted":false}},"result":true,"details":"success","wait":0}}] }
39053 2013-07-26 10:25:28,016 DEBUG [agent.transport.Request] (AgentConnectTaskPool-5:null) Seq 6-341835782: Received: { Ans: , MgmtId: 7280707764394, via: 6, Ver: v1, Flags: 110, { ListTemplateAnswer } }
39054 2013-07-26 10:25:28,017 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-11:null) Seq 6-341835782: No more commands found
39055 2013-07-26 10:25:28,031 DEBUG [xen.resource.CitrixResourceBase] (AgentTaskPool-1:null) Total Ram: 16190133120 dom0 Ram: 588251136
39056 2013-07-26 10:25:28,262 INFO [storage.image.TemplateServiceImpl] (AgentConnectTaskPool-5:null) Template Sync found centos56-x86_64-xen already in the image store
(j) Destroyed SSVM and then didn't see any new SSVM coming up in zone2 forever. Snippet that talks about this is :
2013-07-26 11:55:47,525 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM
2013-07-26 11:55:47,550 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) No secondary storage available in zone 2, wait until it is ready to launch secondary storage vm
2013-07-26 11:55:47,550 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 2 is not ready to launch secondary storage VM yet
2013-07-26 11:55:47,978 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy
2013-07-26 11:55:47,994 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone host is ready, but console proxy template: 1 is not ready on secondary storage.
--
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