[
https://issues.apache.org/jira/browse/CLOUDSTACK-9208?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15082883#comment-15082883
]
ASF GitHub Bot commented on CLOUDSTACK-9208:
--------------------------------------------
Github user kansal commented on the pull request:
https://github.com/apache/cloudstack/pull/1307#issuecomment-168977391
@DaanHoogland With the current code, even if the VM is in poweroff(or power
report missing) state and stopped state in DB, and receives a stop command, it
gets this error. (Atleast, This was the case I encountered in my local setup).
One argument could be why are we sending(or trying to send) the stop
command even if the VM is in the the poweroff state (on host) and stopped state
(in DB).
We can remove sending of command in the poweroff state but only once we
have verified that host id is set to null only in stopped case in DB i.e. "host
id is NULL" and "vm in stopped state" are analogous.
I can check the code and update you. Are there any scenarios that you are
aware of?
> Assertion Error in VM_POWER_STATE handler.
> ------------------------------------------
>
> Key: CLOUDSTACK-9208
> URL: https://issues.apache.org/jira/browse/CLOUDSTACK-9208
> Project: CloudStack
> Issue Type: Bug
> Security Level: Public(Anyone can view this level - this is the
> default.)
> Reporter: Kshitij Kansal
> Assignee: Kshitij Kansal
> Priority: Minor
>
> 1. Enable the assertions.
> LOG
> 2015-12-31 04:09:06,687 DEBUG [c.c.n.r.VirtualNetworkApplianceManagerImpl]
> (RouterStatusMonitor-1:ctx-981a85d4) (logid:863754b8) Found 0 networks to
> update RvR status.
> 2015-12-31 04:09:07,394 DEBUG [c.c.a.m.DirectAgentAttache]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) Ping from 5(10.147.40.18)
> 2015-12-31 04:09:07,394 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) Process host VM state
> report from ping process. host: 5
> 2015-12-31 04:09:07,416 INFO [c.c.v.VirtualMachinePowerStateSyncImpl]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) Unable to find matched
> VM in CloudStack DB. name: New Virtual Machine
> 2015-12-31 04:09:07,420 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) Process VM state report.
> host: 5, number of records in report: 5
> 2015-12-31 04:09:07,420 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) VM state report. host:
> 5, vm id: 69, power state: PowerOff
> 2015-12-31 04:09:07,530 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) VM state report is
> updated. host: 5, vm id: 69, power state: PowerOff
> 2015-12-31 04:09:07,540 INFO [c.c.v.VirtualMachineManagerImpl]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) VM r-69-VM is at Stopped
> and we received a power-off report while there is no pending jobs on it
> 2015-12-31 04:09:07,541 ERROR [o.a.c.f.m.MessageDispatcher]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) Unexpected exception
> when calling
> com.cloud.vm.ClusteredVirtualMachineManagerImpl.HandlePowerStateReport
> java.lang.reflect.InvocationTargetException
> 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:606)
> at
> org.apache.cloudstack.framework.messagebus.MessageDispatcher.dispatch(MessageDispatcher.java:75)
> at
> org.apache.cloudstack.framework.messagebus.MessageDispatcher.onPublishMessage(MessageDispatcher.java:45)
> at
> org.apache.cloudstack.framework.messagebus.MessageBusBase$SubscriptionNode.notifySubscribers(MessageBusBase.java:441)
> at
> org.apache.cloudstack.framework.messagebus.MessageBusBase.publish(MessageBusBase.java:178)
> at
> com.cloud.vm.VirtualMachinePowerStateSyncImpl.processReport(VirtualMachinePowerStateSyncImpl.java:87)
> at
> com.cloud.vm.VirtualMachinePowerStateSyncImpl.processHostVmStatePingReport(VirtualMachinePowerStateSyncImpl.java:70)
> at
> com.cloud.vm.VirtualMachineManagerImpl.processCommands(VirtualMachineManagerImpl.java:2879)
> at
> com.cloud.agent.manager.AgentManagerImpl.handleCommands(AgentManagerImpl.java:309)
> at
> com.cloud.agent.manager.DirectAgentAttache$PingTask.runInContext(DirectAgentAttache.java:192)
> 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)
> Caused by: java.lang.AssertionError: Who's not checking the agent id before
> sending? ... (finger wagging)
> at com.cloud.agent.manager.AgentManagerImpl.send(AgentManagerImpl.java:429)
> at com.cloud.agent.manager.AgentManagerImpl.send(AgentManagerImpl.java:364)
> at
> com.cloud.vm.VirtualMachineManagerImpl.sendStop(VirtualMachineManagerImpl.java:1339)
> ... 27 more
> 2015-12-31 04:09:07,543 WARN [c.c.a.m.DirectAgentAttache]
> (DirectAgentCronJob-3:ctx-3ba82e46) (logid:02dcbd48) Unable to complete the
> ping task
> java.lang.RuntimeException: InvocationTargetException when invoking event
> handler for subject: vm.powerstate
> at
> org.apache.cloudstack.framework.messagebus.MessageDispatcher.dispatch(MessageDispatcher.java:84)
> at
> org.apache.cloudstack.framework.messagebus.MessageDispatcher.onPublishMessage(MessageDispatcher.java:45)
> at
> org.apache.cloudstack.framework.messagebus.MessageBusBase$SubscriptionNode.notifySubscribers(MessageBusBase.java:441)
> at
> org.apache.cloudstack.framework.messagebus.MessageBusBase.publish(MessageBusBase.java:178)
> at
> com.cloud.vm.VirtualMachinePowerStateSyncImpl.processReport(VirtualMachinePowerStateSyncImpl.java:87)
> at
> com.cloud.vm.VirtualMachinePowerStateSyncImpl.processHostVmStatePingReport(VirtualMachinePowerStateSyncImpl.java:70)
> at
> com.cloud.vm.VirtualMachineManagerImpl.processCommands(VirtualMachineManagerImpl.java:2879)
> at
> com.cloud.agent.manager.AgentManagerImpl.handleCommands(AgentManagerImpl.java:309)
> at
> com.cloud.agent.manager.DirectAgentAttache$PingTask.runInContext(DirectAgentAttache.java:192)
> 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-12-31 04:09:10,972 DEBUG [c.c.c.ConsoleProxyManagerImpl]
> (consoleproxy-1:ctx-ff090f45) (logid:38f2d7f8) Zone 1 is ready to launch
> console proxy
> 2015-12-31 04:09:10,973 DEBUG [c.c.c.ConsoleProxyManagerImpl]
> (consoleproxy-1:ctx-ff090f45) (logid:38f2d7f8) Zone 2 is not ready to launch
> console proxy yet
> 2015-12-31 04:09:11,153 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
> (secstorage-1:ctx-4d8194c3) (logid:bdeb5f78) Zone 1 is ready to launch
> secondary storage VM
> 2015-12-31 04:09:11,166 DEBUG [o.a.c.s.SecondaryStorageManagerImpl]
> (secstorage-1:ctx-4d8194c3) (logid:bdeb5f78) Zone 2 is not ready to launch
> secondary storage VM yet
> 2015-12-31 04:09:11,551 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-8:null) (logid SeqA 2-481000: Processing Seq 2-481000:
> { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":45,"_loadInfo":"
> {\n \"connections\": []\n}
> ","wait":0}}] }
> 2015-12-31 04:09:11,557 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-8:null) (logid SeqA 2-481000: Sending Seq 2-481000: {
> Ans: , MgmtId: 7020459589851, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-12-31 04:09:16,474 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-904c4f5a) (logid:7376bd5c) Begin cleanup expired
> async-jobs
> 2015-12-31 04:09:16,488 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-904c4f5a) (logid:7376bd5c) End cleanup expired
> async-jobs
> 2015-12-31 04:09:21,589 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-9:null) (logid SeqA 2-481001: Processing Seq 2-481001:
> { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":45,"_loadInfo":"
> {\n \"connections\": []\n}
> ","wait":0}}] }
> 2015-12-31 04:09:21,596 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-9:null) (logid SeqA 2-481001: Sending Seq 2-481001: {
> Ans: , MgmtId: 7020459589851, via: 2, Ver: v1, Flags: 100010,
> [{"com.cloud.agent.api.AgentControlAnswer":{"result":true,"wait":0}}] }
> 2015-12-31 04:09:26,474 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-9f3afa6f) (logid:31dbd0f4) Begin cleanup expired
> async-jobs
> 2015-12-31 04:09:26,486 INFO [o.a.c.f.j.i.AsyncJobManagerImpl]
> (AsyncJobMgr-Heartbeat-1:ctx-9f3afa6f) (logid:31dbd0f4) End cleanup expired
> async-jobs
> 2015-12-31 04:09:31,589 DEBUG [c.c.a.m.AgentManagerImpl]
> (AgentManager-Handler-10:null) (logid SeqA 2-481002: Processing Seq 2-481002:
> { Cmd , MgmtId: -1, via: 2, Ver: v1, Flags: 11,
> [{"com.cloud.agent.api.ConsoleProxyLoadReportCommand":{"_proxyVmId":45,"_loadInfo":"
> {\n \"connections\": []\n}
> ","wait":0}}] }
> 2015-12-31 04:09:31,596 DEBUG [c.c.a.m.AgentManagerImpl] (AgentManager-Handler
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
