You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@cloudstack.apache.org by "Rajani Karuturi (JIRA)" <ji...@apache.org> on 2015/05/15 11:44:00 UTC
[jira] [Reopened] (CLOUDSTACK-8183) Exceptions from 4.3.2 to 4.5.0
upgrade, logs fill up disk very fast
[ https://issues.apache.org/jira/browse/CLOUDSTACK-8183?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Rajani Karuturi reopened CLOUDSTACK-8183:
-----------------------------------------
> Exceptions from 4.3.2 to 4.5.0 upgrade, logs fill up disk very fast
> -------------------------------------------------------------------
>
> Key: CLOUDSTACK-8183
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-8183
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the default.)
> Affects Versions: 4.5.0
> Reporter: Rohit Yadav
> Assignee: Rohit Yadav
> Priority: Blocker
> Fix For: 4.5.0, 4.6.0
>
>
> Exceptions see when 4.3.2 upgraded to 4.5.0:
> A lot of logs
> 2015-01-27 16:14:15,161 DEBUG [c.c.s.StatsCollector] (StatsCollector-3:ctx-afb47a0b) StorageCollector is running...
> 2015-01-27 16:14:15,165 DEBUG [c.c.a.m.ClusteredAgentAttache] (StatsCollector-3:ctx-afb47a0b) Seq 1-9188469139742654471: Forwarding null to 279278805450840
> 2015-01-27 16:14:15,166 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-7:null) Seq 1-9188469139742654471: Routing from 279278805450939
> 2015-01-27 16:14:15,166 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-7:null) Seq 1-9188469139742654471: Link is closed
> 2015-01-27 16:14:15,166 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-7:null) Seq 1-9188469139742654471: MgmtId 279278805450939: Req: Resource [Host:1] is unreachable: Host 1: Link is closed
> 2015-01-27 16:14:15,166 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-7:null) Seq 1--1: MgmtId 279278805450939: Req: Routing to peer
> 2015-01-27 16:14:15,167 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-8:null) Seq 1--1: MgmtId 279278805450939: Req: Cancel request received
> 2015-01-27 16:14:15,167 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-8:null) Seq 1-9188469139742654471: Cancelling.
> 2015-01-27 16:14:15,167 DEBUG [c.c.a.m.AgentAttache] (StatsCollector-3:ctx-afb47a0b) Seq 1-9188469139742654471: Waiting some more time because this is the current command
> 2015-01-27 16:14:15,167 DEBUG [c.c.a.m.AgentAttache] (StatsCollector-3:ctx-afb47a0b) Seq 1-9188469139742654471: Waiting some more time because this is the current command
> 2015-01-27 16:14:15,167 INFO [c.c.u.e.CSExceptionErrorCode] (StatsCollector-3:ctx-afb47a0b) Could not find exception: com.cloud.exception.OperationTimedoutException in error code list for exceptions
> 2015-01-27 16:14:15,167 WARN [c.c.a.m.AgentAttache] (StatsCollector-3:ctx-afb47a0b) Seq 1-9188469139742654471: Timed out on null
> 2015-01-27 16:14:15,167 DEBUG [c.c.a.m.AgentAttache] (StatsCollector-3:ctx-afb47a0b) Seq 1-9188469139742654471: Cancelling.
> 2015-01-27 16:14:15,167 DEBUG [o.a.c.s.RemoteHostEndPoint] (StatsCollector-3:ctx-afb47a0b) Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 9188469139742654471 to Host 1 timed out after 3600
> 2015-01-27 16:14:15,167 ERROR [c.c.s.StatsCollector] (StatsCollector-3:ctx-afb47a0b) Error trying to retrieve storage stats
> com.cloud.utils.exception.CloudRuntimeException: Failed to send command, due to Agent:1, com.cloud.exception.OperationTimedoutException: Commands 9188469139742654471 to Host 1 timed out after 3600
> at org.apache.cloudstack.storage.RemoteHostEndPoint.sendMessage(RemoteHostEndPoint.java:133)
> at com.cloud.server.StatsCollector$StorageCollector.runInContext(StatsCollector.java:623)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable$1.run(ManagedContextRunnable.java:49)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
> at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
> at org.apache.cloudstack.managed.context.ManagedContextRunnable.run(ManagedContextRunnable.java:46)
> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> 2015-01-27 16:14:15,651 DEBUG [c.c.s.StatsCollector] (StatsCollector-1:ctx-83c6ce44) HostStatsCollector is running...
> 2015-01-27 16:14:15,874 DEBUG [c.c.a.t.Request] (StatsCollector-1:ctx-83c6ce44) Seq 2-2471631770496270373: Received: { Ans: , MgmtId: 279278805450939, via: 2, Ver: v1, Flags: 10, { GetHostStatsAnswer } }
> 2015-01-27 16:14:19,585 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f0109b91) Begin cleanup expired async-jobs
> 2015-01-27 16:14:19,588 INFO [o.a.c.f.j.i.AsyncJobManagerImpl] (AsyncJobMgr-Heartbeat-1:ctx-f0109b91) End cleanup expired async-jobs
> 2015-01-27 16:14:20,975 DEBUG [c.c.c.ConsoleProxyManagerImpl] (consoleproxy-1:ctx-375b4baa) Zone 1 is ready to launch console proxy
> 2015-01-27 16:14:23,472 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-10:null) Ping from 5
> 2015-01-27 16:14:23,686 WARN [c.c.u.n.Link] (AgentManager-Selector:null) SSL: Fail to find the generated keystore. Loading fail-safe one to continue.
> 2015-01-27 16:14:24,137 DEBUG [c.c.a.t.Request] (AgentManager-Handler-13:null) Seq -1-0: Scheduling the first command { Cmd , MgmtId: -1, via: -1, Ver: v1, Flags: 101, [{"com.cloud.agent.api.StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-6-VM-PremiumSecondaryStorageResource","name":"s-6-VM","version":"4.5.0","iqn":"NoIqn","publicIpAddress":"192.168.10.39","publicNetmask":"255.255.0.0","publicMacAddress":"06:40:06:00:01:0f","privateIpAddress":"192.168.11.219","privateMacAddress":"06:fd:f0:00:00:d2","privateNetmask":"255.255.0.0","storageIpAddress":"192.168.11.219","storageNetmask":"255.255.0.0","storageMacAddress":"06:fd:f0:00:00:d2","resourceName":"PremiumSecondaryStorageResource","wait":0}}] }
> 2015-01-27 16:14:24,138 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq -1-0: Processing the first command { Cmd , MgmtId: -1, via: -1, Ver: v1, Flags: 101, [{"com.cloud.agent.api.StartupSecondaryStorageCommand":{"type":"SecondaryStorage","dataCenter":"1","pod":"1","guid":"s-6-VM-PremiumSecondaryStorageResource","name":"s-6-VM","version":"4.5.0","iqn":"NoIqn","publicIpAddress":"192.168.10.39","publicNetmask":"255.255.0.0","publicMacAddress":"06:40:06:00:01:0f","privateIpAddress":"192.168.11.219","privateMacAddress":"06:fd:f0:00:00:d2","privateNetmask":"255.255.0.0","storageIpAddress":"192.168.11.219","storageNetmask":"255.255.0.0","storageMacAddress":"06:fd:f0:00:00:d2","resourceName":"PremiumSecondaryStorae","wait":0}}] }
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to BaremetalDhcpManagerImpl
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to BaremetalPxeManagerImpl
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to NetworkUsageManagerImpl
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to NuageVspElement
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to Ovs
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PaloAltoExternalFirewallElement
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to GloboDnsElement
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to KvmServerDiscoverer
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to F5ExternalLoadBalancerElement
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to JuniperSRXExternalFirewallElement
> 2015-01-27 16:14:24,140 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PremiumSecondaryStorageManagerImpl
> 2015-01-27 16:14:24,196 DEBUG [c.c.r.ResourceState] (AgentConnectTaskPool-3:ctx-3f8632e8) Resource state update: [id = 6; name = s-6-VM; old state = Creating; event = InternalCreated; new state = Enabled]
> 2015-01-27 16:14:24,196 DEBUG [c.c.h.Status] (AgentConnectTaskPool-3:ctx-3f8632e8) Transition:[Resource state = Enabled, Agent event = AgentConnected, Host id = 6, name = s-6-VM]
> 2015-01-27 16:14:24,216 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 5-31: Processing Seq 5-31: { Cmd , MgmtId: -1, via: 5, Ver: v1, Flags: 11, [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":5,"_loadInfo":"{\n \"connections\": [\n {\n \"id\": 2,\n \"clientInfo\": \"\",\n \"host\": \"192.168.1.11\",\n \"port\": 5902,\n \"tag\": \"22ed5c36-4f64-4c63-b9d0-ec895927dc30\",\n \"createTime\": 1422355451513,\n \"lastUsedTime\": 1422355463966\n },\n {\n \"id\": 1,\n \"clientInfo\": \"\",\n \"host\": \"192.168.1.11\",\n \"port\": 5900,\n \"tag\": \"e6206a8c-0a39-4ddd-9266-776b9eac25c1\",\n \"createTime\": 1422355346774,\n \"lastUsedTime\": 1422355350511\n }\n ]\n}","wait":0}}] }
> 2015-01-27 16:14:24,223 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) create ClusteredAgentAttache for 6
> 2015-01-27 16:14:24,224 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: XcpServerDiscoverer
> 2015-01-27 16:14:24,229 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) Ping from 6
> 2015-01-27 16:14:24,229 INFO [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) PingMap for agent: 6 will not be updated because agent is no longer in the PingMap
> 2015-01-27 16:14:24,250 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-11:null) SeqA 5-31: Sending Seq 5-31: { Ans: , MgmtId: 279278805450939, via: 5, Ver: v1, Flags: 100010, [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-01-27 16:14:24,849 DEBUG [c.c.a.t.Request] (AgentManager-Handler-1:null) Seq 2-2471631770496270367: Processing: { Ans: , MgmtId: 279278805450939, via: 2, Ver: v1, Flags: 10, [{"com.cloud.agent.api.StartAnswer":{"vm":{"id":6,"name":"s-6-VM","type":"SecondaryStorageVm","cpus":1,"minSpeed":500,"maxSpeed":500,"minRam":536870912,"maxRam":536870912,"arch":"x86_64","os":"Debian GNU/Linux 7(64-bit)","platformEmulator":"Debian GNU/Linux 7(64-bit)","bootArgs":" template=domP type=secstorage host=192.168.1.11 port=8250 name=s-6-VM zone=1 pod=1 guid=s-6-VM resource=com.cloud.storage.resource.PremiumSecondaryStorageResource instance=SecStorage sslcopy=false role=templateProcessor mtu=1500 eth2ip=192.168.10.39 eth2mask=255.255.0.0 gateway=192.168.1.1 eth0ip=169.254.3.165 eth0mask=255.255.0.0 eth1ip=192.168.11.219 eth1mask=255.255.0.0 mgmtcidr=192.168.0.0/16 localgw=192.168.1.1 private.network.device=eth1 eth3ip=192.168.11.110 eth3mask=255.255.0.0 storageip=192.168.11.110 storagenetmask=255.255.0.0 storagegateway=192.168.1.1 internaldns1=192.168.1.1 dns1=8.8.8.8","enableHA":false,"limitCpuUse":false,"enableDynamicallyScaleVm":false,"vncPassword":"6+xC+1oUziatWgEcj/yNxA==","vncAddr":"192.168.1.11","params":{},"uuid":"525aea2c-876d-4484-aa06-fa42430200a7","disks":[{"data":{"org.apache.cloudstack.storage.to.VolumeObjectTO":{"uuid":"f7dd6da2-7158-48d2-8a29-813954421b97","volumeType":"ROOT","dataStore":{"org.apache.cloudstack.storage.to.PrimaryDataStoreTO":{"uuid":"49419c77-0b0b-32e7-837e-ae1523734a6b","id":3,"poolType":"NetworkFilesystem","host":"192.168.1.11","path":"/ssd","port":2049,"url":"NetworkFilesystem://192.168.1.11/ssd/?ROLE=Primary&STOREUUID=49419c77-0b0b-32e7-837e-ae1523734a6b"}},"name":"ROOT-6","size":2621440000,"path":"f7dd6da2-7158-48d2-8a29-813954421b97","volumeId":7,"vmName":"s-6-VM","accountId":1,"format":"QCOW2","provisioningType":"THIN","id":7,"deviceId":0,"cacheMode":"NONE","hypervisorType":"KVM"}},"diskSeq":0,"path":"f7dd6da2-7158-48d2-8a29-813954421b97","type":"ROOT","_details":{"managed":"false","storagePort":"2049","storageHost":"192.168.1.11","volumeSize":"2621440000"}}],"nics":[{"deviceId":2,"networkRateMbps":-1,"defaultNic":true,"pxeDisable":true,"nicUuid":"0ec93171-101d-4bd8-a31e-d88431a26e5e","uuid":"50d60669-d427-4673-9cc7-c6aed037e5ea","ip":"192.168.10.39","netmask":"255.255.0.0","gateway":"192.168.1.1","mac":"06:40:06:00:01:0f","dns1":"8.8.8.8","broadcastType":"Native","type":"Guest","broadcastUri":"vlan://untagged","isSecurityGroupEnabled":false},{"deviceId":0,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"36ba736f-6400-4865-b74a-ad329191c794","uuid":"ee863916-f27b-4286-bd53-7557b144fbab","ip":"169.254.3.165","netmask":"255.255.0.0","gateway":"169.254.0.1","mac":"0e:00:a9:fe:03:a5","broadcastType":"LinkLocal","type":"Control","isSecurityGroupEnabled":false},{"deviceId":1,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"36ecb314-e8e8-4e6f-add1-28a4907ad859","uuid":"d689bc45-06ef-42d2-adea-a27afb877ed6","ip":"192.168.11.219","netmask":"255.255.0.0","gateway":"192.168.1.1","mac":"06:fd:f0:00:00:d2","broadcastType":"Native","type":"Management","isSecurityGroupEnabled":false},{"deviceId":3,"networkRateMbps":-1,"defaultNic":false,"pxeDisable":true,"nicUuid":"f7930e84-b322-4201-a3a7-d172fa6b4140","uuid":"1f06063b-80af-4632-bb1b-675381a61918","ip":"192.168.11.110","netmask":"255.255.0.0","gateway":"192.168.1.1","mac":"06:34:cc:00:00:65","broadcastType":"Native","type":"Storage","isSecurityGroupEnabled":false}]},"result":true,"wait":0}},{"com.cloud.agent.api.check.CheckSshAnswer":{"result":true,"wait":0}}] }
> 2015-01-27 16:14:24,849 DEBUG [c.c.a.t.Request] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Seq 2-2471631770496270367: Received: { Ans: , MgmtId: 279278805450939, via: 2, Ver: v1, Flags: 10, { StartAnswer, CheckSshAnswer } }
> 2015-01-27 16:14:24,936 DEBUG [c.c.c.CapacityManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) VM state transitted from :Starting to Running with event: OperationSucceededvm's original host id: 2 new host id: 2 host id before state transition: 2
> 2015-01-27 16:14:24,939 DEBUG [c.c.v.VirtualMachineManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Start completed for VM VM[SecondaryStorageVm|s-6-VM]
> 2015-01-27 16:14:24,940 DEBUG [c.c.v.VmWorkJobHandlerProxy] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Done executing VM work job: com.cloud.vm.VmWorkStart{"dcId":0,"userId":1,"accountId":1,"vmId":6,"handlerName":"VirtualMachineManagerImpl"}
> 2015-01-27 16:14:24,940 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Complete async job-211, jobStatus: SUCCEEDED, resultCode: 0, result: null
> 2015-01-27 16:14:24,940 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Publish async job-211 complete on message bus
> 2015-01-27 16:14:24,940 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Wake up jobs related to job-211
> 2015-01-27 16:14:24,940 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Update db status for job-211
> 2015-01-27 16:14:24,941 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211 ctx-43532571) Wake up jobs joined with job-211 and disjoin all subjobs created from job- 211
> 2015-01-27 16:14:24,969 DEBUG [c.c.v.VmWorkJobDispatcher] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211) Done with run of VM work job: com.cloud.vm.VmWorkStart for VM 6, job origin: 200
> 2015-01-27 16:14:24,969 DEBUG [o.a.c.f.j.i.AsyncJobManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211) Done executing com.cloud.vm.VmWorkStart for job-211
> 2015-01-27 16:14:24,971 DEBUG [o.a.c.f.j.i.SyncQueueManagerImpl] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211) Sync queue (6) is currently empty
> 2015-01-27 16:14:24,971 INFO [o.a.c.f.j.i.AsyncJobMonitor] (Work-Job-Executor-6:ctx-ecf451b1 job-200/job-211) Remove job-211 from job monitoring
> 2015-01-27 16:14:24,999 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-f2125c35) received secondary storage vm alert
> 2015-01-27 16:14:24,999 DEBUG [c.c.a.SecondaryStorageVmAlertAdapter] (secstorage-1:ctx-f2125c35) Secondary Storage Vm is up, zone: BlueZone, secStorageVm: s-6-VM, public IP: 192.168.10.39, private IP: 192.168.11.219
> 2015-01-27 16:14:25,000 WARN [o.a.c.alerts] (secstorage-1:ctx-f2125c35) alertType:: 19 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: Secondary Storage Vm up in zone: BlueZone, secStorageVm: s-6-VM, public IP: 192.168.10.39, private IP: 192.168.11.219
> 2015-01-27 16:14:25,027 INFO [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-f2125c35) Secondary storage vm s-6-VM is started
> 2015-01-27 16:14:25,027 INFO [o.a.c.s.PremiumSecondaryStorageManagerImpl] (secstorage-1:ctx-f2125c35) Primary secondary storage is not even started, wait until next turn
> 2015-01-27 16:14:25,032 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (secstorage-1:ctx-196f571a) Zone 1 is ready to launch secondary storage VM
> 2015-01-27 16:14:25,449 DEBUG [c.c.a.t.Request] (AgentManager-Handler-15:null) Seq 6-6712615244595724289: Processing: { Ans: , MgmtId: 279278805450939, via: 6, Ver: v1, Flags: 110, [{"com.cloud.agent.api.SecStorageSetupAnswer":{"_dir":"93975737-5df7-32ee-8d3e-1755cd84beea","result":true,"details":"success","wait":0}}] }
> 2015-01-27 16:14:25,449 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 6-6712615244595724289: Received: { Ans: , MgmtId: 279278805450939, via: 6, Ver: v1, Flags: 110, { SecStorageSetupAnswer } }
> 2015-01-27 16:14:25,449 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-15:null) Seq 6-6712615244595724289: No more commands found
> 2015-01-27 16:14:25,449 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Details from executing class com.cloud.agent.api.SecStorageSetupCommand: success
> 2015-01-27 16:14:25,462 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Successfully programmed secondary storage BlueSecondary in secondary storage VM s-6-VM
> 2015-01-27 16:14:25,468 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-3:null) Seq 1-9188469139742654472: Routing from 279278805450939
> 2015-01-27 16:14:25,468 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-3:null) Seq 1-9188469139742654472: Link is closed
> 2015-01-27 16:14:25,468 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-3:null) Seq 1-9188469139742654472: MgmtId 279278805450939: Req: Resource [Host:1] is unreachable: Host 1: Link is closed
> 2015-01-27 16:14:25,469 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-3:null) Seq 1--1: MgmtId 279278805450939: Req: Routing to peer
> 2015-01-27 16:14:25,469 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentManager-Handler-2:null) Seq 1--1: MgmtId 279278805450939: Req: Cancel request received
> 2015-01-27 16:14:25,469 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-2:null) Seq 1-9188469139742654472: Cancelling.
> 2015-01-27 16:14:25,469 DEBUG [c.c.a.m.AgentAttache] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 1-9188469139742654472: Waiting some more time because this is the current command
> 2015-01-27 16:14:25,469 DEBUG [c.c.a.m.AgentAttache] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 1-9188469139742654472: Waiting some more time because this is the current command
> 2015-01-27 16:14:25,469 INFO [c.c.u.e.CSExceptionErrorCode] (AgentConnectTaskPool-3:ctx-3f8632e8) Could not find exception: com.cloud.exception.OperationTimedoutException in error code list for exceptions
> 2015-01-27 16:14:25,470 WARN [c.c.a.m.AgentAttache] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 1-9188469139742654472: Timed out on Seq 1-9188469139742654472: { Cmd , MgmtId: 279278805450939, via: 1(s-65-VM), Ver: v1, Flags: 100011, [{"com.cloud.agent.api.SecStorageFirewallCfgCommand":{"portConfigs":[{"add":true,"sourceIp":"192.168.10.39","port":"80","intf":"eth2"}],"isAppendAIp":true,"wait":0}}] }
> 2015-01-27 16:14:25,470 DEBUG [c.c.a.m.AgentAttache] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 1-9188469139742654472: Cancelling.
> 2015-01-27 16:14:25,470 WARN [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Operation timed out: Commands 9188469139742654472 to Host 1 timed out after 3600
> 2015-01-27 16:14:25,470 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) failed to program firewall rules into secondary storage vm : s-65-VM
> 2015-01-27 16:14:25,473 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 6-6712615244595724290: Sending { Cmd , MgmtId: 279278805450939, via: 6(s-6-VM), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.SecStorageVMSetupCommand":{"allowedInternalSites":["0.0.0.0/0"],"copyUserName":"cloud","copyPassword":"gR6vawgkxihkijj","wait":0}}] }
> 2015-01-27 16:14:25,528 DEBUG [c.c.a.t.Request] (AgentManager-Handler-4:null) Seq 6-6712615244595724290: Processing: { Ans: , MgmtId: 279278805450939, via: 6, Ver: v1, Flags: 110, [{"com.cloud.agent.api.Answer":{"result":true,"details":"","wait":0}}] }
> 2015-01-27 16:14:25,528 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-4:null) Seq 6-6712615244595724290: No more commands found
> 2015-01-27 16:14:25,528 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 6-6712615244595724290: Received: { Ans: , MgmtId: 279278805450939, via: 6, Ver: v1, Flags: 110, { Answer } }
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Details from executing class com.cloud.agent.api.SecStorageVMSetupCommand:
> 2015-01-27 16:14:25,529 DEBUG [o.a.c.s.SecondaryStorageManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Successfully programmed http auth into s-6-VM
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: DeploymentPlanningManagerImpl
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: SecurityGroupListener
> 2015-01-27 16:14:25,529 INFO [c.c.n.s.SecurityGroupListener] (AgentConnectTaskPool-3:ctx-3f8632e8) Received a host startup notification
> 2015-01-27 16:14:25,529 INFO [c.c.n.s.SecurityGroupListener] (AgentConnectTaskPool-3:ctx-3f8632e8) Received a host startup notification
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: StoragePoolMonitor
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: NetworkOrchestrator
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: ClusteredVirtualMachineManagerImpl
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: ConsoleProxyListener
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: BehindOnPingListener
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: SshKeysDistriMonitor
> 2015-01-27 16:14:25,529 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: VirtualNetworkApplianceManagerImpl
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: StorageCapacityListener
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: ComputeCapacityListener
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: DirectNetworkStatsListener
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: UploadListener
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: SshKeysDistriMonitor
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: VpcVirtualNetworkApplianceManagerImpl
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: LocalStoragePoolListener
> 2015-01-27 16:14:25,530 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-3:ctx-3f8632e8) Sending Connect to listener: DownloadListener
> 2015-01-27 16:14:25,535 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentConnectTaskPool-3:ctx-3f8632e8) Seq 1-9188469139742654473: Forwarding Seq 1-9188469139742654473: { Cmd , MgmtId: 279278805450939, via: 1(s-65-VM), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.ListVolumeCommand":{"store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.11/export/secondary","_role":"Image"}},"secUrl":"nfs://192.168.1.11/export/secondary","wait":0}}] } to 279278805450840
> 2015-01-27 16:14:25,537 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-5:null) Seq 1-9188469139742654473: Forwarding Seq 1-9188469139742654473: { Cmd , MgmtId: 279278805450939, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.ListVolumeCommand":{"store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.11/export/secondary","_role":"Image"}},"secUrl":"nfs://192.168.1.11/export/secondary","wait":0}}] } to 279278805450840
> 2015-01-27 16:14:25,539 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-6:null) Seq 1-9188469139742654473: Forwarding Seq 1-9188469139742654473: { Cmd , MgmtId: 279278805450939, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.ListVolumeCommand":{"store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.11/export/secondary","_role":"Image"}},"secUrl":"nfs://192.168.1.11/export/secondary","wait":0}}] } to 279278805450840
> 2015-01-27 16:14:25,540 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-7:null) Seq 1-9188469139742654473: Forwarding Seq 1-9188469139742654473: { Cmd , MgmtId: 279278805450939, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.ListVolumeCommand":{"store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.11/export/secondary","_role":"Image"}},"secUrl":"nfs://192.168.1.11/export/secondary","wait":0}}] } to 279278805450840
> After this, the following is seen in the log filling up the logs and disk:
> 2015-01-27 16:21:44,313 DEBUG [c.c.a.m.ClusteredAgentAttache] (AgentManager-Handler-10:null) Seq 1-2130202623746244610: Forwarding Seq 1-2130202623746244610: { Cmd , MgmtId: 279278805451241, via: 1, Ver: v1, Flags: 100111, [{"com.cloud.agent.api.storage.ListVolumeCommand":{"store":{"com.cloud.agent.api.to.NfsTO":{"_url":"nfs://192.168.1.11/export/secondary","_role":"Image"}},"secUrl":"nfs://192.168.1.11/export/secondary","wait":0}}] } to 279278805450840
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)