Sanjeev N created CLOUDSTACK-4250:
-------------------------------------
Summary: [Object_store_refactor] Register ISO fails in multizone
environment if downloading to one of the zone fails
Key: CLOUDSTACK-4250
URL: https://issues.apache.org/jira/browse/CLOUDSTACK-4250
Project: CloudStack
Issue Type: Bug
Security Level: Public (Anyone can view this level - this is the default.)
Components: ISO, Storage Controller, Template
Affects Versions: 4.2.0
Environment: Latest build from ACS 4.2 branch.
Storage: NFS for both primary and secondary storage
Reporter: Sanjeev N
Priority: Critical
Fix For: 4.2.0
Registering ISO/template with AllZones yes fails If the setup has more than one
zone and one of the zones is disabled and SSVM is not running.
Steps to Reproduce:
================
1.Bring up CS with more than one zone say zone1 and zone2 both using NFS for
primary and secondary storage
2.Disable zone2 and stop SSVM in it
3.Register ISO/Template in zone1 and choose zone= All Zones in UI while
registering iso
Result:
======
Template download was succeeded in zone1 but it was timed out in zone2. Timeout
in downloading template in zone2 deleted the template from both the zones
Observations:
===========
Log snippet from management server log file:
2013-08-12 20:58:37,978 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null)
===START=== 10.146.0.20 -- GET
command=registerIso&response=json&sessionkey=G1sYAr9SNj4GF7irv5eSdcqDB10%3D&name=all&displayText=all&url=http%3A%2F%2F10.147.28.7%2Ftemplates%2Fvmware%2Fdummy.iso&zoneid=-1&isextractable=true&bootable=true&osTypeId=12&ispublic=true&isfeatured=true&_=1376301850336
2013-08-12 20:58:38,171 DEBUG [storage.image.TemplateDataFactoryImpl]
(catalina-exec-22:null) template 220 is not in store:6, type:Image
2013-08-12 20:58:38,250 DEBUG [storage.image.TemplateDataFactoryImpl]
(catalina-exec-22:null) template 220 is already in store:6, type:Image
2013-08-12 20:58:38,286 DEBUG [storage.image.BaseImageStoreDriverImpl]
(catalina-exec-22:null) Downloading template to data store 6
2013-08-12 20:58:38,313 DEBUG [storage.image.BaseImageStoreDriverImpl]
(catalina-exec-22:null) Performing image store createTemplate async callback
2013-08-12 20:58:38,340 DEBUG [cloudstack.storage.RemoteHostEndPoint]
(catalina-exec-22:null) Sending command
org.apache.cloudstack.storage.command.DownloadCommand to host: 7
2013-08-12 20:58:38,344 DEBUG [agent.transport.Request] (catalina-exec-22:null)
Seq 7-1199968632: Sending { Cmd , MgmtId: 6851580133501, via: 7, Ver: v1,
Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadCommand":{"hvm":true,"description":"all","maxDownloadSizeInBytes":53687091200,"id":220,"resourceType":"TEMPLATE","installPath":"template/tmpl/9/220","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/manasa/secondaryVMw","_role":"Image"}},"url":"http://10.147.28.7/templates/vmware/dummy.iso","format":"ISO","accountId":9,"name":"220-9-41f76fdf-af7e-3d03-91aa-f7fd95fcdf02","secUrl":"nfs://10.147.28.7/export/home/manasa/secondaryVMw","wait":0}}]
}
2013-08-12 20:58:38,350 DEBUG [storage.image.TemplateDataFactoryImpl]
(catalina-exec-22:null) template 220 is not in store:9, type:Image
2013-08-12 20:58:38,390 DEBUG [storage.image.TemplateDataFactoryImpl]
(catalina-exec-22:null) template 220 is already in store:9, type:Image
2013-08-12 20:58:38,431 DEBUG [storage.image.BaseImageStoreDriverImpl]
(catalina-exec-22:null) Downloading template to data store 9
2013-08-12 20:58:38,447 INFO [storage.endpoint.DefaultEndPointSelector]
(catalina-exec-22:null) No running ssvm is found, so command will be sent to
LocalHostEndPoint
2013-08-12 20:58:38,450 DEBUG [storage.image.BaseImageStoreDriverImpl]
(catalina-exec-22:null) Performing image store createTemplate async callback
2013-08-12 20:58:38,471 DEBUG [storage.image.TemplateDataFactoryImpl]
(catalina-exec-22:null) template 220 is not in store:2, type:Image
2013-08-12 20:58:38,499 DEBUG [storage.image.TemplateDataFactoryImpl]
(catalina-exec-22:null) template 220 is already in store:2, type:Image
2013-08-12 20:58:38,524 DEBUG [storage.image.BaseImageStoreDriverImpl]
(catalina-exec-22:null) Downloading template to data store 2
In the above log, store 9 was present in a zone which was in disabled state and
SSVM was in stopped state. But still CS initiated download via
LocalHostEndPoint
Q: What is LocalHostEndPoint? Is it management server? If yes why do we
initiate download via management server?
2013-08-12 20:58:38,540 DEBUG [storage.image.BaseImageStoreDriverImpl]
(catalina-exec-22:null) Performing image store createTemplate async callback
2013-08-12 20:58:38,556 DEBUG [cloudstack.storage.RemoteHostEndPoint]
(catalina-exec-22:null) Sending command
org.apache.cloudstack.storage.command.DownloadCommand to host: 14
2013-08-12 20:58:38,559 DEBUG [agent.transport.Request] (catalina-exec-22:null)
Seq 14-670765384: Sending { Cmd , MgmtId: 6851580133501, via: 14, Ver: v1,
Flags: 100011,
[{"org.apache.cloudstack.storage.command.DownloadCommand":{"hvm":true,"description":"all","maxDownloadSizeInBytes":53687091200,"id":220,"resourceType":"TEMPLATE","installPath":"template/tmpl/9/220","_store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://10.147.28.7/export/home/manasa/secondaryxen","_role":"Image"}},"url":"http://10.147.28.7/templates/vmware/dummy.iso","format":"ISO","accountId":9,"name":"220-9-41f76fdf-af7e-3d03-91aa-f7fd95fcdf02","secUrl":"nfs://10.147.28.7/export/home/manasa/secondaryxen","wait":0}}]
}
2013-08-12 20:58:38,594 DEBUG [cloud.api.ApiServlet] (catalina-exec-22:null)
===END=== 10.146.0.20 -- GET
command=registerIso&response=json&sessionkey=G1sYAr9SNj4GF7irv5eSdcqDB10%3D&name=all&displayText=all&url=http%3A%2F%2F10.147.28.7%2Ftemplates%2Fvmware%2Fdummy.iso&zoneid=-1&isextractable=true&bootable=true&osTypeId=12&ispublic=true&isfeatured=true&_=1376301850336
2013-08-12 20:58:42,059 DEBUG [agent.transport.Request]
(AgentManager-Handler-12:null) Seq 7-1199968632: Processing: { Ans: , MgmtId:
6851580133501, via: 7, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"edf48a3a-24a2-4ea5-8863-87cba1a31971","downloadPct":100,"errorString":"Download
success, starting install
","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStorage/0e8da06e-0788-3efb-86a6-b0705a2205d3/template/tmpl/9/220/dnld6918760524895984102tmp_","installPath":"template/tmpl/9/220/220-9-41f76fdf-af7e-3d03-91aa-f7fd95fcdf02.iso","templateSize":0,"templatePhySicalSize":0,"checkSum":"18425b903c6969ed63f328ef4fd346af","result":true,"details":"Download
success, starting install ","wait":0}}] }
2013-08-12 20:58:42,061 DEBUG [agent.transport.Request]
(AgentManager-Handler-15:null) Seq 14-670765384: Processing: { Ans: , MgmtId:
6851580133501, via: 14, Ver: v1, Flags: 10,
[{"com.cloud.agent.api.storage.DownloadAnswer":{"jobId":"4dafa883-a1bf-4693-a463-049120455173","downloadPct":100,"errorString":"Download
success, starting install
","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStorage/0a639c32-c2df-36e3-883d-eebcb5093bf1/template/tmpl/9/220/dnld2814394365859359939tmp_","installPath":"template/tmpl/9/220/220-9-41f76fdf-af7e-3d03-91aa-f7fd95fcdf02.iso","templateSize":0,"templatePhySicalSize":0,"checkSum":"18425b903c6969ed63f328ef4fd346af","result":true,"details":"Download
success, starting install ","wait":0}}] }
2013-08-12 20:58:42,623 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-11:null) SeqA 4-36208: Processing Seq 4-36208: { Cmd ,
MgmtId: -1, via: 4, Ver: v1, Flags: 11,
[{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":2,"_loadInfo":"{\n
\"connections\": []\n}","wait":0}}] }
2013-08-12 20:58:42,632 DEBUG [agent.manager.AgentManagerImpl]
(AgentManager-Handler-11:null) SeqA 4-36208: Sending Seq 4-36208: { Ans: ,
MgmtId: 6851580133501, via: 4, Ver: v1, Flags: 100010,
[{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
2013-08-12 20:58:43,257 DEBUG [cloud.server.StatsCollector]
(StatsCollector-1:null) StorageCollector is running...
2013-08-12 20:58:43,817 DEBUG [agent.transport.Request] (StatsCollector-1:null)
Seq 14-670765385: Received: { Ans: , MgmtId: 6851580133501, via: 14, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-08-12 20:58:43,934 DEBUG [agent.transport.Request] (StatsCollector-1:null)
Seq 7-1199968633: Received: { Ans: , MgmtId: 6851580133501, via: 7, Ver: v1,
Flags: 10, { GetStorageStatsAnswer } }
2013-08-12 20:58:43,938 INFO [storage.endpoint.DefaultEndPointSelector]
(StatsCollector-1:null) No running ssvm is found, so command will be sent to
LocalHostEndPoint
Before deleting ISO from CS I could see the following timeout messages:
2013-08-12 20:59:38,450 DEBUG [storage.download.DownloadListener]
(Timer-25:null) timeout: transitioning to download error state,
currstate=NOT_DOWNLOADED, TEMPLATE: 220 at host 0
2013-08-12 20:59:38,450 DEBUG [storage.image.BaseImageStoreDriverImpl]
(Timer-25:null) Performing image store createTemplate async callback
2013-08-12 20:59:38,543 WARN [storage.download.DownloadListener]
(Timer-25:null) Entering download error state: timeout waiting for response
from storage host, TEMPLATE: 220 at host 0
Attaching management server log file and cloud DB.
--
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
