CF 4.1 -> CF 4.2 migration: update_serviceprovision_status ERROR and never ends


#1

After migrating from CF 4.1 to CF 4.2, the service creation is broken:
(EVM: 5.7.2.1.20170406142927_0a1ad0e )

It looks like something changed in the MIQ method update_serviceprovision_status:

[----] I, [2017-05-23T13:44:31.772721 #7402:709130] INFO – : Q-task_id([service_template_provision_task_1000000002967]) Invoking [inline] method [/ManageIQ/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status] with inputs [{“status”=>“Creating Service”}]
[----] I, [2017-05-23T13:44:31.773782 #7402:709130] INFO – : Q-task_id([service_template_provision_task_1000000002967]) <AEMethod [/ManageIQ/Service/Provisioning/StateMachines/ServiceProvision_Template/update_serviceprovision_status]> Starting
[----] E, [2017-05-23T13:44:32.449391 #7402:6fb79c] ERROR – : Q-task_id([service_template_provision_task_1000000002967]) The following error occurred during method evaluation:
[----] E, [2017-05-23T13:44:32.451847 #7402:6fb79c] ERROR – : Q-task_id([service_template_provision_task_1000000002967]) NoMethodError: undefined method `name’ for nil:NilClass

looks like the code pb is in this bloc:

Update Status Message

updated_message = "Server [#{$evm.root[‘miq_server’].name}] "
updated_message += "Service [#{prov.destination.name}] "

But i can’t understand why.

The service request is never ending (started yesterday) and the service is still not created.


#2

@tinaafitz @wfitzger Have you seen this before or have any suggestions here?


#3

FYI it looks like it went to then end of deployment:

Ending
[----] I, [2017-05-23T13:46:08.777656 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Method exited with rc=MIQ_OK
[----] I, [2017-05-23T13:46:08.778186 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Followed Relationship [miqaedb:/System/CommonMethods/StateMachineMethods/vm_provision_finished#create]
[----] I, [2017-05-23T13:46:08.778316 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Processed State=[Finished] with Result=[ok]
[----] I, [2017-05-23T13:46:08.778431 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Processed State =[Finished]
[----] I, [2017-05-23T13:46:08.778794 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Next State=[]
[----] I, [2017-05-23T13:46:08.778954 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Followed Relationship [miqaedb:/Infrastructure/VM/Provisioning/StateMachines/VMProvision_vm/template#create]
[----] I, [2017-05-23T13:46:08.779693 #7409:709130] INFO – : Q-task_id([miq_provision_1000000002969]) Followed Relationship [miqaedb:/infrastructure/VM/Lifecycle/Provisioning#create]

but the service request still run and service is not created:

Request Details
Request ID
1,000,000,001,059
Status
Ok
Request State
Active
Requester
Administrator
Request Type
Service Provision
Description
Provisioning Service [MyService] from [Myservice]
Last Message
[EVM] VM [myVM] IP [127.0.0.2] Provisioned Successfully
Created On
Tue, 23 May 2017 13:40:17 +0200
Last Update
Tue, 23 May 2017 13:46:08 +0200
Approval State
Approved
Approved/Denied by
admin (Administrator)
Approved/Denied on
Tue, 23 May 2017 13:40:32 +0200
Reason
Auto-Approved


#4

Hi gquentin,

It’s odd that your Service provisioning update_serviceprovision_status worked properly until the Create Service state, then had an issue. I see from your log snippet that the underlying VM provision completed successfully.

These values should be available for sure:
updated_message = "Server [#{$evm.root[‘miq_server’].name}] "
updated_message += "Service [#{prov.destination.name}] "

Can you send me the automation.log and evm.log for this provision?

My email address is tfitzger@redhat.com

Regards,
Tina


#5

since logs are very big and contains other things, can i just extract the part of the log we are interesting in with this?

zcat /var/www/miq/vmdb/log/evm.log-20170524.gz | grep -e 1000000001059 -e 1000000002969

zcat /var/www/miq/vmdb/log/automation.log-20170524.gz | grep -e 1000000001059 -e 1000000002969

(miq_request_id and miq_provision_id)?


#6

I think that’ll be good, thanks.


#7

just sent them to you.
thanks


#8

Hi gquentin,

Can you send me logging related to service_template_provision_task_1000000002967?

Thanks,
Tina


#9

sent.


#10

FYI we know why the service in not created: one of our colleagues created a transfert_vm instance/method which moves the vm into a standardized service . This one has been deleted so the service creation cannot be accomplished. There are errors in logs so, why did the service creation not stopped with failure ? And it does not explain why the service creation request continues to run.


#11

FYI we have finally rebooted cloudforms appliance. The service request is still active, but we can’t see any ruby process to kill. How to stop it?


#12

Hi gquentin,

Service provisioning needs the Service object for the state machine to be successful.
It sounds like your work flow doesn’t have that requirement. You could copy the update_serviceprovision_status method into your custom domain and change it to not rely on the prov.destination.
The method called in the finish state also relies on the Service, so you would have to do something custom there as well.

The update_serviceprovision_status method was not expecting the Service object to be deleted and didn’t update the Request.
The Request is not running, even though it is still marked as active.

Regards,
Tina