cloudstack-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "manasaveloori (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CLOUDSTACK-5688) NPE when the KVM host is rebooted on the upgraded environment
Date Tue, 31 Dec 2013 07:46:51 GMT

     [ https://issues.apache.org/jira/browse/CLOUDSTACK-5688?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

manasaveloori updated CLOUDSTACK-5688:
--------------------------------------

    Attachment: management-server.rar
                mysqldump421.dmp
                mysqldump43.dmp
                agent.log

> NPE when the KVM host is rebooted  on the upgraded environment
> --------------------------------------------------------------
>
>                 Key: CLOUDSTACK-5688
>                 URL: https://issues.apache.org/jira/browse/CLOUDSTACK-5688
>             Project: CloudStack
>          Issue Type: Bug
>      Security Level: Public(Anyone can view this level - this is the default.) 
>          Components: KVM, Upgrade
>    Affects Versions: 4.3.0
>         Environment: upgraded from 4.2.1 to 4.3
>            Reporter: manasaveloori
>            Priority: Critical
>             Fix For: 4.3.0
>
>         Attachments: agent.log, management-server.rar, mysqldump421.dmp, mysqldump43.dmp
>
>
> Steps:
> 1.	Have CS 4.2.1 with KVM host.---advanced zone.
> 2.	Upgrade the CS to 4.3.
> 3.	Reboot the KVM host(did not enable maintenance)
> 4.	The KVM host is connected and then disconnecting from the CS.
> Observing the following NPE in CS logs:
> 2013-12-31 18:03:38,127 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to BaremetalDhcpManagerImpl
> 2013-12-31 18:03:38,127 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to NetworkUsageManagerImpl
> 2013-12-31 18:03:38,127 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to BaremetalPxeManagerImpl
> 2013-12-31 18:03:38,128 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to PaloAltoExternalFirewallElement
> 2013-12-31 18:03:38,128 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to KvmServerDiscoverer
> 2013-12-31 18:03:38,172 DEBUG [c.c.r.ResourceState] (AgentConnectTaskPool-194:ctx-00137ad5)
Resource state update: [id = 1; name = RHLE64; old state = Enabled; event = InternalCreated;
new state = Enabled]
> 2013-12-31 18:03:38,173 DEBUG [c.c.h.Status] (AgentConnectTaskPool-194:ctx-00137ad5)
Transition:[Resource state = Enabled, Agent event = AgentConnected, Host id = 1, name = RHLE64]
> 2013-12-31 18:03:38,185 DEBUG [c.c.h.Status] (AgentConnectTaskPool-194:ctx-00137ad5)
Agent status update: [id = 1; name = RHLE64; old status = Alert; event = AgentConnected; new
status = Connecting; old update count = 390; new update count = 391]
> 2013-12-31 18:03:38,185 DEBUG [c.c.a.m.ClusteredAgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
create ClusteredAgentAttache for 1
> 2013-12-31 18:03:38,188 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: XcpServerDiscoverer
> 2013-12-31 18:03:38,189 DEBUG [c.c.h.x.d.XcpServerDiscoverer] (AgentConnectTaskPool-194:ctx-00137ad5)
Not XenServer so moving on.
> 2013-12-31 18:03:38,189 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: HypervServerDiscoverer
> 2013-12-31 18:03:38,189 DEBUG [c.c.h.h.d.HypervServerDiscoverer] (AgentConnectTaskPool-194:ctx-00137ad5)
Not Hyper-V hypervisor, so moving on.
> 2013-12-31 18:03:38,189 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: StoragePoolMonitor
> 2013-12-31 18:03:38,202 DEBUG [c.c.s.l.StoragePoolMonitor] (AgentConnectTaskPool-194:ctx-00137ad5)
Host 1 connected, sending down storage pool information ...
> 2013-12-31 18:03:38,205 DEBUG [c.c.s.StorageManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Adding pool null to  host 1
> 2013-12-31 18:03:38,215 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-194:ctx-00137ad5)
Seq 1-920387585: Sending  { Cmd , MgmtId: 6758231703598, via: 1(RHLE64), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.ModifyStoragePoolCommand":{"add":true,"pool":{"id":1,"uuid":"efbe1d5a-12c4-3a30-bef6-a219dfe81249","host":"10.147.40.27","path":"/export/home/manasa/primaryKVM","port":2049,"type":"NetworkFilesystem"},"localPath":"/mnt//efbe1d5a-12c4-3a30-bef6-a219dfe81249","wait":0}}]
}
> 2013-12-31 18:03:38,220 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null)
Ping from 1
> 2013-12-31 18:03:38,228 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-6:null)
Not processing PingRoutingCommand for agent id=0; can't find the host in the DB
> 2013-12-31 18:03:38,233 DEBUG [c.c.a.t.Request] (AgentManager-Handler-4:null) Seq 1-920387585:
Processing:  { Ans: , MgmtId: 6758231703598, via: 1, Ver: v1, Flags: 10, [{"com.cloud.agent.api.ModifyStoragePoolAnswer":{"poolInfo":{"host":"10.147.40.27","localPath":"/mnt//efbe1d5a-12c4-3a30-bef6-a219dfe81249","hostPath":"/export/home/manasa/primaryKVM","poolType":"NetworkFilesystem","capacityBytes":52844687360,"availableBytes":40225341440},"templateInfo":{},"result":true,"wait":0}}]
}
> 2013-12-31 18:03:38,234 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-194:ctx-00137ad5)
Seq 1-920387585: Received:  { Ans: , MgmtId: 6758231703598, via: 1, Ver: v1, Flags: 10, {
ModifyStoragePoolAnswer } }
> 2013-12-31 18:03:38,273 INFO  [o.a.c.s.d.p.DefaultHostListener] (AgentConnectTaskPool-194:ctx-00137ad5)
Connection established between org.apache.cloudstack.storage.datastore.PrimaryDataStoreImpl@22daf59c
host + 1
> 2013-12-31 18:03:38,283 DEBUG [c.c.s.StorageManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Successfully set Capacity - 105689374720 for capacity type - 3 , DataCenterId - 1, HostOrPoolId
- 1, PodId null
> 2013-12-31 18:03:38,283 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: DeploymentPlanningManagerImpl
> 2013-12-31 18:03:38,284 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: NetworkOrchestrator
> 2013-12-31 18:03:38,286 DEBUG [o.a.c.e.o.NetworkOrchestrator] (AgentConnectTaskPool-194:ctx-00137ad5)
Host's hypervisorType is: KVM
> 2013-12-31 18:03:38,293 DEBUG [o.a.c.e.o.NetworkOrchestrator] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending CheckNetworkCommand to check the Network is setup correctly on Agent
> 2013-12-31 18:03:38,306 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-194:ctx-00137ad5)
Seq 1-920387586: Sending  { Cmd , MgmtId: 6758231703598, via: 1(RHLE64), Ver: v1, Flags: 100111,
[{"com.cloud.agent.api.CheckNetworkCommand":{"networkInfoList":[{"physicalNetworkId":200}],"wait":0}}]
}
> 2013-12-31 18:03:38,360 DEBUG [c.c.a.t.Request] (AgentManager-Handler-9:null) Seq 1-920387586:
Processing:  { Ans: , MgmtId: 6758231703598, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.CheckNetworkAnswer":{"_reconnect":false,"result":true,"wait":0}}]
}
> 2013-12-31 18:03:38,360 DEBUG [c.c.a.t.Request] (AgentConnectTaskPool-194:ctx-00137ad5)
Seq 1-920387586: Received:  { Ans: , MgmtId: 6758231703598, via: 1, Ver: v1, Flags: 110, {
CheckNetworkAnswer } }
> 2013-12-31 18:03:38,360 DEBUG [o.a.c.e.o.NetworkOrchestrator] (AgentConnectTaskPool-194:ctx-00137ad5)
Network setup is correct on Agent
> 2013-12-31 18:03:38,361 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: VmwareManagerImpl
> 2013-12-31 18:03:38,362 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: SecondaryStorageListener
> 2013-12-31 18:03:38,362 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Connect to listener: ClusteredVirtualMachineManagerImpl
> 2013-12-31 18:03:38,362 DEBUG [c.c.v.VirtualMachineManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Received startup command from hypervisor host. host id: 1
> 2013-12-31 18:03:38,362 INFO  [c.c.v.VirtualMachinePowerStateSyncImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Reset VM power state sync for host: 1
> 2013-12-31 18:03:38,361 DEBUG [c.c.a.m.AgentAttache] (AgentManager-Handler-9:null) Seq
1-920387586: No more commands found
> 2013-12-31 18:03:38,383 DEBUG [c.c.v.VirtualMachineManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Found 8 VMs for host 1
> 2013-12-31 18:03:38,385 DEBUG [c.c.v.VirtualMachineManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
VM s-1-VM: cs state = Running and realState = Stopped
> 2013-12-31 18:03:38,385 DEBUG [c.c.v.VirtualMachineManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
VM s-1-VM: cs state = Running and realState = Stopped
> 2013-12-31 18:03:38,386 DEBUG [c.c.h.HighAvailabilityManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
VM does not require investigation so I'm marking it as Stopped: VM[SecondaryStorageVm|s-1-VM]
> 2013-12-31 18:03:38,386 WARN  [o.a.c.alerts] (AgentConnectTaskPool-194:ctx-00137ad5)
 alertType:: 19 // dataCenterId:: 1 // podId:: 1 // clusterId:: null // message:: VM (name:
s-1-VM, id: 1) stopped unexpectedly on host id:1, availability zone id:1, pod id:1
> 2013-12-31 18:03:38,396 DEBUG [c.c.h.HighAvailabilityManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
VM is not HA enabled so we're done.
> 2013-12-31 18:03:38,396 ERROR [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Monitor ClusteredVirtualMachineManagerImpl says there is an error in the connect process for
1 due to null
> java.lang.NullPointerException
>         at com.cloud.vm.VirtualMachineManagerImpl.advanceStop(VirtualMachineManagerImpl.java:1264)
>         at com.cloud.ha.HighAvailabilityManagerImpl.scheduleRestart(HighAvailabilityManagerImpl.java:346)
>         at com.cloud.vm.VirtualMachineManagerImpl.compareState(VirtualMachineManagerImpl.java:2715)
>         at com.cloud.vm.VirtualMachineManagerImpl.fullHostSync(VirtualMachineManagerImpl.java:2278)
>         at com.cloud.vm.VirtualMachineManagerImpl.processConnect(VirtualMachineManagerImpl.java:2929)
>         at com.cloud.agent.manager.AgentManagerImpl.notifyMonitorsOfConnection(AgentManagerImpl.java:495)
>         at com.cloud.agent.manager.AgentManagerImpl.handleConnectedAgent(AgentManagerImpl.java:999)
>         at com.cloud.agent.manager.AgentManagerImpl.access$000(AgentManagerImpl.java:117)
>         at com.cloud.agent.manager.AgentManagerImpl$HandleAgentConnectTask.runInContext(AgentManagerImpl.java:1082)
>         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.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
>         at java.lang.Thread.run(Thread.java:722)
> 2013-12-31 18:03:38,398 INFO  [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Host 1 is disconnecting with event AgentDisconnected
> 2013-12-31 18:03:38,401 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
The next status of agent 1is Alert, current status is Connecting
> 2013-12-31 18:03:38,402 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Deregistering link for 1 with state Alert
> 2013-12-31 18:03:38,402 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Remove Agent : 1
> 2013-12-31 18:03:38,402 DEBUG [c.c.a.m.ConnectedAgentAttache] (AgentConnectTaskPool-194:ctx-00137ad5)
Processing Disconnect.
> 2013-12-31 18:03:38,403 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.hypervisor.xen.discoverer.XcpServerDiscoverer
> 2013-12-31 18:03:38,403 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.hypervisor.hyperv.discoverer.HypervServerDiscoverer
> 2013-12-31 18:03:38,403 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.storage.listener.StoragePoolMonitor
> 2013-12-31 18:03:38,403 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.deploy.DeploymentPlanningManagerImpl
> 2013-12-31 18:03:38,403 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: org.apache.cloudstack.engine.orchestration.NetworkOrchestrator
> 2013-12-31 18:03:38,403 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.hypervisor.vmware.manager.VmwareManagerImpl
> 2013-12-31 18:03:38,404 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.storage.secondary.SecondaryStorageListener
> 2013-12-31 18:03:38,404 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.vm.ClusteredVirtualMachineManagerImpl
> 2013-12-31 18:03:38,404 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.network.security.SecurityGroupListener
> 2013-12-31 18:03:38,404 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.consoleproxy.ConsoleProxyListener
> 2013-12-31 18:03:38,407 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.network.NetworkUsageManagerImpl$DirectNetworkStatsListener
> 2013-12-31 18:03:38,407 DEBUG [c.c.n.NetworkUsageManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Disconnected called on 1 with status Alert
> 2013-12-31 18:03:38,407 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.storage.LocalStoragePoolListener
> 2013-12-31 18:03:38,408 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-194:ctx-00137ad5)
Sending Disconnect to listener: com.cloud.agent.manager.AgentManager
> The KVM host will be in Alert state:
> The log snippet from agent log:
> 2013-12-31 13:06:17,978 INFO  [cloud.agent.Agent] (Agent-Handler-1:null) Reconnecting...
> 2013-12-31 13:06:17,979 INFO  [utils.nio.NioClient] (Agent-Selector:null) Connecting
to 10.147.38.164:8250
> 2013-12-31 13:06:18,070 INFO  [utils.nio.NioClient] (Agent-Selector:null) SSL: Handshake
done
> 2013-12-31 13:06:18,070 INFO  [utils.nio.NioClient] (Agent-Selector:null) Connected to
10.147.38.164:8250
> 2013-12-31 13:06:18,124 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Proccess agent
startup answer, agent id = 0
> 2013-12-31 13:06:18,125 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Set agent id
0
> 2013-12-31 13:06:18,125 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Startup Response
Received: agent id = 0
> 2013-12-31 13:06:23,070 INFO  [cloud.agent.Agent] (Agent-Handler-1:null) Connected to
the server
> 2013-12-31 13:06:23,378 INFO  [cloud.agent.Agent] (Agent-Handler-1:null) Lost connection
to the server. Dealing with the remaining commands...
> 2013-12-31 13:06:28,379 INFO  [cloud.agent.Agent] (Agent-Handler-1:null) Reconnecting...
> 2013-12-31 13:06:28,380 INFO  [utils.nio.NioClient] (Agent-Selector:null) Connecting
to 10.147.38.164:8250
> 2013-12-31 13:06:28,473 INFO  [utils.nio.NioClient] (Agent-Selector:null) SSL: Handshake
done
> 2013-12-31 13:06:28,473 INFO  [utils.nio.NioClient] (Agent-Selector:null) Connected to
10.147.38.164:8250
> 2013-12-31 13:06:28,528 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Proccess agent
startup answer, agent id = 0
> 2013-12-31 13:06:28,528 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Set agent id
0
> 2013-12-31 13:06:28,529 INFO  [cloud.agent.Agent] (Agent-Handler-2:null) Startup Response
Received: agent id = 0
> Attaching the MS and agent logs.
> Dumps before and after upgrade.



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

Mime
View raw message