[CLOUDSTACK-7560] Usage Event is not generated when VM state is transited from RUNNING to STOPPED directly

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 4.5.0
• Fix Version/s: 4.5.0
• Component/s: Usage
• Security Level: Public (Anyone can view this level - this is the default.)
• Assignee: Damodar Reddy T
• Reporter: Damodar Reddy T
• Created: 16/Sep/14 10:52
• Updated: 14/Oct/14 04:06
• Resolved: 14/Oct/14 04:06

Description

When Maagement server is not able to detect VM state, after a specific time it will try to change the RUNNING state to STOPPED state directly without STOPPING state in between. Which is causing the event not to be generated and now if you DESTROY the VM still it will generate the usage records for a period of 24 hrs every day.
Logs are attached below...

2014-05-15 16:13:25,197 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgent-117:ctx-775a3f34) Run missing VM report. current time: 1400163205197
2014-05-15 16:13:25,197 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgent-117:ctx-775a3f34) Detected missing VM. host: 1, vm id: 106, power state: PowerReportMissing, last state update: 1400162537000
2014-05-15 16:13:25,197 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgent-117:ctx-775a3f34) vm id: 106 - time since last state update(668197ms) has passed graceful period
2014-05-15 16:13:25,202 DEBUG [c.c.v.VirtualMachinePowerStateSyncImpl] (DirectAgent-117:ctx-775a3f34) VM state report is updated. host: 1, vm id: 106, power state: PowerReportMissing
2014-05-15 16:13:25,207 INFO [c.c.v.VirtualMachineManagerImpl] (DirectAgent-117:ctx-775a3f34) VM i-5-106-VM is at Running and we received a power-off report while there is no pending jobs on it
2014-05-15 16:13:25,210 DEBUG [c.c.a.t.Request] (DirectAgent-117:ctx-775a3f34) Seq 1-1971781673: Sending { Cmd , MgmtId: 20750978301280, via: 1(XSMASTER-5), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":true,"vmName":"i-5-106-VM","wait":0}}] }
2014-05-15 16:13:25,210 DEBUG [c.c.a.t.Request] (DirectAgent-117:ctx-775a3f34) Seq 1-1971781673: Executing: { Cmd , MgmtId: 20750978301280, via: 1(XSMASTER-5), Ver: v1, Flags: 100111, [{"com.cloud.agent.api.StopCommand":{"isProxy":false,"executeInSequence":true,"checkBeforeCleanup":true,"vmName":"i-5-106-VM","wait":0}}] }
2014-05-15 16:13:25,210 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-18:ctx-7180bb9c) Seq 1-1971781673: Executing request
2014-05-15 16:13:25,249 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-18:ctx-7180bb9c) 9. The VM i-5-106-VM is in Stopping state
2014-05-15 16:13:25,293 INFO [c.c.h.x.r.XenServer56Resource] (DirectAgent-18:ctx-7180bb9c) Catch com.xensource.xenapi.Types$VifInUse: failed to destory VLAN eth0 on host c4080dac-f034-452f-9203-8e69d5512315 due to Network has active VIFs
2014-05-15 16:13:25,294 DEBUG [c.c.h.x.r.CitrixResourceBase] (DirectAgent-18:ctx-7180bb9c) 10. The VM i-5-106-VM is in Stopped state
2014-05-15 16:13:25,294 DEBUG [c.c.a.m.DirectAgentAttache] (DirectAgent-18:ctx-7180bb9c) Seq 1-1971781673: Response Received:
2014-05-15 16:13:25,294 DEBUG [c.c.a.t.Request] (DirectAgent-18:ctx-7180bb9c) Seq 1-1971781673: Processing: { Ans: , MgmtId: 20750978301280, via: 1, Ver: v1, Flags: 110, [{"com.cloud.agent.api.StopAnswer":{"platform":"viridian:true;acpi:1;apic:true;pae:true;nx:true","result":true,"details":"Stop VM i-5-106-VM Succeed","wait":0}}] }
2014-05-15 16:13:25,294 DEBUG [c.c.a.t.Request] (DirectAgent-117:ctx-775a3f34) Seq 1-1971781673: Received: { Ans: , MgmtId: 20750978301280, via: 1, Ver: v1, Flags: 110,

{ StopAnswer }

}
2014-05-15 16:13:25,301 DEBUG [c.c.a.m.AgentAttache] (DirectAgent-18:ctx-7180bb9c) Seq 1-1971781673: No more commands found
2014-05-15 16:13:25,365 DEBUG [c.c.c.CapacityManagerImpl] (DirectAgent-117:ctx-775a3f34) VM state transitted from :Running to Stopped with event: FollowAgentPowerOffReportvm's original host id: 1 new host id: null host id before state transition: 1