For the last exception in step 5, I forgot to mention this. We need to start cloud-agent service after installing the agent in case of both Ubuntu and Rhel KVM otherwise we don't see the Agent logs at the location /var/log/cloud/agent.
From: Edison Su Sent: Wednesday, September 26, 2012 2:56 AM To: Abhinav Roy; Rohit Yadav; cloudstack-dev@incubator.apache.org Cc: Sudha Ponnaganti; Sowmya Krishnan; Sailaja Mada; Suresh Sadhu; Shweta Agarwal; Prashant Kumar Mishra; Srinivas Vejalla Subject: RE: Few observations while installing agent on KVM host (ubuntu 12.04) and Management server on ubuntu 12.04 From: Abhinav Roy Sent: Tuesday, September 25, 2012 2:17 PM To: Rohit Yadav; Edison Su; cloudstack-dev@incubator.apache.org Cc: Sudha Ponnaganti; Sowmya Krishnan; Sailaja Mada; Suresh Sadhu; Shweta Agarwal; Prashant Kumar Mishra; Srinivas Vejalla Subject: Few observations while installing agent on KVM host (ubuntu 12.04) and Management server on ubuntu 12.04 Hi Rohit, I had the following observation while installing agent on KVM host (Ubuntu) and adding it to the management server (Ubuntu) [it was a fresh install] : 1. I had used the build http://jenkins.cloudstack.org/job/build-4.0-ubuntu1204/154/artifact/CloudStack-oss-4.0.0-154.tar.bz2 . There I saw multiple instances of the same package after untarring cloud-agent_4.0.0-rc1_amd64.deb cloud-cli_4.0.0-rc2_amd64.deb cloud-deps_4.0.0-rc1_amd64.deb cloud-server_4.0.0-rc2_amd64.deb cloud-utils_4.0.0-rc1_amd64.deb cloud-agent_4.0.0-rc2_amd64.deb cloud-client_4.0.0-rc1_amd64.deb cloud-deps_4.0.0-rc2_amd64.deb cloud-setup_4.0.0-rc1_amd64.deb cloud-utils_4.0.0-rc2_amd64.deb cloud-agent-deps_4.0.0-rc1_amd64.deb cloud-client_4.0.0-rc2_amd64.deb cloud-python_4.0.0-rc1_amd64.deb cloud-setup_4.0.0-rc2_amd64.deb install.sh cloud-agent-deps_4.0.0-rc2_amd64.deb cloud-client-ui_4.0.0-rc1_amd64.deb cloud-python_4.0.0-rc2_amd64.deb cloud-system-iso_4.0.0-rc1_amd64.deb Packages.gz cloud-agent-libs_4.0.0-rc1_amd64.deb cloud-client-ui_4.0.0-rc2_amd64.deb cloud-scripts_4.0.0-rc1_amd64.deb cloud-system-iso_4.0.0-rc2_amd64.deb cloud-agent-libs_4.0.0-rc2_amd64.deb cloud-core_4.0.0-rc1_amd64.deb cloud-scripts_4.0.0-rc2_amd64.deb cloud-usage_4.0.0-rc1_amd64.deb cloud-cli_4.0.0-rc1_amd64.deb cloud-core_4.0.0-rc2_amd64.deb cloud-server_4.0.0-rc1_amd64.deb cloud-usage_4.0.0-rc2_amd64.deb Is this the new way of packaging? [Edison] The packaging is wrong. Need to remove the old debs. 2. I did the agent install using install.sh script but this script doesn't install the cloud-scripts package, so after running install.sh I had to install scripts package manually. So, do we need to do this always? [Edison] Need to be fixed in install.sh 3. The script for copying the systemvm-template to secondary storage is located at /usr/lib/cloud/common/scripts/storage/secondary/cloud-install-sys-tmplt while for Rhel 6.3 it is stored at /usr/lib64/cloud/common/scripts/storage/secondary/cloud-install-sys-tmplt. Is this going to be documented? [Edison] Need to be documented. 4. After management server and DB server installation was done and I was going to configure the CS through UI, I was not able to login to the UI with the default admin/password credentials. I saw these errors in the logs...... 2012-09-25 15:29:33,568 DEBUG [utils.script.Script] (main:null) Looking for vms/systemvm.iso in /usr/lib/cloud/common/vms/systemvm.iso 2012-09-25 15:29:33,570 ERROR [cloud.servlet.CloudStartupServlet] (main:null) Exception starting management server com.cloud.utils.exception.CloudRuntimeException: Unable to find key inject script scripts/vm/systemvm/injectkeys.sh at com.cloud.server.ConfigurationServerImpl.updateKeyPairs(ConfigurationServerImpl.java:675) at com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34) at com.cloud.server.ConfigurationServerImpl.persistDefaultValues(ConfigurationServerImpl.java:265) at com.cloud.utils.db.DatabaseCallback.intercept(DatabaseCallback.java:34) at com.cloud.servlet.CloudStartupServlet.init(CloudStartupServlet.java:47) at javax.servlet.GenericServlet.init(GenericServlet.java:212) at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1206) at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1026) at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4421) at org.apache.catalina.core.StandardContext.start(StandardContext.java:4734) at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:799) at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:779) at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:601) at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1079) at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:1002) at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:506) at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1317) at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:324) at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:142) at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1065) at org.apache.catalina.core.StandardHost.start(StandardHost.java:840) at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1057) at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:463) at org.apache.catalina.core.StandardService.start(StandardService.java:525) at org.apache.catalina.core.StandardServer.start(StandardServer.java:754) at org.apache.catalina.startup.Catalina.start(Catalina.java:595) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:616) at org.apache.commons.daemon.support.DaemonLoader.start(DaemonLoader.java:243) but after restarting the management server , I was able to login with the default credentials. Is this expected and is going to be documented? [Edison] I think it's due to cloud-scripts package is not installed. 5. Now while adding the host I got the following exception, though the host got added successfully , but this exception was found in the management server logs 2012-09-25 15:57:45,074 DEBUG [agent.manager.AgentManagerImpl] (AgentTaskPool-1:null) Sending Disconnect to listener: com.cloud.network.NetworkUsageManagerImpl$DirectNetworkStatsListener 2012-09-25 15:57:45,074 DEBUG [cloud.network.NetworkUsageManagerImpl] (AgentTaskPool-1:null) Disconnected called on 1 with status Disconnected 2012-09-25 15:57:45,074 DEBUG [cloud.host.Status] (AgentTaskPool-1:null) Transition:[Resource state = Enabled, Agent event = ShutdownRequested, Host id = 1, name = BAND-CLOUD-19] 2012-09-25 15:57:45,076 DEBUG [cloud.ha.HighAvailabilityManagerImpl] (secstorage-1:null) Scheduled HAWork[1-CheckStop-1-Starting-Scheduled] 2012-09-25 15:57:45,082 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-1) Processing HAWork[1-CheckStop-1-Starting-Scheduled] 2012-09-25 15:57:45,084 INFO [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-1) Stopping VM[SecondaryStorageVm|s-1-VM] 2012-09-25 15:57:45,085 DEBUG [cloud.vm.VirtualMachineManagerImpl] (HA-Worker-0:work-1) Found an outstanding work item for this vm VM[SecondaryStorageVm|s-1-VM] with state:Starting, work id:54d69a61-135d-4cd1-add5-3ed6265c71dc 2012-09-25 15:57:45,092 ERROR [cloud.ha.HighAvailabilityManagerImpl] (HA-Worker-0:work-1) Terminating HAWork[1-CheckStop-1-Starting-Scheduled] com.cloud.utils.exception.CloudRuntimeException: We cannot stop VM[SecondaryStorageVm|s-1-VM] when it is in state Starting at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1030) at com.cloud.ha.HighAvailabilityManagerImpl.stopVM(HighAvailabilityManagerImpl.java:645) at com.cloud.ha.HighAvailabilityManagerImpl$WorkerThread.run(HighAvailabilityManagerImpl.java:837) 2012-09-25 15:57:45,092 WARN [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Exception while trying to start secondary storage vm com.cloud.exception.AgentUnavailableException: Resource [Host:1] is unreachable: Host 1: Unable to start s-1-VM at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:825) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:472) at com.cloud.vm.VirtualMachineManagerImpl.start(VirtualMachineManagerImpl.java:465) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.startSecStorageVm(SecondaryStorageManagerImpl.java:257) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.allocCapacity(SecondaryStorageManagerImpl.java:684) at com.cloud.storage.secondary.SecondaryStorageManagerImpl.expandPool(SecondaryStorageManagerImpl.java:1310) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:119) at com.cloud.secstorage.PremiumSecondaryStorageManagerImpl.scanPool(PremiumSecondaryStorageManagerImpl.java:50) at com.cloud.vm.SystemVmLoadScanner.loadScan(SystemVmLoadScanner.java:106) at com.cloud.vm.SystemVmLoadScanner.access$100(SystemVmLoadScanner.java:34) at com.cloud.vm.SystemVmLoadScanner$1.reallyRun(SystemVmLoadScanner.java:83) at com.cloud.vm.SystemVmLoadScanner$1.run(SystemVmLoadScanner.java:73) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:351) at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:165) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:267) 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.cloud.exception.OperationTimedoutException: Commands 1514209300 to Host 1 timed out after 3600 at com.cloud.agent.manager.AgentAttache.send(AgentAttache.java:429) at com.cloud.agent.manager.AgentManagerImpl.send(AgentManagerImpl.java:505) at com.cloud.agent.manager.AgentManagerImpl.send(AgentManagerImpl.java:1026) at com.cloud.vm.VirtualMachineManagerImpl.advanceStart(VirtualMachineManagerImpl.java:778) ... 20 more 2012-09-25 15:57:45,097 INFO [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Unable to start secondary storage vm for standby capacity, secStorageVm vm Id : 1, will recycle it and start a new one 2012-09-25 15:57:45,097 INFO [cloud.secstorage.PremiumSecondaryStorageManagerImpl] (secstorage-1:null) Primary secondary storage is not even started, wait until next turn 2012-09-25 15:57:45,099 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,121 DEBUG [cloud.host.Status] (AgentTaskPool-1:null) Agent status update: [id = 1; name = BAND-CLOUD-19; old status = Up; event = ShutdownRequested; new status = Disconnected; old update count = 2; new update count = 3] 2012-09-25 15:57:45,121 DEBUG [agent.manager.ClusteredAgentManagerImpl] (AgentTaskPool-1:null) Notifying other nodes of to disconnect 2012-09-25 15:57:45,124 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,126 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,128 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,130 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,132 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,138 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,140 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,142 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,150 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,151 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:57:45,153 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:58:10,801 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:58:10,959 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet 2012-09-25 15:58:11,469 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Snapshot scheduler.poll is being called at 2012-09-25 10:28:11 GMT 2012-09-25 15:58:11,470 DEBUG [storage.snapshot.SnapshotSchedulerImpl] (SnapshotPollTask:null) Got 0 snapshots to be executed at 2012-09-25 10:28:11 GMT 2012-09-25 15:58:11,503 DEBUG [cloud.network.ExternalLoadBalancerUsageManagerImpl] (ExternalNetworkMonitor-1:null) External load balancer devices stats collector is running... 2012-09-25 15:58:11,546 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterMonitor-1:null) Found 0 running routers. 2012-09-25 15:58:11,548 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2012-09-25 15:58:16,191 DEBUG [utils.ssh.SSHCmdHelper] (catalina-exec-13:null) cloud-setup-agent -m 10.102.125.241 -z 1 -p 1 -c 1 -g d8830471-0deb-31e3-aef0-30a145f93689 -a --pubNic=cloudbr0 --prvNic=cloudbr0 --guestNic=cloudbr0 output:CloudStack Agent setup is done! [OK] Configure cloudAgent ... 2012-09-25 15:58:19,404 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-0: Processing the first command { Cmd , MgmtId: -1, via: 1, Ver: v1, Flags: 1, [{"StartupRoutingCommand":{"cpus":8,"speed":2394,"memory":16814125056,"dom0MinMemory":805306368,"poolSync":false,"vms":{"v-2-VM":{"state":"Running"},"s-1-VM":{"state":"Running"}},"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS":"Ubuntu","Host.OS.Kernel.Version":"3.2.0-23-generic","Host.OS.Version":"12.04"},"type":"Routing","dataCenter":"1","pod":"1","cluster":"1","guid":"d8830471-0deb-31e3-aef0-30a145f93689-LibvirtComputingResource","name":"BAND-CLOUD-19","id":1,"version":"2.2.20120925090538","publicIpAddress":"10.102.125.19","publicNetmask":"255.255.255.0","publicMacAddress":"78:2b:cb:5e:d1:cb","privateIpAddress":"10.102.125.19","privateMacAddress":"78:2b:cb:5e:d1:cb","privateNetmask":"255.255.255.0","storageIpAddress":"10.102.125.19","storageNetmask":"255.255.255.0","storageMacAddress":"78:2b:cb:5e:d1:cb","resourceName":"LibvirtComputingResource","gatewayIpAddress":"10.102.125.1","wait":0}},{"StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"b0581710-be0b-4818-9869-ff12bd9fe08e","host":"10.102.125.19","localPath":"/var/lib/libvirt/images/","hostPath":"/var/lib/libvirt/images/","poolType":"Filesystem","capacityBytes":481872109568,"availableBytes":8612806656},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"1","pod":"1","guid":"d8830471-0deb-31e3-aef0-30a145f93689-LibvirtComputingResource","name":"BAND-CLOUD-19","id":1,"version":"2.2.20120925090538","resourceName":"LibvirtComputingResource","wait":0}}] } 2012-09-25 15:58:19,415 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to NiciraNvpElement$$EnhancerByCGLIB$$3eb29c70 2012-09-25 15:58:19,415 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to XcpServerDiscoverer$$EnhancerByCGLIB$$cb61f98 2012-09-25 15:58:19,415 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PxeServerManagerImpl$$EnhancerByCGLIB$$803542e0 2012-09-25 15:58:19,415 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to ConsoleProxyManagerImpl$$EnhancerByCGLIB$$7666f719 2012-09-25 15:58:19,415 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to ExternalDhcpManagerImpl$$EnhancerByCGLIB$$b1df3ce6 2012-09-25 15:58:19,416 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PremiumSecondaryStorageManagerImpl$$EnhancerByCGLIB$$b40686c1 2012-09-25 15:58:19,416 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to NetworkUsageManagerImpl$$EnhancerByCGLIB$$913212a8 2012-09-25 15:58:19,416 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-13:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to KvmServerDiscoverer$$EnhancerByCGLIB$$20bb7634 2012-09-25 15:58:19,448 DEBUG [cloud.resource.ResourceState] (AgentManager-Handler-13:null) Resource state update: [id = 1; name = BAND-CLOUD-19; old state = Enabled; event = InternalCreated; new state = Enabled] 2012-09-25 15:58:19,449 DEBUG [cloud.host.Status] (AgentManager-Handler-13:null) Transition:[Resource state = Enabled, Agent event = AgentConnected, Host id = 1, name = BAND-CLOUD-19] 2012-09-25 15:58:19,454 DEBUG [cloud.host.Status] (AgentManager-Handler-13:null) Agent status update: [id = 1; name = BAND-CLOUD-19; old status = Disconnected; event = AgentConnected; new status = Connecting; old update count = 3; new update count = 4] 2012-09-25 15:58:19,454 DEBUG [agent.manager.ClusteredAgentManagerImpl] (AgentManager-Handler-13:null) create ClusteredAgentAttache for 1 2012-09-25 15:58:19,456 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: XcpServerDiscoverer$$EnhancerByCGLIB$$cb61f98 2012-09-25 15:58:19,456 DEBUG [xen.discoverer.XcpServerDiscoverer] (AgentManager-Handler-13:null) Not XenServer so moving on. 2012-09-25 15:58:19,456 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: ClusteredVirtualMachineManagerImpl$$EnhancerByCGLIB$$7c5727bd 2012-09-25 15:58:19,472 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) Found 2 VMs for host 1 2012-09-25 15:58:19,478 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) VM s-1-VM: cs state = Starting and realState = Running 2012-09-25 15:58:19,480 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) VM s-1-VM: cs state = Starting and realState = Running 2012-09-25 15:58:19,481 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) VM state is starting on full sync so updating it to running 2012-09-25 15:58:19,488 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) Found an outstanding work item for this vm VM[SecondaryStorageVm|s-1-VM] in state:Starting, work id:54d69a61-135d-4cd1-add5-3ed6265c71dc 2012-09-25 15:58:19,504 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) VM state transitted from :Starting to Running with event: AgentReportRunningvm's original host id: null new host id: 1 host id before state transition: 1 2012-09-25 15:58:19,504 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) VM's VM[SecondaryStorageVm|s-1-VM] state is starting on full sync so updating it to Running 2012-09-25 15:58:19,514 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) Finalizing commands that need to be send to complete Start process for the vm VM[SecondaryStorageVm|s-1-VM] 2012-09-25 15:58:19,521 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493889: Sending { Cmd , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 100011, [{"check.CheckSshCommand":{"ip":"169.254.2.123","port":3922,"interval":6,"retries":100,"name":"s-1-VM","wait":0}}] } 2012-09-25 15:58:19,640 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 1 2012-09-25 15:58:25,554 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) VmStatsCollector is running... 2012-09-25 15:58:27,145 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-15:null) Ping from 3 2012-09-25 15:58:31,006 DEBUG [cloud.server.StatsCollector] (StatsCollector-2:null) HostStatsCollector is running... 2012-09-25 15:58:36,692 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) StorageCollector is running... 2012-09-25 15:58:36,695 DEBUG [cloud.server.StatsCollector] (StatsCollector-3:null) There is no secondary storage VM for secondary storage host nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu 2012-09-25 15:58:40,801 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is not ready to launch secondary storage VM yet 2012-09-25 15:58:40,965 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is not ready to launch console proxy yet 2012-09-25 15:58:41,446 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Running Capacity Checker ... 2012-09-25 15:58:41,446 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) recalculating system capacity 2012-09-25 15:58:41,446 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing cpu/ram capacity update 2012-09-25 15:58:41,451 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 2 VMs on host 1 2012-09-25 15:58:41,452 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) Found 0 VM, not running on host 1 2012-09-25 15:58:41,454 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate cpu capacity, host:1 usedCpu: 1000 reservedCpu: 0 2012-09-25 15:58:41,454 DEBUG [cloud.capacity.CapacityManagerImpl] (CapacityChecker:null) No need to calibrate memory capacity, host:1 usedMem: 1342177280 reservedMem: 0 2012-09-25 15:58:41,454 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing cpu/ram capacity update 2012-09-25 15:58:41,454 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing storage capacity update 2012-09-25 15:58:41,461 DEBUG [cloud.storage.StorageManagerImpl] (CapacityChecker:null) Successfully set Capacity - 15739424079872 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 200, PodId 1 2012-09-25 15:58:41,461 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing storage capacity update 2012-09-25 15:58:41,461 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for public ip and Vlans 2012-09-25 15:58:41,477 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done capacity updates for public ip and Vlans 2012-09-25 15:58:41,477 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Executing capacity updates for private ip 2012-09-25 15:58:41,483 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done executing capacity updates for private ip 2012-09-25 15:58:41,483 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done recalculating system capacity 2012-09-25 15:58:41,496 DEBUG [cloud.alert.AlertManagerImpl] (CapacityChecker:null) Done running Capacity Checker ... 2012-09-25 15:58:41,549 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2012-09-25 15:59:08,578 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 1-195493889: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, [{"check.CheckSshAnswer":{"result":true,"wait":0}}] } 2012-09-25 15:59:08,578 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493889: Received: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, { CheckSshAnswer } } 2012-09-25 15:59:08,588 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) VM state transitted from :Running to Running with event: AgentReportRunningvm's original host id: null new host id: 1 host id before state transition: 1 2012-09-25 15:59:08,588 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) Updating outstanding work item to Done, id:54d69a61-135d-4cd1-add5-3ed6265c71dc 2012-09-25 15:59:08,592 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) VM v-2-VM: cs state = Running and realState = Running 2012-09-25 15:59:08,592 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) VM v-2-VM: cs state = Running and realState = Running 2012-09-25 15:59:08,592 DEBUG [cloud.vm.VirtualMachineManagerImpl] (AgentManager-Handler-13:null) Both states are Running for VM[ConsoleProxy|v-2-VM] 2012-09-25 15:59:08,605 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) VM state transitted from :Running to Running with event: AgentReportRunningvm's original host id: 1 new host id: 1 host id before state transition: 1 2012-09-25 15:59:08,605 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: SecurityGroupListener 2012-09-25 15:59:08,605 INFO [network.security.SecurityGroupListener] (AgentManager-Handler-13:null) Received a host startup notification 2012-09-25 15:59:08,608 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493890: Sending { Cmd , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 100011, [{"CleanupNetworkRulesCmd":{"interval":1976,"wait":0}}] } 2012-09-25 15:59:08,609 INFO [network.security.SecurityGroupListener] (AgentManager-Handler-13:null) Scheduled network rules cleanup, interval=1976 2012-09-25 15:59:08,609 INFO [network.security.SecurityGroupListener] (AgentManager-Handler-13:null) Received a host startup notification 2012-09-25 15:59:08,609 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: StoragePoolMonitor 2012-09-25 15:59:08,610 DEBUG [storage.listener.StoragePoolMonitor] (AgentManager-Handler-13:null) Host 1 connected, sending down storage pool information ... 2012-09-25 15:59:08,610 DEBUG [cloud.storage.StorageManagerImpl] (AgentManager-Handler-13:null) Adding pool p1 to host 1 2012-09-25 15:59:08,612 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493891: Sending { Cmd , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 100011, [{"ModifyStoragePoolCommand":{"add":true,"pool":{"id":200,"uuid":"ef0bdc65-34ea-3472-a4a4-82f605f01593","host":"10.102.123.240","path":"/cloudstack/abhinav/PS-ubuntu","port":2049,"type":"NetworkFilesystem"},"localPath":"/mnt//ef0bdc65-34ea-3472-a4a4-82f605f01593","wait":0}}] } 2012-09-25 15:59:08,614 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 1-195493890: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, [{"Answer":{"result":true,"wait":0}}] } 2012-09-25 15:59:08,674 DEBUG [agent.transport.Request] (AgentManager-Handler-5:null) Seq 1-195493891: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, [{"ModifyStoragePoolAnswer":{"poolInfo":{"host":"10.102.123.240","localPath":"/mnt//ef0bdc65-34ea-3472-a4a4-82f605f01593","hostPath":"/cloudstack/abhinav/PS-ubuntu","poolType":"NetworkFilesystem","capacityBytes":7869712039936,"availableBytes":4545246789632},"templateInfo":{},"result":true,"wait":0}}] } 2012-09-25 15:59:08,674 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493891: Received: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, { ModifyStoragePoolAnswer } } 2012-09-25 15:59:08,680 INFO [cloud.storage.StorageManagerImpl] (AgentManager-Handler-13:null) Connection established between Pool[200|NetworkFilesystem] host + 1 2012-09-25 15:59:08,681 DEBUG [cloud.storage.StorageManagerImpl] (AgentManager-Handler-13:null) Successfully set Capacity - 15739424079872 for capacity type - 3 , DataCenterId - 1, HostOrPoolId - 200, PodId 1 2012-09-25 15:59:08,681 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: SecondaryStorageListener 2012-09-25 15:59:08,681 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: NetworkManagerImpl$$EnhancerByCGLIB$$a11338d9 2012-09-25 15:59:08,682 DEBUG [cloud.network.NetworkManagerImpl] (AgentManager-Handler-13:null) Host's hypervisorType is: KVM 2012-09-25 15:59:08,687 DEBUG [cloud.network.NetworkManagerImpl] (AgentManager-Handler-13:null) Sending CheckNetworkCommand to check the Network is setup correctly on Agent 2012-09-25 15:59:08,688 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493892: Sending { Cmd , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 100111, [{"CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":200}],"wait":0}}] } 2012-09-25 15:59:08,710 DEBUG [agent.transport.Request] (AgentManager-Handler-4:null) Seq 1-195493890: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, [{"Answer":{"result":true,"details":"","wait":0}}] } 2012-09-25 15:59:08,749 DEBUG [agent.transport.Request] (AgentManager-Handler-7:null) Seq 1-195493892: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 110, [{"CheckNetworkAnswer":{"_reconnect":false,"result":true,"wait":0}}] } 2012-09-25 15:59:08,750 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-7:null) Seq 1-195493892: No more commands found 2012-09-25 15:59:08,750 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493892: Received: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 110, { CheckNetworkAnswer } } 2012-09-25 15:59:08,750 DEBUG [cloud.network.NetworkManagerImpl] (AgentManager-Handler-13:null) Network setup is correct on Agent 2012-09-25 15:59:08,750 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: AgentMonitor$$EnhancerByCGLIB$$11a88b39 2012-09-25 15:59:08,750 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: DownloadListener 2012-09-25 15:59:08,752 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: UploadListener 2012-09-25 15:59:08,752 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: LocalStoragePoolListener$$EnhancerByCGLIB$$a3a4d76d 2012-09-25 15:59:08,752 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: StorageCapacityListener 2012-09-25 15:59:08,752 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: ComputeCapacityListener 2012-09-25 15:59:08,755 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) Found 2 VMs on host 1 2012-09-25 15:59:08,764 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) Found 0 VM, not running on host 1 2012-09-25 15:59:08,767 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) No need to calibrate cpu capacity, host:1 usedCpu: 1000 reservedCpu: 0 2012-09-25 15:59:08,767 DEBUG [cloud.capacity.CapacityManagerImpl] (AgentManager-Handler-13:null) No need to calibrate memory capacity, host:1 usedMem: 1342177280 reservedMem: 0 2012-09-25 15:59:08,767 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: ConsoleProxyListener 2012-09-25 15:59:08,767 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: SshKeysDistriMonitor 2012-09-25 15:59:08,771 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493893: Sending { Cmd , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 100011, [{"ModifySshKeysCommand":{"wait":0}}] } 2012-09-25 15:59:08,771 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: VpcVirtualNetworkApplianceManagerImpl$$EnhancerByCGLIB$$ad9d1c61 2012-09-25 15:59:08,773 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-13:null) Sending Connect to listener: DirectNetworkStatsListener 2012-09-25 15:59:08,775 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493894: Sending { Cmd , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 100111, [{"ReadyCommand":{"dcId":1,"wait":0}}] } 2012-09-25 15:59:08,783 DEBUG [agent.transport.Request] (AgentManager-Handler-8:null) Seq 1-195493893: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 10, [{"Answer":{"result":true,"wait":0}}] } 2012-09-25 15:59:08,821 DEBUG [agent.transport.Request] (AgentManager-Handler-2:null) Seq 1-195493894: Processing: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 110, [{"ReadyAnswer":{"result":true,"wait":0}}] } 2012-09-25 15:59:08,821 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-2:null) Seq 1-195493894: No more commands found 2012-09-25 15:59:08,822 DEBUG [agent.transport.Request] (AgentManager-Handler-13:null) Seq 1-195493894: Received: { Ans: , MgmtId: 165676482560269, via: 1, Ver: v1, Flags: 110, { ReadyAnswer } } 2012-09-25 15:59:08,822 DEBUG [cloud.host.Status] (AgentManager-Handler-13:null) Transition:[Resource state = Enabled, Agent event = Ready, Host id = 1, name = BAND-CLOUD-19] 2012-09-25 15:59:08,825 DEBUG [cloud.host.Status] (AgentManager-Handler-13:null) Agent status update: [id = 1; name = BAND-CLOUD-19; old status = Connecting; event = Ready; new status = Up; old update count = 4; new update count = 5] 2012-09-25 15:59:10,427 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq -1-0: Processing the first command { Cmd , MgmtId: -1, via: -1, Ver: v1, Flags: 101, [{"StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-1-VM-NfsSecondaryStorageResource","name":"s-1-VM","version":"2.2.20120925090538","iqn":"NoIqn","publicIpAddress":"10.102.125.67","publicNetmask":"255.255.255.0","publicMacAddress":"06:39:4c:00:00:07","privateIpAddress":"10.102.125.62","privateMacAddress":"06:2b:3e:00:00:02","privateNetmask":"255.255.255.0","storageIpAddress":"10.102.125.62","storageNetmask":"255.255.255.0","storageMacAddress":"06:2b:3e:00:00:02","resourceName":"NfsSecondaryStorageResource","wait":0}}] } 2012-09-25 15:59:10,431 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-9:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to NiciraNvpElement$$EnhancerByCGLIB$$3eb29c70 2012-09-25 15:59:10,431 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-9:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to XcpServerDiscoverer$$EnhancerByCGLIB$$cb61f98 2012-09-25 15:59:10,431 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-9:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PxeServerManagerImpl$$EnhancerByCGLIB$$803542e0 2012-09-25 15:59:10,431 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-9:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to ConsoleProxyManagerImpl$$EnhancerByCGLIB$$7666f719 2012-09-25 15:59:10,431 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-9:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to ExternalDhcpManagerImpl$$EnhancerByCGLIB$$b1df3ce6 2012-09-25 15:59:10,431 DEBUG [cloud.resource.ResourceManagerImpl] (AgentManager-Handler-9:null) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PremiumSecondaryStorageManagerImpl$$EnhancerByCGLIB$$b40686c1 2012-09-25 15:59:10,437 DEBUG [cloud.resource.ResourceState] (AgentManager-Handler-9:null) Resource state update: [id = 4; name = s-1-VM; old state = Creating; event = InternalCreated; new state = Enabled] 2012-09-25 15:59:10,437 DEBUG [cloud.host.Status] (AgentManager-Handler-9:null) Transition:[Resource state = Enabled, Agent event = AgentConnected, Host id = 4, name = s-1-VM] 2012-09-25 15:59:10,460 DEBUG [cloud.host.Status] (AgentManager-Handler-9:null) Agent status update: [id = 4; name = s-1-VM; old status = Creating; event = AgentConnected; new status = Connecting; old update count = 0; new update count = 1] 2012-09-25 15:59:10,460 DEBUG [agent.manager.ClusteredAgentManagerImpl] (AgentManager-Handler-9:null) create ClusteredAgentAttache for 4 2012-09-25 15:59:10,462 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: XcpServerDiscoverer$$EnhancerByCGLIB$$cb61f98 2012-09-25 15:59:10,462 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: ClusteredVirtualMachineManagerImpl$$EnhancerByCGLIB$$7c5727bd 2012-09-25 15:59:10,462 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: SecurityGroupListener 2012-09-25 15:59:10,462 INFO [network.security.SecurityGroupListener] (AgentManager-Handler-9:null) Received a host startup notification 2012-09-25 15:59:10,463 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: StoragePoolMonitor 2012-09-25 15:59:10,463 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: SecondaryStorageListener 2012-09-25 15:59:10,463 INFO [storage.secondary.SecondaryStorageListener] (AgentManager-Handler-9:null) Received a host startup notification com.cloud.agent.api.StartupSecondaryStorageCommand 2012-09-25 15:59:10,472 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998081: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100111, [{"SecStorageSetupCommand":{"secUrl":"nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu","certs":{},"wait":0}}] } 2012-09-25 15:59:10,566 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 4 2012-09-25 15:59:10,804 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (secstorage-1:null) Zone 1 is ready to launch secondary storage VM 2012-09-25 15:59:10,965 DEBUG [cloud.consoleproxy.ConsoleProxyManagerImpl] (consoleproxy-1:null) Zone 1 is ready to launch console proxy 2012-09-25 15:59:11,549 DEBUG [network.router.VirtualNetworkApplianceManagerImpl] (RouterStatusMonitor-1:null) Found 0 routers. 2012-09-25 15:59:12,430 DEBUG [agent.transport.Request] (AgentManager-Handler-11:null) Seq 4-173998081: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, [{"SecStorageSetupAnswer":{"_dir":"d24c72b9-3fe8-34b1-ad54-af523e0cfdb0","result":true,"details":"success","wait":0}}] } 2012-09-25 15:59:12,431 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998081: Received: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, { SecStorageSetupAnswer } } 2012-09-25 15:59:12,431 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Details from executing class com.cloud.agent.api.SecStorageSetupCommand: success 2012-09-25 15:59:12,433 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-11:null) Seq 4-173998081: No more commands found 2012-09-25 15:59:12,444 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (AgentManager-Handler-9:null) Successfully programmed secondary storage nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu in secondary storage VM s-1-VM 2012-09-25 15:59:12,450 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998082: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100011, [{"SecStorageFirewallCfgCommand":{"isAppendAIp":false,"wait":0}}] } 2012-09-25 15:59:12,514 DEBUG [agent.transport.Request] (AgentManager-Handler-12:null) Seq 4-173998082: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 10, [{"Answer":{"result":true,"wait":0}}] } 2012-09-25 15:59:12,514 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998082: Received: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 10, { Answer } } 2012-09-25 15:59:12,514 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (AgentManager-Handler-9:null) Successfully programmed firewall rules into s-1-VM 2012-09-25 15:59:12,519 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998083: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100111, [{"SecStorageVMSetupCommand":{"allowedInternalSites":[],"copyUserName":"cloud","copyPassword":"kB5dcuwbyfpjvwr","wait":0}}] } 2012-09-25 15:59:12,630 DEBUG [agent.transport.Request] (AgentManager-Handler-14:null) Seq 4-173998083: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, [{"Answer":{"result":true,"details":"","wait":0}}] } 2012-09-25 15:59:12,630 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-14:null) Seq 4-173998083: No more commands found 2012-09-25 15:59:12,630 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998083: Received: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, { Answer } } 2012-09-25 15:59:12,630 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Details from executing class com.cloud.agent.api.SecStorageVMSetupCommand: 2012-09-25 15:59:12,630 DEBUG [storage.secondary.SecondaryStorageManagerImpl] (AgentManager-Handler-9:null) Successfully programmed http auth into s-1-VM 2012-09-25 15:59:12,630 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: NetworkManagerImpl$$EnhancerByCGLIB$$a11338d9 2012-09-25 15:59:12,630 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: AgentMonitor$$EnhancerByCGLIB$$11a88b39 2012-09-25 15:59:12,631 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: DownloadListener 2012-09-25 15:59:12,635 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998084: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100111, [{"storage.ListTemplateCommand":{"secUrl":"nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu","wait":0}}] } 2012-09-25 15:59:12,783 DEBUG [agent.transport.Request] (AgentManager-Handler-15:null) Seq 4-173998084: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, [{"storage.ListTemplateAnswer":{"secUrl":"nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu","templateInfos":{"routing-3":{"templateName":"routing-3","installPath":"template/tmpl/1/3//9929242b-4048-4b3b-9d36-1052dc442d01.qcow2","size":725811200,"physicalSize":725811200,"id":3,"isPublic":true,"isCorrupted":false}},"result":true,"details":"success","wait":0}}] } 2012-09-25 15:59:12,783 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-15:null) Seq 4-173998084: No more commands found 2012-09-25 15:59:12,783 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998084: Received: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, { ListTemplateAnswer } } 2012-09-25 15:59:12,783 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Details from executing class com.cloud.agent.api.storage.ListTemplateCommand: success 2012-09-25 15:59:12,789 INFO [storage.download.DownloadMonitorImpl] (AgentManager-Handler-9:null) Template Sync found routing-3 already in the template host table 2012-09-25 15:59:12,798 INFO [storage.download.DownloadMonitorImpl] (AgentManager-Handler-9:null) Template Sync did not find centos55-x86_64 on the server 2, will request download shortly 2012-09-25 15:59:12,819 INFO [storage.download.DownloadMonitorImpl] (AgentManager-Handler-9:null) Template Sync did not find centos56-x86_64-xen on the server 2, will request download shortly 2012-09-25 15:59:12,828 INFO [storage.download.DownloadMonitorImpl] (AgentManager-Handler-9:null) Template Sync did not find centos53-x64 on the server 2, will request download shortly 2012-09-25 15:59:12,858 DEBUG [storage.download.DownloadMonitorImpl] (AgentManager-Handler-9:null) Template CentOS 5.5(64-bit) no GUI (KVM) needs to be downloaded to nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu 2012-09-25 15:59:12,869 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998085: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100011, [{"storage.DownloadCommand":{"hvm":false,"description":"CentOS 5.5(64-bit) no GUI (KVM)","checksum":"ed0e788280ff2912ea40f7f91ca7a249","maxDownloadSizeInBytes":53687091200,"id":4,"resourceType":"TEMPLATE","url":"http://download.cloud.com/releases/2.2.0/eec2209b-9875-3c8d-92be-c001bd8a0faf.qcow2.bz2","format":"QCOW2","accountId":1,"name":"centos55-x86_64","secUrl":"nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu","wait":0}}] } 2012-09-25 15:59:12,872 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998086: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100111, [{"storage.ListVolumeCommand":{"secUrl":"nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu","wait":0}}] } 2012-09-25 15:59:12,904 DEBUG [agent.transport.Request] (AgentManager-Handler-1:null) Seq 4-173998086: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, [{"storage.ListVolumeAnswer":{"secUrl":"nfs://10.102.123.240/cloudstack/abhinav/SS-ubuntu","templateInfos":{},"result":true,"details":"success","wait":0}}] } 2012-09-25 15:59:12,905 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-1:null) Seq 4-173998086: No more commands found 2012-09-25 15:59:12,905 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998086: Received: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, { ListVolumeAnswer } } 2012-09-25 15:59:12,905 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Details from executing class com.cloud.agent.api.storage.ListVolumeCommand: success 2012-09-25 15:59:12,912 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: UploadListener 2012-09-25 15:59:12,913 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: LocalStoragePoolListener$$EnhancerByCGLIB$$a3a4d76d 2012-09-25 15:59:12,913 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: StorageCapacityListener 2012-09-25 15:59:12,913 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: ComputeCapacityListener 2012-09-25 15:59:12,913 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: ConsoleProxyListener 2012-09-25 15:59:12,913 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: SshKeysDistriMonitor 2012-09-25 15:59:12,913 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: VpcVirtualNetworkApplianceManagerImpl$$EnhancerByCGLIB$$ad9d1c61 2012-09-25 15:59:12,914 DEBUG [agent.manager.AgentManagerImpl] (AgentManager-Handler-9:null) Sending Connect to listener: DirectNetworkStatsListener 2012-09-25 15:59:12,916 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998087: Sending { Cmd , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 100111, [{"ReadyCommand":{"dcId":1,"wait":0}}] } 2012-09-25 15:59:12,997 DEBUG [agent.transport.Request] (AgentManager-Handler-3:null) Seq 4-173998087: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, [{"ReadyAnswer":{"result":true,"wait":0}}] } 2012-09-25 15:59:12,998 DEBUG [agent.manager.AgentAttache] (AgentManager-Handler-3:null) Seq 4-173998087: No more commands found 2012-09-25 15:59:12,998 DEBUG [agent.transport.Request] (AgentManager-Handler-9:null) Seq 4-173998087: Received: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 110, { ReadyAnswer } } 2012-09-25 15:59:12,998 DEBUG [cloud.host.Status] (AgentManager-Handler-9:null) Transition:[Resource state = Enabled, Agent event = Ready, Host id = 4, name = s-1-VM] 2012-09-25 15:59:13,011 DEBUG [cloud.host.Status] (AgentManager-Handler-9:null) Agent status update: [id = 4; name = s-1-VM; old status = Connecting; event = Ready; new status = Up; old update count = 1; new update count = 2] 2012-09-25 15:59:18,632 DEBUG [agent.transport.Request] (AgentManager-Handler-5:null) Seq 4-173998085: Processing: { Ans: , MgmtId: 165676482560269, via: 4, Ver: v1, Flags: 10, [{"storage.DownloadAnswer":{"jobId":"8b863298-6a81-45b3-b1b5-686e21639ede","downloadPct":0,"errorString":" ","downloadStatus":"DOWNLOAD_IN_PROGRESS","downloadPath":"/mnt/SecStorage/d24c72b9-3fe8-34b1-ad54-af523e0cfdb0/template/tmpl/1/4/dnld4739241109688436760tmp_","templateSize":0,"templatePhySicalSize":0,"checkSum":"ed0e788280ff2912ea40f7f91ca7a249","result":false,"details":" ","wait":0}}] } [Edison] adding host is ok, system vm is started, template is downloading. Did you stop/start cloud-agent manually? Please let us know if these are expected and if they are then are they going to be documented somewhere. NOTE : This install was done on a freshly installed KVM host with Ubuntu running on it and a fresh Ubuntu management server. Thanks and regards, Abhinav
