Service retirement into infinite loop


#1

Sometime a service created by cloudforms can’t be retired: it goes into infinite loop, until we restart cloudforms (4.1)

On vpshere we saw that the vm has been well powered off. But it looks like cf can not delete it. So it waits:

in automation.log, looping on:
[----] I, [2017-01-31T15:09:30.382418 #25173:64198c] INFO – : In State=[RemoveFromSalt], invoking [on_error] method=[update_retirement_status(status => ‘Error Removing from Salt’)]
[----] I, [2017-01-31T15:10:23.974937 #25173:64198c] INFO – : In State=[CheckServiceRetired], invoking [on_entry] method=[update_service_retirement_status(status => ‘Checking Service retirement’)]
[----] I, [2017-01-31T15:10:27.120178 #25173:64198c] INFO – : In State=[CheckServiceRetired], invoking [on_exit] method=[update_service_retirement_status(status => ‘Checked Service retirement’)]
[----] I, [2017-01-31T15:11:37.988432 #521:64198c] INFO – : In State=[CheckServiceRetired], invoking [on_entry] method=[update_service_retirement_status(status => ‘Checking Service retirement’)]
[----] I, [2017-01-31T15:11:41.220222 #521:64198c] INFO – : In State=[CheckServiceRetired], invoking [on_exit] method=[update_service_retirement_status(status => ‘Checked Service retirement’)]
[----] I, [2017-01-31T15:12:53.856741 #25181:64198c] INFO – : In State=[CheckServiceRetired], invoking [on_entry] method=[update_service_retirement_status(status => ‘Checking Service retirement’)]

until 17:17 … so we restarted cf4 and relaunched the retirement: it worked fine this time.

----] I, [2017-01-31T17:17:57.879238 #3058:80b998] INFO – : In State=[CheckServiceRetired], invoking [on_entry] method=[update_service_retirement_status(status => ‘Checking Service retirement’)]

An idea?


#2

Sounds like a CF / vSphere communication failure : event not handled,
inventory timeout… Do you have error message in evm.log ?


#3

Yes there are:

[----] E, [2017-01-31T15:09:30.301482 #25173:a2f6e8] ERROR – : The following error occurred during method evaluation:
[----] E, [2017-01-31T15:09:30.303227 #25173:a2f6e8] ERROR – : RestClient::InternalServerError: 500 Internal Server Error
[----] E, [2017-01-31T15:09:30.305514 #25173:a2f6e8] ERROR – : /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/abstract_response.rb:197:in exception_with_response' [----] E, [2017-01-31T15:09:30.309422 #25173:a06fa4] ERROR -- : <AutomationEngine> Method STDERR: /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/abstract_response.rb:197:inexception_with_response’: 500 Internal Server Error (RestClient::InternalServerError)
[----] E, [2017-01-31T15:09:30.309721 #25173:a06fa4] ERROR – : Method STDERR: from /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/abstract_response.rb:83:in return!' [----] E, [2017-01-31T15:09:30.309891 #25173:a06fa4] ERROR -- : <AutomationEngine> Method STDERR: from /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/request.rb:594:inprocess_result’
[----] E, [2017-01-31T15:09:30.310052 #25173:a06fa4] ERROR – : Method STDERR: from /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/request.rb:504:in block in transmit' [----] E, [2017-01-31T15:09:30.310219 #25173:a06fa4] ERROR -- : <AutomationEngine> Method STDERR: from /opt/rh/rh-ruby22/root/usr/share/ruby/net/http.rb:853:instart’
[----] E, [2017-01-31T15:09:30.310354 #25173:a06fa4] ERROR – : Method STDERR: from /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/request.rb:494:in transmit' [----] E, [2017-01-31T15:09:30.310479 #25173:a06fa4] ERROR -- : <AutomationEngine> Method STDERR: from /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/request.rb:202:inexecute’
[----] E, [2017-01-31T15:09:30.310617 #25173:a06fa4] ERROR – : Method STDERR: from /opt/rh/cfme-gemset/gems/rest-client-2.0.0.rc1/lib/restclient/request.rb:52:in execute' [----] E, [2017-01-31T15:09:30.310783 #25173:a06fa4] ERROR -- : <AutomationEngine> Method STDERR: from <code: dooie = RestClient::Request.execute(:url => url, :method => :post, :verify_ssl => false, :payload => payload )>:31:in
[----] E, [2017-01-31T15:09:30.381409 #25173:64198c] ERROR – : Aborting instantiation (unknown method return code) because [Method exited with rc=Unknown RC: [1]]
[----] E, [2017-01-31T15:09:30.381760 #25173:64198c] ERROR – : State= running raised exception: <Method exited with rc=Unknown RC: [1]>
[----] E, [2017-01-31T15:09:31.688899 #25173:64198c] ERROR – : MIQ(MiqAeEngine.deliver_block) Error delivering {:event_type=>“request_vm_retire”, “VmOrTemplate::vm”=>1000000001380, :vm_id=>1000000001380, “Host::host”=>1000000000041, :host_id=>1000000000041, :retirement_initiator=>“user”, :userid=>“admin”, :type=>“ManageIQ::Providers::Vmware::InfraManager::Vm”, “MiqEvent::miq_event”=>1000000715492, :miq_event_id=>1000000715492, “EventStream::event_stream”=>1000000715492, :event_stream_id=>1000000715492} for object [ManageIQ::Providers::Vmware::InfraManager::Vm.1000000001380] with state [CheckPreRetirement] to Automate:
[----] E, [2017-01-31T15:09:57.753189 #25181:64198c] ERROR – : MIQ(MiqQueue#deliver) Message id: [1000004730275], Error: [undefined local variable or method id' for Metric::Capture:Module] [----] E, [2017-01-31T15:09:57.753408 #25181:64198c] ERROR -- : [NameError]: undefined local variable or methodid’ for Metric::Capture:Module Method:[rescue in deliver]
[----] E, [2017-01-31T15:09:57.753581 #25181:64198c] ERROR – : /var/www/miq/vmdb/app/models/metric/capture.rb:199:in block (2 levels) in queue_captures' [----] E, [2017-01-31T15:13:04.735054 #521:64198c] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000004730305], Error: [undefined local variable or methodid’ for Metric::Capture:Module]
[----] E, [2017-01-31T15:13:04.735300 #521:64198c] ERROR – : [NameError]: undefined local variable or method id' for Metric::Capture:Module Method:[rescue in deliver] [----] E, [2017-01-31T15:13:04.735501 #521:64198c] ERROR -- : /var/www/miq/vmdb/app/models/metric/capture.rb:199:inblock (2 levels) in queue_captures’
[----] E, [2017-01-31T15:16:01.683490 #521:64198c] ERROR – : MIQ(MiqQueue#deliver) Message id: [1000004730334], Error: [undefined local variable or method id' for Metric::Capture:Module] [----] E, [2017-01-31T15:16:01.683717 #521:64198c] ERROR -- : [NameError]: undefined local variable or methodid’ for Metric::Capture:Module Method:[rescue in deliver]
[----] E, [2017-01-31T15:16:01.683893 #521:64198c] ERROR – : /var/www/miq/vmdb/app/models/metric/capture.rb:199:in block (2 levels) in queue_captures' [----] E, [2017-01-31T15:18:01.281599 #9600:ca2aec] ERROR -- : <API> MIQ(ApiController.api_error) API Error [----] E, [2017-01-31T15:18:01.281769 #9600:ca2aec] ERROR -- : <API> MIQ(ApiController.api_error) ApiController::AuthenticationError: Invalid Authentication Token d4f069302876aa19fbd71290ad43c041 specified [----] E, [2017-01-31T15:19:06.810464 #25173:64198c] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000004730363], Error: [undefined local variable or methodid’ for Metric::Capture:Module]
[----] E, [2017-01-31T15:19:06.810695 #25173:64198c] ERROR – : [NameError]: undefined local variable or method id' for Metric::Capture:Module Method:[rescue in deliver] [----] E, [2017-01-31T15:19:06.810879 #25173:64198c] ERROR -- : /var/www/miq/vmdb/app/models/metric/capture.rb:199:inblock (2 levels) in queue_captures’
[----] E, [2017-01-31T15:22:07.730134 #25173:64198c] ERROR – : MIQ(MiqQueue#deliver) Message id: [1000004730396], Error: [undefined local variable or method id' for Metric::Capture:Module] [----] E, [2017-01-31T15:22:07.730317 #25173:64198c] ERROR -- : [NameError]: undefined local variable or methodid’ for Metric::Capture:Module Method:[rescue in deliver]
[----] E, [2017-01-31T15:22:07.730493 #25173:64198c] ERROR – : /var/www/miq/vmdb/app/models/metric/capture.rb:199:in block (2 levels) in queue_captures' [----] E, [2017-01-31T15:25:17.058735 #25181:64198c] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000004730426], Error: [undefined local variable or methodid’ for Metric::Capture:Module]
[----] E, [2017-01-31T15:25:17.059054 #25181:64198c] ERROR – : [NameError]: undefined local variable or method id' for Metric::Capture:Module Method:[rescue in deliver] [----] E, [2017-01-31T15:25:17.059298 #25181:64198c] ERROR -- : /var/www/miq/vmdb/app/models/metric/capture.rb:199:inblock (2 levels) in queue_captures’
[----] E, [2017-01-31T15:28:09.172815 #25173:64198c] ERROR – : MIQ(MiqQueue#deliver) Message id: [1000004730454], Error: [undefined local variable or method id' for Metric::Capture:Module] [----] E, [2017-01-31T15:28:09.173012 #25173:64198c] ERROR -- : [NameError]: undefined local variable or methodid’ for Metric::Capture:Module Method:[rescue in deliver]
[----] E, [2017-01-31T15:28:09.173178 #25173:64198c] ERROR – : /var/www/miq/vmdb/app/models/metric/capture.rb:199:in block (2 levels) in queue_captures' [----] E, [2017-01-31T15:30:55.912853 #25173:64198c] ERROR -- : MIQ(MiqQueue#deliver) Message id: [1000004730744], Error: [undefined local variable or methodid’ for Metric::Capture:Module]
[----] E, [2017-01-31T15:30:55.913142 #25173:64198c] ERROR – : [NameError]: undefined local variable or method `id’ for Metric::Capture:Module Method:[rescue in deliver]