Bug 1378503

Summary: amazon refresh throws [NoMethodError]: undefined method `pop'
Product: Red Hat CloudForms Management Engine Reporter: Gellert Kis <gekis>
Component: ApplianceAssignee: Joe Rafaniello <jrafanie>
Status: CLOSED WORKSFORME QA Contact: Matouš Mojžíš <mmojzis>
Severity: medium Docs Contact:
Priority: high    
Version: 5.5.0CC: abellott, cpelland, dajohnso, gtanzill, hkataria, jfrey, jhardy, jrafanie, mhild, mmojzis, mpovolny, obarenbo
Target Milestone: GA   
Target Release: cfme-future   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: ec2:ems_refresh
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-11-16 10:17:45 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: CFME Core Target Upstream Version:

Description Gellert Kis 2016-09-22 15:02:08 UTC 
Description of problem:
happens when the scanning of amazon is queued 

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

How reproducible:
in customer environment

Steps to Reproduce:
1.
2.
3.

Actual results:
[----] I, [2016-09-21T03:22:34.413155 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...
[----] I, [2016-09-21T03:22:34.428252 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...Successful
[----] I, [2016-09-21T03:22:39.456073 #13788:47f98c]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-21T03:22:39.492520 #13947:b33990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [2000004246131], MiqWorker id: [2000000014059], Zone: [Amazon], Role: [], Server: [d9ad9cf6-7e79-11e6-ba81-001a4aae8881], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [5.815764272] seconds
[----] I, [2016-09-21T03:22:39.492745 #13947:b33990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [2000004246131], Delivering...
[----] I, [2016-09-21T03:22:39.503393 #13947:b33990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [2000004246131], State: [ok], Delivered in [0.010674934] seconds
[----] I, [2016-09-21T03:22:48.690123 #13960:ff198c]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
[----] I, [2016-09-21T03:22:49.478698 #13788:47f98c]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-21 01:22:49 UTC]...
[----] I, [2016-09-21T03:22:49.494195 #13788:47f98c]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-21 01:22:49 UTC]...Complete
[----] I, [2016-09-21T03:22:49.696724 #13788:47f98c]  INFO -- : MIQ(MiqUiWorker.sync_workers) Workers are being synchronized: Current #: [1], Desired #: [0]
[----] E, [2016-09-21T03:22:49.697436 #13788:47f98c] ERROR -- : MIQ(MiqServer#monitor) undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000a703c30>
[----] E, [2016-09-21T03:22:49.697599 #13788:47f98c] ERROR -- : [NoMethodError]: undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000a703c30>  Method:[rescue in monitor]
[----] E, [2016-09-21T03:22:49.697697 #13788:47f98c] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:136:in `method_missing'
/opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:99:in `method_missing'
/var/www/miq/vmdb/app/models/mixins/miq_web_server_worker_mixin.rb:95:in `block in sync_workers'
/var/www/miq/vmdb/app/models/mixins/miq_web_server_worker_mixin.rb:94:in `times'
/var/www/miq/vmdb/app/models/mixins/miq_web_server_worker_mixin.rb:94:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:49:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:47:in `each'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:47:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:19:in `monitor_workers'
/var/www/miq/vmdb/app/models/miq_server.rb:361:in `block in monitor'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:361:in `monitor'
/var/www/miq/vmdb/app/models/miq_server.rb:381:in `block (2 levels) in monitor_loop'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:381:in `block in monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:380:in `loop'
/var/www/miq/vmdb/app/models/miq_server.rb:380:in `monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:272:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:60:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:79:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:3:in `<top (required)>'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `load'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `<top (required)>'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require_command!'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>'
/var/www/miq/vmdb/bin/rails:4:in `require'
/var/www/miq/vmdb/bin/rails:4:in `<main>'
[----] I, [2016-09-21T03:22:49.697750 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...
[----] I, [2016-09-21T03:22:49.715896 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...Successful
[----] I, [2016-09-21T03:23:03.690762 #13960:ff198c]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
[----] I, [2016-09-21T03:23:05.019214 #13788:47f98c]  INFO -- : MIQ(MiqUiWorker.sync_workers) Workers are being synchronized: Current #: [1], Desired #: [0]
[----] E, [2016-09-21T03:23:05.020477 #13788:47f98c] ERROR -- : MIQ(MiqServer#monitor) undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x00000008cb3678>
[----] E, [2016-09-21T03:23:05.020728 #13788:47f98c] ERROR -- : [NoMethodError]: undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x00000008cb3678>  Method:[rescue in monitor]
[----] E, [2016-09-21T03:23:05.020824 #13788:47f98c] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:136:in `method_missing'
/opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:99:in `method_missing'
/var/www/miq/vmdb/app/models/mixins/miq_web_server_worker_mixin.rb:95:in `block in sync_workers'
/var/www/miq/vmdb/app/models/mixins/miq_web_server_worker_mixin.rb:94:in `times'
/var/www/miq/vmdb/app/models/mixins/miq_web_server_worker_mixin.rb:94:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:49:in `block in sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:47:in `each'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:47:in `sync_workers'
/var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:19:in `monitor_workers'
/var/www/miq/vmdb/app/models/miq_server.rb:361:in `block in monitor'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:361:in `monitor'
/var/www/miq/vmdb/app/models/miq_server.rb:381:in `block (2 levels) in monitor_loop'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/var/www/miq/vmdb/gems/pending/util/extensions/miq-benchmark.rb:30:in `realtime_block'
/var/www/miq/vmdb/app/models/miq_server.rb:381:in `block in monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:380:in `loop'
/var/www/miq/vmdb/app/models/miq_server.rb:380:in `monitor_loop'
/var/www/miq/vmdb/app/models/miq_server.rb:272:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:60:in `start'
/var/www/miq/vmdb/lib/workers/evm_server.rb:79:in `start'
/var/www/miq/vmdb/lib/workers/bin/evm_server.rb:3:in `<top (required)>'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `load'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/runner.rb:60:in `<top (required)>'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:123:in `require_command!'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>'
/var/www/miq/vmdb/bin/rails:4:in `require'
/var/www/miq/vmdb/bin/rails:4:in `<main>'


Expected results:


Additional info:
Comment 2 Gellert Kis 2016-09-23 06:46:33 UTC 
After putting an appliance into debug mode, the trace is disappeared , 
and following NoMethodError error appear ~1500 times ;

log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner'
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>'
log/evm.log-/var/www/miq/vmdb/bin/rails:4:in `require'
log/evm.log-/var/www/miq/vmdb/bin/rails:4:in `<main>'
log/evm.log:[----] I, [2016-09-22T03:24:15.271293 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...
log/evm.log:[----] I, [2016-09-22T03:24:15.283961 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...Successful
log/evm.log-[----] I, [2016-09-22T03:24:24.616424 #13960:ff198c]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
log/evm.log-[----] I, [2016-09-22T03:24:30.439992 #13788:47f98c]  INFO -- : MIQ(MiqUiWorker.sync_workers) Workers are being synchronized: Current #: [1], Desired #: [0]
log/evm.log-[----] E, [2016-09-22T03:24:30.440787 #13788:47f98c] ERROR -- : MIQ(MiqServer#monitor) undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000bf48368>
log/evm.log-[----] E, [2016-09-22T03:24:30.441018 #13788:47f98c] ERROR -- : [NoMethodError]: undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000bf48368>  Method:[rescue in monitor]
log/evm.log-[----] E, [2016-09-22T03:24:30.441091 #13788:47f98c] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:136:in `method_missing'
--
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner'
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>'
log/evm.log-/var/www/miq/vmdb/bin/rails:4:in `require'
log/evm.log-/var/www/miq/vmdb/bin/rails:4:in `<main>'
log/evm.log:[----] I, [2016-09-22T03:24:30.441134 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...
log/evm.log:[----] I, [2016-09-22T03:24:30.455155 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...Successful
log/evm.log-[----] I, [2016-09-22T03:24:39.622168 #13960:ff198c]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
log/evm.log-[----] I, [2016-09-22T03:24:39.670523 #13960:ff198c]  INFO -- : MIQ(MiqQueue.put) Message id: [2000004354590],  id: [], Zone: [Amazon], Role: [], Server: [d9ad9cf6-7e79-11e6-ba81-001a4aae8881], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
log/evm.log-[----] I, [2016-09-22T03:24:40.491463 #13788:47f98c]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
log/evm.log-[----] I, [2016-09-22T03:24:40.669839 #13944:8ff994]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [2000004354590], MiqWorker id: [2000000014058], Zone: [Amazon], Role: [], Server: [d9ad9cf6-7e79-11e6-ba81-001a4aae8881], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.016122335] seconds
log/evm.log-[----] I, [2016-09-22T03:24:40.670065 #13944:8ff994]  INFO -- : MIQ(MiqQueue#deliver) Message id: [2000004354590], Delivering...
--
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:90:in `runner'
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands/commands_tasks.rb:39:in `run_command!'
log/evm.log-/opt/rh/cfme-gemset/gems/railties-4.2.5/lib/rails/commands.rb:17:in `<top (required)>'
log/evm.log-/var/www/miq/vmdb/bin/rails:4:in `require'
log/evm.log-/var/www/miq/vmdb/bin/rails:4:in `<main>'
log/evm.log:[----] I, [2016-09-22T03:24:45.642045 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...
log/evm.log:[----] I, [2016-09-22T03:24:45.655654 #13788:47f98c]  INFO -- : MIQ(MiqServer#monitor) Reconnecting to database after error...Successful
log/evm.log-[----] I, [2016-09-22T03:24:54.671075 #13960:ff198c]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 0.
log/evm.log-[----] I, [2016-09-22T03:25:00.830593 #13788:47f98c]  INFO -- : MIQ(MiqUiWorker.sync_workers) Workers are being synchronized: Current #: [1], Desired #: [0]
log/evm.log-[----] E, [2016-09-22T03:25:00.831760 #13788:47f98c] ERROR -- : MIQ(MiqServer#monitor) undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000c6e2010>
log/evm.log-[----] E, [2016-09-22T03:25:00.832039 #13788:47f98c] ERROR -- : [NoMethodError]: undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000c6e2010>  Method:[rescue in monitor]
log/evm.log-[----] E, [2016-09-22T03:25:00.832113 #13788:47f98c] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:136:in `method_missing'
Comment 3 Marcel Hild 2016-10-04 08:51:22 UTC 
The error is at MiqUiWorker and specifically at app/models/mixins/miq_web_server_worker_mixin.rb

I guess the amazon refresh being queued is just a coincidence?

Re-Assigning to Core team, maybe UI?
Comment 4 Gellert Kis 2016-10-04 13:18:59 UTC 
Amazon refresh is no longer relevant. 
The first error miq_web_server_worker_mixin.rb is not longer visible in debug more. 

The error is the above one :  

Might be for Core team and UI worth checking .

[----] I, [2016-09-21T03:23:50.714614 #13788:47f98c]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-21 01:23:50 UTC]...
[----] I, [2016-09-21T03:23:50.729669 #13788:47f98c]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-21 01:23:50 UTC]...Complete
[----] I, [2016-09-21T03:23:50.987526 #13788:47f98c]  INFO -- : MIQ(MiqUiWorker.sync_workers) Workers are being synchronized: Current #: [1], Desired #: [0]
[----] E, [2016-09-21T03:23:50.988421 #13788:47f98c] ERROR -- : MIQ(MiqServer#monitor) undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000a7f85c8>
[----] E, [2016-09-21T03:23:50.988595 #13788:47f98c] ERROR -- : [NoMethodError]: undefined method `pop' for #<MiqUiWorker::ActiveRecord_Relation:0x0000000a7f85c8>  Method:[rescue in monitor]
[----] E, [2016-09-21T03:23:50.988672 #13788:47f98c] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-4.2.5/lib/active_record/relation/delegation.rb:136:in `method_missing'
...
Comment 5 Dave Johnson 2016-11-03 04:16:07 UTC 
Matous, are you seeing this, can you reproduce?
Comment 6 Joe Rafaniello 2016-11-03 21:19:24 UTC 
Dave,

This was fixed in https://github.com/ManageIQ/manageiq/commit/4547a4c7b4c3e5dcd5d7d4c2aa73b5c7e21d5464
as part of this PR: https://github.com/ManageIQ/manageiq/pull/6131

It should be fixed in all 5.6 and 5.7 releases.


5.5 doesn't have it:
git log --oneline --grep "Fix for disabling the web_services worker" 5.5.0.0

5.6.0.0 has it:
git log --oneline --grep "Fix for disabling the web_services worker" 5.6.0.0
bbf362d Merge pull request #6131 from agrare/bz_1286811_miq_web_server_worker_sync_workers
4547a4c Fix for disabling the web_services worker

5.7.0.0 has it:
git log --oneline --grep "Fix for disabling the web_services worker" 5.7.0.0
bbf362d Merge pull request #6131 from agrare/bz_1286811_miq_web_server_worker_sync_workers
4547a4c Fix for disabling the web_services worker

Let me know what you want to do with this.
Comment 7 Dave Johnson 2016-11-09 04:09:41 UTC 
Matous, please confirm this is working (not present) in 5.7.0 and 5.6.3.  We can then remove the 5.7 and 5.6 flags and let it stay open for cfme-5.5.z release.