Bug 1568040

Summary: OpenShift 3.7 Refresh Fails Undefined method 'each' Error when saving InventoryCollection
Product: Red Hat CloudForms Management Engine Reporter: myoder
Component: ProvidersAssignee: Mooli Tayer <mtayer>
Status: CLOSED DUPLICATE QA Contact: Einat Pacifici <epacific>
Severity: medium Docs Contact:
Priority: high    
Version: 5.9.0CC: cben, cpelland, gblomqui, jfrey, jhardy, mfeifer, mtayer, myoder, obarenbo
Target Milestone: GA   
Target Release: 5.9.3   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2018-05-09 06:51:45 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: Bug
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: Container Management Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1561041    

Description myoder 2018-04-16 16:11:56 UTC
Description of problem:


Refresh is failing for OpenShift 3.7 provider with the following errors:


[----] E, [2018-04-12T03:31:31.034554 #24863:105d13c] ERROR -- : MIQ(ManagerRefresh::SaveCollection::Saver::Default#save!) Error when saving InventoryCollection:<ContainerService>, blacklist: [namespace] with strategy: , saver_strategy: 
default, targeted: false. Message: undefined method `each' for nil:NilClass
[----] I, [2018-04-12T03:31:31.034717 #24863:105d13c]  INFO -- : Exception in realtime_block :ems_refresh - Timings: {:collect_inventory_for_targets=>5.765163421630859, :parse_targeted_inventory=>9.739534139633179, :save_inventory=>8.322
40915298462, :ems_refresh=>23.82739567756653}
[----] E, [2018-04-12T03:31:31.034808 #24863:105d13c] ERROR -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [Production], id: [2] Refresh failed
[----] E, [2018-04-12T03:31:31.034979 #24863:105d13c] ERROR -- : [NoMethodError]: undefined method `each' for nil:NilClass  Method:[block in method_missing]
[----] E, [2018-04-12T03:31:31.035059 #24863:105d13c] ERROR -- : /opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/associations/collection_association.rb:385:in `replace'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/associations/collection_association.rb:48:in `writer'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/associations/builder/association.rb:119:in `container_groups='
/opt/rh/cfme-gemset/gems/activemodel-5.0.6/lib/active_model/attribute_assignment.rb:46:in `public_send'
/opt/rh/cfme-gemset/gems/activemodel-5.0.6/lib/active_model/attribute_assignment.rb:46:in `_assign_attribute'
/opt/rh/cfme-gemset/gems/activemodel-5.0.6/lib/active_model/attribute_assignment.rb:40:in `block in _assign_attributes'
/opt/rh/cfme-gemset/gems/activemodel-5.0.6/lib/active_model/attribute_assignment.rb:39:in `each'
/opt/rh/cfme-gemset/gems/activemodel-5.0.6/lib/active_model/attribute_assignment.rb:39:in `_assign_attributes'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/attribute_assignment.rb:26:in `_assign_attributes'
/opt/rh/cfme-gemset/gems/activemodel-5.0.6/lib/active_model/attribute_assignment.rb:33:in `assign_attributes'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/core.rb:319:in `initialize'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/inheritance.rb:65:in `new'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/inheritance.rb:65:in `new'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/persistence.rb:50:in `create!'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/saver/default.rb:17:in `create_record!'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/saver/base.rb:120:in `block (2 levels) in save!'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/saver/base.rb:117:in `each'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/saver/base.rb:117:in `block in save!'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/opt/rh/cfme-gemset/gems/activerecord-5.0.6/lib/active_record/transactions.rb:211:in `transaction'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/saver/base.rb:116:in `save!'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/saver/base.rb:67:in `save_inventory_collection!'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/base.rb:22:in `save_inventory'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/base.rb:12:in `save_inventory_object_inventory'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/topological_sort.rb:19:in `block (2 levels) in save_collections'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/topological_sort.rb:18:in `each'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/topological_sort.rb:18:in `block in save_collections'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/topological_sort.rb:16:in `each'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/topological_sort.rb:16:in `each_with_index'
/var/www/miq/vmdb/app/models/manager_refresh/save_collection/topological_sort.rb:16:in `save_collections'
/var/www/miq/vmdb/app/models/manager_refresh/save_inventory.rb:15:in `save_inventory'
/var/www/miq/vmdb/app/models/manager_refresh/inventory/persister.rb:26:in `persist!'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:170:in `save_inventory'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:92:in `block in refresh_targets_for_ems'
/opt/rh/cfme-gemset/bundler/gems/manageiq-gems-pending-22145df40925/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/opt/rh/cfme-gemset/bundler/gems/manageiq-gems-pending-22145df40925/lib/gems/pending/util/extensions/miq-benchmark.rb:28:in `realtime_block'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:92:in `refresh_targets_for_ems'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:24:in `block (2 levels) in refresh'
/opt/rh/cfme-gemset/bundler/gems/manageiq-gems-pending-22145df40925/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store'
/opt/rh/cfme-gemset/bundler/gems/manageiq-gems-pending-22145df40925/lib/gems/pending/util/extensions/miq-benchmark.rb:35:in `realtime_block'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:24:in `block in refresh'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:14:in `each'
/var/www/miq/vmdb/app/models/ems_refresh/refreshers/ems_refresher_mixin.rb:14:in `refresh'
/var/www/miq/vmdb/app/models/manageiq/providers/base_manager/refresher.rb:9:in `refresh'
/var/www/miq/vmdb/app/models/ems_refresh.rb:97:in `block in refresh'
/var/www/miq/vmdb/app/models/ems_refresh.rb:96:in `each'
/var/www/miq/vmdb/app/models/ems_refresh.rb:96:in `refresh'



These are the log lines from when the refresh was picked up off the queue leading up to the refresh error:


[----] I, [2018-04-12T03:31:07.204508 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::RefreshWorker::Runner#get_message_via_drb) Message id: [3822180], MiqWorker id: [377], Zone: [default], Role: [ems_inv
entory], Server: [], Ident: [ems_2], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [dequeue], Deliver On: [], Data: [1 bytes], Args: [], Dequeued in: [8.571486689] se
conds
[----] I, [2018-04-12T03:31:07.204665 #24863:105d13c]  INFO -- : MIQ(MiqQueue#deliver) Message id: [3822180], Delivering...
[----] I, [2018-04-12T03:31:07.206881 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) Refreshing all targets...
[----] I, [2018-04-12T03:31:07.207002 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [Production], id: [2] Refreshing targets for EMS...
[----] I, [2018-04-12T03:31:07.207209 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh) EMS: [Production], id: [2]   ManageIQ::Providers::Openshift::ContainerManager [Production] id [2]
[----] I, [2018-04-12T03:31:07.207411 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::Openshift::ContainerManager: [Production]
[----] I, [2018-04-12T03:31:09.770029 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::Openshift::ContainerManager: [Production]
[----] I, [2018-04-12T03:31:12.972537 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Openshift::ContainerManager::Refresher#refresh_targets_for_ems) EMS: [Production], id: [2] Refreshing target ManageIQ::Providers::Openshift::Contai
nerManager [Production] id [2]...
[----] I, [2018-04-12T03:31:23.470674 #24863:105d13c]  INFO -- : MIQ(ManagerRefresh::SaveInventory.save_inventory) EMS: [Production], id: [2] Saving EMS Inventory...
[----] I, [2018-04-12T03:31:29.498235 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-7zklb] id [13188] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.506145 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15321] from EMS
[----] I, [2018-04-12T03:31:29.517982 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-c69l4] id [13189] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.525836 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15322] from EMS
[----] I, [2018-04-12T03:31:29.537774 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-f8xdh] id [13190] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.545616 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15323] from EMS
[----] I, [2018-04-12T03:31:29.557445 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-fsbkl] id [13191] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.565202 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15324] from EMS
[----] I, [2018-04-12T03:31:29.578625 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-jvvk7] id [13192] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.586224 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15325] from EMS
[----] I, [2018-04-12T03:31:29.598911 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-kpf2z] id [13193] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.607239 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15326] from EMS
[----] I, [2018-04-12T03:31:29.619714 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-qvsr7] id [13194] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.627987 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15327] from EMS
[----] I, [2018-04-12T03:31:29.641536 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-xgj6j] id [13195] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.649501 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15328] from EMS
[----] I, [2018-04-12T03:31:29.662341 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::ContainerGroup#disconnect_inv) Disconnecting Pod [logging-fluentd-zr82t] id [13196] from EMS [Production] id [2]
[----] I, [2018-04-12T03:31:29.670466 #24863:105d13c]  INFO -- : MIQ(ManageIQ::Providers::Kubernetes::ContainerManager::Container#disconnect_inv) Disconnecting Container [fluentd-elasticsearch] id [15329] from EMS


Version-Release number of selected component (if applicable):
CFME 5.9.0.22
OpenShift 3.7

How reproducible:
customer environment

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 3 Mooli Tayer 2018-05-03 10:14:03 UTC
Beni is this be a duplicate of bz 1558209?

Comment 6 Beni Paskin-Cherniavsky 2018-05-06 15:32:45 UTC
Good catch, definitely looks like a dup of bug 1558209, and should be fixed in 5.9.1.1.
However in this bug the crash is in activerecord saving, stacktrace doesn't directly indicate what was wrong *in the data*, only that it was in ContainerService collection and something with nil.

=> I'll explain/ask on the support case before closing this BZ.

Comment 7 Beni Paskin-Cherniavsky 2018-05-09 06:51:45 UTC
Customer confirmed upgrading helped, which strongly indicates it was the known problem, closing as duplicate.

*** This bug has been marked as a duplicate of bug 1558209 ***