[
https://issues.apache.org/jira/browse/CLOUDSTACK-3845?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Nitin Mehta resolved CLOUDSTACK-3845.
-------------------------------------
Resolution: Cannot Reproduce
> [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
> Assignee: Nitin Mehta
> Priority: Critical
> Fix For: 4.2.0
>
> Attachments: logs.tgz, logs.tgz
>
>
> 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
