Bug 1265174 - VMware VmPoweredOffEvent not handled (stack trace in evm.log)
VMware VmPoweredOffEvent not handled (stack trace in evm.log)
Status: CLOSED NOTABUG
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Appliance (Show other bugs)
5.4.0
Unspecified Unspecified
high Severity high
: GA
: 5.5.0
Assigned To: Gregg Tanzillo
Dave Johnson
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2015-09-22 05:59 EDT by Peter McGowan
Modified: 2015-11-11 15:36 EST (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-10-19 11:23:03 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Peter McGowan 2015-09-22 05:59:43 EDT
Description of problem:
When a VMware VmPoweredOffEvent occurs, the event is not handled correctly by CFME and a stack trace appears in evm.log

Version-Release number of selected component (if applicable):
CFME 5.4.2.0.20150820153254_83e434d
vCenter 4.1.0

How reproducible:
Every time


Steps to Reproduce:
1. in a managed (i.e. configured as a Provider) vCenter, power off a VM
2. monitor evm.log


Actual results:
[----] I, [2015-09-22T10:49:02.700035 #10323:9c9e88]  INFO -- : MIQ(MiqQueue.delivered)  Message id: [1000000473740], State: [ok], Delivered in [0.134196167] seconds
[----] I, [2015-09-22T10:49:02.715174 #10323:9c9e88]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [1000000473741], MiqWorker id: [1000000001482], Zone: [default], Role: [event], Server: [], Ident: [ems], Target id: [1000000000001], Instance id: [], Task id: [], Command: [EmsEvent.add_vc], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [{"key"=>"27939", "chainId"=>"27933", "createdTime"=>"2015-09-22T09:48:51.205031Z", "userName"=>"Administrator", "datacenter"=>{"name"=>"Winchester", "datacenter"=>"datacenter-2"}, "computeResource"=>{"name"=>"Production", "computeResource"=>"domain-c7"}, "host"=>{"name"=>"192.168.2.228", "host"=>"host-9"}, "vm"=>{"name"=>"web02", "vm"=>"vm-1117", "path"=>"[datastore1] web02/web02.vmx"}, "fullFormattedMessage"=>"web02 on  192.168.2.228 in Winchester is powered off", "changeTag"=>"", "template"=>"false", "eventType"=>"VmPoweredOffEvent"}], Dequeued in: [4.97534463] seconds
[----] I, [2015-09-22T10:49:02.715303 #10323:9c9e88]  INFO -- : MIQ(MiqQueue.deliver)    Message id: [1000000473741], Delivering...
[----] D, [2015-09-22T10:49:02.715529 #10323:9c9e88] DEBUG -- : MIQ(EmsEvent::Parsers::Vc.event_to_hash) ems_id: [1000000000001] event: [{"key"=>"27939", "chainId"=>"27933", "createdTime"=>"2015-09-22T09:48:51.205031Z", "userName"=>"Administrator", "datacenter"=>{"name"=>"Winchester", "datacenter"=>"datacenter-2"}, "computeResource"=>{"name"=>"Production", "computeResource"=>"domain-c7"}, "host"=>{"name"=>"192.168.2.228", "host"=>"host-9"}, "vm"=>{"name"=>"web02", "vm"=>"vm-1117", "path"=>"[datastore1] web02/web02.vmx"}, "fullFormattedMessage"=>"web02 on  192.168.2.228 in Winchester is powered off", "changeTag"=>"", "template"=>"false", "eventType"=>"VmPoweredOffEvent"}]
[----] I, [2015-09-22T10:49:02.770963 #10323:9c9e88]  INFO -- : MIQ(EmsEventHandler-handle_event) Processing EMS event [VmPoweredOffEvent] chain_id [27933] on EMS [1000000000001]...
[----] D, [2015-09-22T10:49:02.777242 #10323:9c9e88] DEBUG -- : MIQ(EmsEventHandler-handle_routine) Handling event [VmPoweredOffEvent] with the following routine: [{"call"=>["src_vm", "state=", "off"]}, {"call"=>["src_vm", "save!"]}, {"policy"=>["src_vm", "vm_poweroff"]}]
[----] D, [2015-09-22T10:49:02.777353 #10323:9c9e88] DEBUG -- : MIQ(EmsEventHandler-handle_step) Performing routine step [call] with the following targets: ["src_vm", "state=", "off"]
[----] D, [2015-09-22T10:49:02.779561 #10323:9c9e88] DEBUG -- : MIQ(EmsEventHandler-handle_step) Calling method [VmVmware, 1000000000078].state=("off")
[----] E, [2015-09-22T10:49:02.780753 #10323:9c9e88] ERROR -- : [NoMethodError]: undefined method `state=' for #<VmVmware:0x0000000bf6df50>  Method:[rescue in handle_event]
[----] E, [2015-09-22T10:49:02.780862 #10323:9c9e88] ERROR -- : /opt/rh/cfme-gemset/bundler/gems/rails-4842a8377644/activemodel/lib/active_model/attribute_methods.rb:407:in `method_missing'
/opt/rh/cfme-gemset/bundler/gems/rails-4842a8377644/activerecord/lib/active_record/attribute_methods.rb:149:in `method_missing'
/var/www/miq/vmdb/lib/ems_event_helper.rb:97:in `block in handle_step'
/var/www/miq/vmdb/lib/ems_event_helper.rb:97:in `each'
/var/www/miq/vmdb/lib/ems_event_helper.rb:97:in `handle_step'
/var/www/miq/vmdb/lib/ems_event_helper.rb:41:in `block in handle_routine'
/var/www/miq/vmdb/lib/ems_event_helper.rb:41:in `each'
/var/www/miq/vmdb/lib/ems_event_helper.rb:41:in `handle_routine'
/var/www/miq/vmdb/lib/ems_event_helper.rb:35:in `handle_event'
/var/www/miq/vmdb/lib/ems_event_helper.rb:11:in `handle'
/var/www/miq/vmdb/app/models/ems_event.rb:39:in `handle_event'
/var/www/miq/vmdb/app/models/ems_event.rb:273:in `create_event'
/var/www/miq/vmdb/app/models/ems_event.rb:124:in `add'
/var/www/miq/vmdb/app/models/ems_event.rb:90:in `add_vc'
/var/www/miq/vmdb/app/models/miq_queue.rb:354:in `block in deliver'
/opt/rh/ruby200/root/usr/share/ruby/timeout.rb:66:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:352:in `deliver'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:107:in `deliver_queue_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:135:in `deliver_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:152:in `block in do_work'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `loop'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `do_work'
/var/www/miq/vmdb/lib/workers/worker_base.rb:323:in `block in do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:141:in `run'
/var/www/miq/vmdb/lib/workers/worker_base.rb:122:in `start'
/var/www/miq/vmdb/lib/workers/worker_base.rb:23:in `start_worker'
/var/www/miq/vmdb/lib/workers/bin/worker.rb:3:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-4842a8377644/railties/lib/rails/commands/runner.rb:52:in `eval'
/opt/rh/cfme-gemset/bundler/gems/rails-4842a8377644/railties/lib/rails/commands/runner.rb:52:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-4842a8377644/railties/lib/rails/commands.rb:64:in `require'
/opt/rh/cfme-gemset/bundler/gems/rails-4842a8377644/railties/lib/rails/commands.rb:64:in `<top (required)>'
script/rails:6:in `require'
script/rails:6:in `<main>'


Expected results:
The event should be handled correctly


Additional info:
Comment 1 Peter McGowan 2015-09-22 06:07:53 EDT
I've just noticed that the same things happens with a DrsVmPoweredOnEvent...

[----] I, [2015-09-22T11:04:03.560572 #10323:9c9e88]  INFO -- : MIQ(EmsEventHandler-handle_event) Processing EMS event [DrsVmPoweredOnEvent] chain_id [27941] on EMS [1000000000001]...
[----] D, [2015-09-22T11:04:03.566967 #10323:9c9e88] DEBUG -- : MIQ(EmsEventHandler-handle_routine) Handling event [DrsVmPoweredOnEvent] with the following routine: [{"call"=>["src_vm", "state=", "on"]}, {"call"=>["src_vm", "save!"]}]
[----] D, [2015-09-22T11:04:03.567083 #10323:9c9e88] DEBUG -- : MIQ(EmsEventHandler-handle_step) Performing routine step [call] with the following targets: ["src_vm", "state=", "on"]
[----] D, [2015-09-22T11:04:03.569278 #10323:9c9e88] DEBUG -- : MIQ(EmsEventHandler-handle_step) Calling method [VmVmware, 1000000000078].state=("on")
[----] E, [2015-09-22T11:04:03.570532 #10323:9c9e88] ERROR -- : [NoMethodError]: undefined method `state=' for #<VmVmware:0x0000000bcfb100>  Method:[rescue in handle_event]

Note You need to log in before you can comment on or make changes to this bug.