incubator-cloudstack-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Abhinav Roy <abhinav....@citrix.com>
Subject RE: Few observations while installing agent on KVM host (ubuntu 12.04) and Management server on ubuntu 12.04
Date Tue, 25 Sep 2012 21:33:45 GMT
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



Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message