Bug 1467537 - Error: [undefined method `base_class' for NilClass:Class]
Error: [undefined method `base_class' for NilClass:Class]
Status: CLOSED NOTABUG
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Automate (Show other bugs)
5.8.0
Unspecified Unspecified
high Severity high
: GA
: cfme-future
Assigned To: Tina Fitzgerald
Nandini Chandra
automate
:
Depends On:
Blocks: 1511957
  Show dependency treegraph
 
Reported: 2017-07-04 03:25 EDT by Nandini Chandra
Modified: 2017-12-20 13:45 EST (History)
11 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2017-12-20 13:45:48 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: Feature
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: CFME Core


Attachments (Terms of Use)

  None (edit)
Description Nandini Chandra 2017-07-04 03:25:32 EDT
Description of problem:
------------------------
I found this error message logged in the evm.log file.

[----] E, [2017-07-03T11:00:17.446152 #3020:8bb140] ERROR -- : MIQ(MiqQueue#deliver) Message id: [204945], Error: [undefined method `base_class' for NilClass:Class]

[----] E, [2017-07-03T11:00:17.446366 #3020:8bb140] ERROR -- : [NoMethodError]: undefined method `base_class' for NilClass:Class  Method:[rescue in deliver]

[----] E, [2017-07-03T11:00:17.446573 #3020:8bb140] ERROR -- : /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'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch'
/opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:106:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:343:in `deliver'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:107:in `deliver_queue_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:135:in `deliver_message'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:153:in `block in do_work'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:147:in `loop'
/var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:147:in `do_work'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:341:in `block in do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:338:in `loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:338:in `do_work_loop'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:160:in `run'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:134:in `start'
/var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:339:in `block in start_runner'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork'
/var/www/miq/vmdb/app/models/miq_worker.rb:337:in `start_runner'
/var/www/miq/vmdb/app/models/miq_worker.rb:348:in `start'
/var/www/miq/vmdb/app/models/miq_worker.rb:266:in `start_worker'
/var/www/miq/vmdb/app/models/miq_worker.rb:150:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_worker.rb:150:in `times'
/var/www/miq/vmdb/app/models/miq_worker.rb:150:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:53:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server.rb:160:in `start'
/var/www/miq/vmdb/app/models/miq_server.rb:252:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:91:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>'


Version-Release number of selected component (if applicable):
-------------------------------------------------------------
5.8.1


How reproducible:
-----------------
Unsure


Steps to Reproduce:
-------------------
1.
2.
3.


Actual results:
--------------
NoMethodError in evm.log


Expected results:
-----------------
There should be a defined method for base_class.


Additional info:
---------------
Comment 2 Greg McCullough 2017-07-05 09:53:54 EDT
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.
Comment 3 Dave Johnson 2017-07-18 17:24:04 EDT
Nandini, can this be reproduced?  Please point Greg at it.
Comment 5 Felix Dewaleyne 2017-07-31 07:42:05 EDT
does that cover what you need to progress on this one?
Comment 6 Greg McCullough 2017-07-31 18:00:19 EDT
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.
Comment 7 Tina Fitzgerald 2017-09-28 12:58:59 EDT
* 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
Comment 8 Edu Alcaniz 2017-09-30 08:32:45 EDT
I will take care of it. I will update to you soon.
Comment 11 Tina Fitzgerald 2017-10-23 14:07:20 EDT
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
Comment 13 Tina Fitzgerald 2017-11-06 15:46:53 EST
Hi Edu/Nandini,

Any update on this ticket? 

Thanks,
Tina
Comment 18 Tina Fitzgerald 2017-11-07 11:38:21 EST
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
Comment 21 Nandini Chandra 2017-12-04 13:19:29 EST
Clearing NEEDINFO set for me.
Comment 22 Tina Fitzgerald 2017-12-20 13:45:48 EST
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.

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