Bug 1637042

Summary: undefined method `[]' for nil:NilClass when more virt-who reports are sent a short time after other
Product: Red Hat Satellite Reporter: Pavel Moravec <pmoravec>
Component: Subscriptions - virt-whoAssignee: Partha Aji <paji>
Status: CLOSED ERRATA QA Contact: Perry Gagne <pgagne>
Severity: high Docs Contact:
Priority: high    
Version: 6.3.3CC: aeladawy, arahaman, bbuckingham, ehelms, gscarbor, hsun, jbhatia, jturel, khowell, knakai, ktordeur, kuhuang, mverma, paji, satellite6-bugs, shisingh, suarora, wpinheir, wpoteat
Target Milestone: 6.5.0Keywords: Triaged
Target Release: Unused   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: tfm-rubygem-katello-3.10.0 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-05-14 12:38:11 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:

Description Pavel Moravec 2018-10-08 13:47:28 UTC
Description of problem:
When sending a virt-who report to Satellite a short time after a previous one (from even different set of hypervisors), Satellite's task Hypervisors fail on

undefined method `[]' for nil:NilClass

error.

I reproduced it on 6.3.4 snap 2, but older/other versions of 6.3 are expected to have the bug as well.


Version-Release number of selected component (if applicable):
Sat 6.3.4 (should be reproducible on older versions as well)
- satellite-6.3.4-2.el7sat.noarch
- tfm-rubygem-katello-3.4.5.86-1.el7sat.noarch
- candlepin-2.1.24-1.el7.noarch


How reproducible:
100% in several attempts


Steps to Reproduce:
1. Send concurrently (within 10 seconds or so) several virt-who reports - ideally, generate the json file via virt-who -op for each hypervisor (to have multiple reports), and then run:

for file in $(ls virt-who.report.*.json); do curl -ks -u admin:Password -X POST -H "Content-Type: text/plain" -d @${file} 'https://satellite.example.com/rhsm/hypervisors/ORGANIZATION' & done

2. Check status of Hypervisors tasks spawned


Actual results:
Some of the tasks fail with:

2018-10-08 14:34:49  [foreman-tasks/action] [E] undefined method `[]' for nil:NilClass (NoMethodError)
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/katello/host/hypervisors.rb:23:in `block in parse_hypervisors'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/katello/host/hypervisors.rb:22:in `each'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/katello/host/hypervisors.rb:22:in `parse_hypervisors'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/candlepin/async_hypervisors.rb:14:in `poll_external_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/candlepin/async_hypervisors.rb:20:in `invoke_external_task'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action/polling.rb:83:in `initiate_external_action'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.34/lib/dynflow/action/polling.rb:18:in `run'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/candlepin/abstract_async_task.rb:9:in `run'
..


Expected results:
No such nullpointer exception


Additional info:
The reason is, Candlepin responded with WAITING state of a task (not sure if it is a new task or an announcement candlepin is busy), what katello cant react on properly. That is evident when I put to /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.86/app/lib/actions/candlepin/async_hypervisors.rb :

      def poll_external_task(task_id = external_task[:id])
        task = ::Katello::Resources::Candlepin::Job.get(task_id, :result_data => true)
        unless ::Katello::Resources::Candlepin::Job.not_finished?(task)
          Rails.logger.info("PavelM: finished task=#{task.inspect}")     ################### add this debug line
          output[:hypervisors] = ::Actions::Katello::Host::Hypervisors.parse_hypervisors(task.delete('resultData'))
        end
        task
      end

that returned:

2018-10-08 15:39:26 4d9bdaeb [app] [I] PavelM: finished task={"id"=>"hypervisor_update_0376d314-c552-4920-b7f3-af2f1679bb8b", "state"=>"WAITING", "startTime"=>nil, "finishTime"=>nil, "result"=>nil, "principalName"=>"foreman_admin", "targetType"=>"owner", "targetId"=>"ORGANIZATION", "ownerId"=>"ORGANIZATION", "correlationId"=>"4d9bdaeb", "resultData"=>nil, "statusPath"=>"/jobs/hypervisor_update_0376d314-c552-4920-b7f3-af2f1679bb8b", "done"=>false, "group"=>"async group", "created"=>"2018-10-08T13:39:25+0000", "updated"=>"2018-10-08T13:39:25+0000"}

instead of typical:

2018-10-08 15:39:28 c9174a73 [app] [I] PavelM: finished task={"id"=>"hypervisor_update_b5bc3425-39ab-4792-98e2-37fecf2918c1", "state"=>"FINISHED", "startTime"=>"2018-10-08T13:39:22+0000", "finishTime"=>"2018-10-08T13:39:27+0000", "result"=>"Created: 0, Updated: 47, Unchanged:123, ..

Comment 1 Kevin Howell 2018-10-08 14:58:54 UTC
Brad, this looks like a Katello issue. Katello should handle a status of "WAITING " similar to "PENDING". Thoughts?

Comment 2 Brad Buckingham 2018-10-08 18:15:43 UTC
My change was not intended to remove the needinfo.  Adding it back.

Comment 9 Partha Aji 2018-12-10 18:55:18 UTC
Connecting redmine issue https://projects.theforeman.org/issues/25643 from this bug

Comment 10 Satellite Program 2018-12-10 23:11:22 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue https://projects.theforeman.org/issues/25643 has been resolved.

Comment 12 Perry Gagne 2019-01-14 21:30:45 UTC
Verified fix in sat 6.5 snap 11. 

I ran :
curl -k -X POST --user $SATUSER:$SATPASS https://$SATHOST/rhsm/hypervisors/Default_Organization -H "Content-Type: application/json" -d @"/root/foo.json"


Multiple times in quick succession. foo.json contained a fairly large number of reports. All of the Hypervisors tasks were successful

Comment 13 Barnaby Court 2019-01-30 20:01:11 UTC
*** Bug 1667545 has been marked as a duplicate of this bug. ***

Comment 15 errata-xmlrpc 2019-05-14 12:38:11 UTC
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://access.redhat.com/errata/RHSA-2019:1222