Bug 1467537

Is the logging still available?  The log snippet in the description shows work being picked up from the queue but it is unclear what commands are being run.

Any additional information would be helpful as right we cannot determine what would cause this error.

Nandini, can this be reproduced?  Please point Greg at it.

does that cover what you need to progress on this one?

Thanks Felix, the log snippet shows that service provisioning was progressing and got to the checkprovisioned state before it hit the error.

Again, from your log it shows that "Service::Service"=>1000000000172 is the object we would have tried to load but failed to do so leading to the error "[NoMethodError]: undefined method `base_class' for NilClass:Class".

Automate was definitely called several times before it got to the checkprovisioned state so my guess is that the customer may have deleted the Service instance, possibly from the UI, before provisioning completed.

Can you try to confirm this with the customer?  Otherwise I need a way to reproduce the error.

* Note - this ticket has unspecified/medium while the newly added case is marked as urgent.

Customer logs show the miq_request of the Service provision was deleted while the Service was still actively provisioning.

evm.log error for Service Template Provision Task: 100000000000283, which belongs to Service Template Provision Request: 100000000000007
and Service: 100000000000005

es: 17\n  ae_state_started: 2017-09-27 15:51:21 UTC\n"}], Dequeued in: [1136.54826955] seconds
[----] I, [2017-09-27T12:10:19.691390 #10757:385130]  INFO -- : Q-task_id([service_template_provision_task_100000000000283]) MIQ(MiqQueue#deliver) Message id: [100000075600204], Delivering...
[----] I, [2017-09-27T12:10:19.693978 #10757:385130]  INFO -- : Q-task_id([service_template_provision_task_100000000000283]) <AutomationEngine> User [admin] with current group ID [100000000000002] name [EvmGroup-super_administrator]
[----] I, [2017-09-27T12:10:19.694190 #10757:385130]  INFO -- : Q-task_id([service_template_provision_task_100000000000283]) MIQ(MiqAeEngine.deliver) Delivering {"dialog_service_name"=>"b-test-0927", "dialog_project_number"=>"562562", "dialog_tag_0_environment"=>"dev", "dialog_option_1_vm_name"=>"btest0927", "dialog_option_1_cores_per_socket"=>"1", "dialog_option_1_vm_memory"=>"1024", "dialog_option_1_subnet_id"=>"11", "dialog_option_1_hostgroup"=>"HG_DEV_RHEL7", "dialog_option_1_compute_profile_id"=>"13", "dialog_option_1_additional_info"=>"", "request"=>"clone_to_service", "Service::Service"=>100000000000105} for object [ServiceTemplateProvisionTask.100000000000283] with state [checkprovisioned] to Automate
[----] E, [2017-09-27T12:10:19.698629 #10757:385130] ERROR -- : Q-task_id([service_template_provision_task_100000000000283]) MIQ(MiqQueue#deliver) Message id: [100000075600204], Error: [undefined method `base_class' for NilClass:Class]
[----] E, [2017-09-27T12:10:19.698816 #10757:385130] ERROR -- : Q-task_id([service_template_provision_task_100000000000283]) [NoMethodError]: undefined method `base_class' for NilClass:Class  Method:[rescue in deliver]
[----] E, [2017-09-27T12:10:19.698977 #10757:385130] ERROR -- : Q-task_id([service_template_provision_task_100000000000283]) /var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_engine.rb:187:in `create_automation_attribute_class_name'
/var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_engine.rb:205:in `create_automation_attribute_key'
/var/www/miq/vmdb/lib/miq_automation_engine/engine/miq_ae_engine.rb:88:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue.rb:347:in `block in deliver'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:91:in `block in timeout'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `block in catch'
 
The Service provisioning state machine successfully processes this request(ID=100000000000007, check_provisioned) 16 times, then fails at 12:10:19

The production.log shows the request(100000000000007) being deleted at 12:09:31, which causes the Service provisioning failure.

[----] I, [2017-09-27T12:09:31.925880 #10923:48ddfc]  INFO -- : Started POST "/miq_request/button/100000000000107?pressed=miq_request_delete" for 140.98.129.46 at 2017-09-27 12:09:31 -0400
[----] I, [2017-09-27T12:09:31.927740 #10923:48ddfc]  INFO -- : Processing by MiqRequestController#button as JS
[----] I, [2017-09-27T12:09:31.927810 #10923:48ddfc]  INFO -- :   Parameters: {"refresh"=>"y", "pressed"=>"miq_request_delete", "id"=>"100000000000107"}
[----] I, [2017-09-27T12:09:31.989711 #10923:48ddfc]  INFO -- : Completed 200 OK in 62ms (Views: 0.7ms | ActiveRecord: 14.0ms


Can you ask the customer why they're deleting the request before the provision is complete?

Thanks,
Tina

I will take care of it. I will update to you soon.

https://github.com/ManageIQ/manageiq-automation_engine/pull/84

Hi Nandini,

Can you review this ticket?

There are 2 cases attached, one is closed with cant reproduce and the other should be an RFE.

Thanks,
Tina

Hi Edu/Nandini,

Any update on this ticket? 

Thanks,
Tina

Hi Edu/Nandini,

The attached logs show errors unrelated to this ticket.
A new ticket should be opened to track this new issue.

Service provisioning check_provisioned method is reacting to an internal state machine provisioning error.

automation.log - check_provisioned report error
----] E, [2017-11-07T13:11:12.529098 #16987:5f56630] ERROR -- : Q-task_id([service_template_provision_task_1000000000012]) <AEMethod update_serviceprovision_status> Service Provision Error: Server [CFME 5.8.2] Service [launch_instance-20171107-130940] Step [checkprovisioned] Status [Error Creating Service] Message [[NoMethodError]: undefined method `[]' for nil:NilClass]
[----] I, [2017-11-07T13:11:12.549716 #16987:cb113c]  INFO -- : Q-task_id([service_template_provision_task_1000000000012]) <AEMet


evm.log - internal state machine start_clone_task gets error

[----] I, [2017-11-07T13:10:43.685504 #16987:cb113c]  INFO -- : Q-task_id([miq_provision_1000000000013]) MIQ(ManageIQ::Providers::Openstack::CloudManager::Provision#log_clone_options) Prov Options:  [:dest_availability_zone][1](String) = "CANN-1"
[----] I, [2017-11-07T13:10:43.685566 #16987:cb113c]  INFO -- : Q-task_id([miq_provision_1000000000013]) MIQ(ManageIQ::Providers::Openstack::CloudManager::Provision#log_clone_options) Prov Options:  [:networks][0]["net_id"](String) = "e2eb62b7-acc6-4872-bbce-8aef08d7ac6c"
[----] I, [2017-11-07T13:10:43.687081 #16987:cb113c]  INFO -- : Q-task_id([miq_provision_1000000000013]) Starting Phase <provision_error>
[----] E, [2017-11-07T13:10:43.711865 #16987:cb113c] ERROR -- : Q-task_id([miq_provision_1000000000013]) MIQ(ManageIQ::Providers::Openstack::CloudManager::Provision#provision_error) [[NoMethodError]: undefined method `[]' for nil:NilClass] encountered during phase [start_clone_task]
[----] E, [2017-11-07T13:10:43.711975 #16987:cb113c] ERROR -- : Q-task_id([miq_provision_1000000000013]) /var/www/miq/vmdb/app/models/mixins/provider_object_mixin.rb:29:in `connection_source'
/var/www/miq/vmdb/app/models/mixins/provider_object_mixin.rb:5:in `with_provider_connection'
/var/www/miq/vmdb/app/models/manageiq/providers/openstack/cloud_manager/provision/cloning.rb:45:in `start_clone'
/var/www/miq/vmdb/app/models/manageiq/providers/cloud_manager/provision/state_machine.rb:37:in `start_clone_task'


there are multiple fog connection errors:
----] I, [2017-11-07T13:10:52.409172 #5826:cb113c]  INFO -- :   :ems_event_thread_shutdown_timeout: 10
[----] I, [2017-11-07T13:10:52.409198 #5826:cb113c]  INFO -- : ---
[----] I, [2017-11-07T13:10:52.409454 #5826:cb113c]  INFO -- :   :guid: b2b471fc-c3b4-11e7-8961-fa163e6f5f07
[----] I, [2017-11-07T13:10:52.409505 #5826:cb113c]  INFO -- :   :ems_id: 1000000000001
[----] I, [2017-11-07T13:10:52.419461 #5826:cb113c]  INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Openstack::CloudManager: [OSP_CANN]
[----] E, [2017-11-07T13:10:53.219548 #5826:cb113c] ERROR -- : <Fog> excon.error     #<Excon::Error::Unauthorized: Expected([201]) <=> Actual(401 Unauthorized)
excon.error.response
  :body          => "{\"error\": {\"message\": \"The request you have made requires authentication.\", \"code\": 401, \"title\": \"Unauthorized\"}}"
  :cookies       => [
  ]
  :headers       => {
    "Content-Length"         => "114"
    "Content-Type"           => "application/json"
    "Date"                   => "Tue, 07 Nov 2017 12:10:52 GMT"
    "Server"                 => "Apache/2.4.6 (Red Hat Enterprise Linux) OpenSSL/1.0.1e-fips mod_wsgi/3.4 Python/2.7.5"
    "Vary"                   => "X-Auth-Token"
    "WWW-Authenticate"       => "Keystone uri=\"https://keystone.cann.gsnetcloud.corp:5000/\""
    "x-openstack-request-id" => "req-89191ab8-ca8f-4e1c-a9e0-a21db6506b17"
  }
  :host          => "keystone.cann.gsnetcloud.corp"
  :local_address => "10.94.77.62"
  :local_port    => 52566
  :path          => "/v3/auth/tokens"
  :port          => 5000
  :reason_phrase => "Unauthorized"
  :remote_ip     => "180.14.0.163"
  :status        => 401
  :status_line   => "HTTP/1.1 401 Unauthorized\r\n"
>


Thanks,
Tina

Clearing NEEDINFO set for me.

Custom code was the cause of the issue mentioned in comments 19 and 20.
The last logs from customer show an unrelated problem(comment 18).
Closing ticket.