Bug 1211249
| Summary: | ems_refresh undefined method error `emstype' for nil:NilClass | ||
|---|---|---|---|
| Product: | Red Hat CloudForms Management Engine | Reporter: | Thom Carlin <tcarlin> |
| Component: | Providers | Assignee: | Matthew Draper <mdraper> |
| Status: | CLOSED ERRATA | QA Contact: | Thom Carlin <tcarlin> |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 5.4.0 | CC: | gblomqui, jfrey, jhardy, obarenbo |
| Target Milestone: | GA | Keywords: | Reopened |
| Target Release: | 5.4.0 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2015-06-16 12:57:50 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
Also occurs on VMware [----] I, [2015-04-14T08:12:51.828869 #28397:12d1ea4] INFO -- : MIQ(MiqQueue.deliver) Message id: [2802], Delivering... [----] E, [2015-04-14T08:12:51.835930 #28397:12d1ea4] ERROR -- : MIQ(MiqQueue.deliver) Message id: [2802], Error: [undefined method `emstype' for nil:NilClass] [----] E, [2015-04-14T08:12:51.836254 #28397:12d1ea4] ERROR -- : [NoMethodError]: undefined method `emstype' for nil:NilClass Method:[rescue in deliver] [----] E, [2015-04-14T08:12:51.836438 #28397:12d1ea4] ERROR -- : /var/www/miq/vmdb/app/models/ems_refresh.rb:73:in `block in refresh' /var/www/miq/vmdb/app/models/ems_refresh.rb:67:in `each' /var/www/miq/vmdb/app/models/ems_refresh.rb:67:in `group_by' /var/www/miq/vmdb/app/models/ems_refresh.rb:67:in `refresh' /var/www/miq/vmdb/app/models/miq_queue.rb:356: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-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `eval' /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `<top (required)>' /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `require' /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `<top (required)>' script/rails:6:in `require' script/rails:6:in `<main>' [----] I, [2015-04-14T08:12:51.836757 #28397:12d1ea4] INFO -- : MIQ(MiqQueue.delivered) Message id: [2802], State: [error], Delivered in [0.007879138] seconds Thom tried to reproduce this a couple times today, but couldn't get an environment where it would show up again. Neither of us are sure the specific steps to reproduce and we're not seeing the error in the appliances tested today. If a reproducer shows up, please reopen and capture the IP of the offending appliance so we can dig into logs and the database. Closing as worksforme for now. I'm pretty sure that was handled before. I believe one of Keenan's changes to the EmsRefresh.queue_refresh may have broken it... See commits https://github.com/ManageIQ/manageiq/commit/a5f4110744ced6601fc0429b26dbb5fd88eeb5a9 https://github.com/ManageIQ/manageiq/commit/068485e33e7244299d8bbbd4496a50986ce4f23a New commit detected on manageiq/master: https://github.com/ManageIQ/manageiq/commit/b87a9ba2a388cb131b2b6e4af8f56bd406c5a745 commit b87a9ba2a388cb131b2b6e4af8f56bd406c5a745 Author: Matthew Draper <mdraper> AuthorDate: Thu Apr 23 06:14:12 2015 +0930 Commit: Matthew Draper <mdraper> CommitDate: Thu Apr 23 06:14:12 2015 +0930 Silently ignore archived VMs during refresh This restores behaviour that seems to have gradually faded between 068485e33e7244299d8bbbd4496a50986ce4f23a (lost the comment) and 3abfa1dd9e134667e2b58abbd20830762aaa250b (broke nil handling). But now we have tests! https://bugzilla.redhat.com/show_bug.cgi?id=1211249 vmdb/app/models/ems_refresh.rb | 2 ++ vmdb/spec/models/ems_refresh_spec.rb | 24 ++++++++++++++++++++++++ 2 files changed, 26 insertions(+) I believe this was broken during the development of 5.4 and was never released in the product. I doubt this requires doctext. Verified in 5.4.0.0.24.20150427192818_1fd9e49 (by absence of error) Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://rhn.redhat.com/errata/RHBA-2015-1100.html |
Description of problem: During initial RHEVM 3.5 discovery/cluster fleecing, saw error in log Version-Release number of selected component (if applicable): 5.4.0.0.19.20150410165622_ad23806 How reproducible: Uncertain Steps to Reproduce: 1. Discover VM 2. 3. Actual results: Errors (below) Expected results: No error Additional info: evm.log excerpts: [----] I, [2015-04-13T07:50:17.162023 #2523:e23eac] INFO -- : MIQ(MiqQueue.put) Message id: [5370], id: [], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_1], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[["VmRedhat", 64]]] [...] [----] I, [2015-04-13T07:50:17.752933 #2523:e23eac] INFO -- : MIQ(MiqQueue.merge) Message id: [5370] updated with following: {:queue_name=>"ems_1", :state=>"ready", :zone=>"default", :class_name=>"EmsRefresh", :method_name=>"refresh", :role=>"ems_inventory", :args=>[[["VmRedhat", 64], ["EmsRedhat", 1]]], :msg_timeout=>7200, :task_id=>nil} [----] I, [2015-04-13T07:50:17.753263 #2523:e23eac] INFO -- : MIQ(MiqQueue.merge) Message id: [5370], id: [], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_1], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[["VmRedhat", 64], ["EmsRedhat", 1]]], Requeued [...] [----] I, [2015-04-13T07:50:23.278274 #47708:329eac] INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [5370], MiqWorker id: [54], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_1], Tar get id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[["VmRedhat", 64], ["EmsRedhat", 1]]], Dequ eued in: [6.12905883] seconds [----] I, [2015-04-13T07:50:23.278496 #47708:329eac] INFO -- : MIQ(MiqQueue.deliver) Message id: [5370], Delivering... [----] E, [2015-04-13T07:50:23.287609 #47708:329eac] ERROR -- : MIQ(MiqQueue.deliver) Message id: [5370], Error: [undefined method `emstype' for nil:NilClass] [----] E, [2015-04-13T07:50:23.287837 #47708:329eac] ERROR -- : [NoMethodError]: undefined method `emstype' for nil:NilClass Method:[rescue in deliver] [----] E, [2015-04-13T07:50:23.287981 #47708:329eac] ERROR -- : /var/www/miq/vmdb/app/models/ems_refresh.rb:73:in `block in refresh' /var/www/miq/vmdb/app/models/ems_refresh.rb:67:in `each' /var/www/miq/vmdb/app/models/ems_refresh.rb:67:in `group_by' /var/www/miq/vmdb/app/models/ems_refresh.rb:67:in `refresh' /var/www/miq/vmdb/app/models/miq_queue.rb:356: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-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `eval' /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `<top (required)>' /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `require' /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `<top (required)>' script/rails:6:in `require' script/rails:6:in `<main>' [----] I, [2015-04-13T07:50:23.288322 #47708:329eac] INFO -- : MIQ(MiqQueue.delivered) Message id: [5370], State: [error], Delivered in [0.009827711] seconds [----] I, [2015-04-13T07:50:24.459906 #2551:104fe9c] INFO -- : MIQ(ScheduleWorker.do_work) Number of scheduled items to be processed: 5. Will try to update with reproducer