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:
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]