Bug 1731861

Summary: Uploading facts when host is in build mode does log error at info or higher
Product: Red Hat Satellite Reporter: Peter Vreman <peter.vreman>
Component: ProvisioningAssignee: Lukas Zapletal <lzap>
Status: CLOSED ERRATA QA Contact: Peter Dragun <pdragun>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.5.0CC: inecas, pdragun, sshtein, zhunting
Target Milestone: 6.6.0Keywords: Patch, Triaged
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Fixed In Version: foreman- Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-10-22 19:50:18 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:
Bug Depends On:    
Bug Blocks: 1122832    

Description Peter Vreman 2019-07-22 08:45:38 UTC
Description of problem:
I had a problem to get facts uploaded in satellite. The request was not completed, but there is no reason written what is wrong.

[crash/LI] root@li-lc-2224:~# grep 4403a209 /var/log/foreman/production.log
2019-07-22T08:18:04 [I|app|4403a209] Processing by Api::V2::HostsController#facts as JSON
2019-07-22T08:18:04 [I|app|4403a209]   Parameters: {"facts"=>"[FILTERED]", "name"=>"li-lc-1681.hag.hilti.com", "certname"=>"li-lc-1681.hag.hilti.com", "apiv"=>"v2", "host"=>{"certname"=>"li-lc-1681.hag.hilti.com", "name"=>"li-lc-1681.hag.hilti.com"}}
2019-07-22T08:18:04 [I|app|4403a209] Completed 422 Unprocessable Entity in 23ms (Views: 0.3ms | ActiveRecord: 3.2ms)

Only when i enabled debug logging i was able to find the root cause (the system was in build mode and then it is not allowed):
[crash/LI] root@li-lc-2224:~# grep 2fead00e /var/log/foreman/production.log
2019-07-22T08:22:46 [I|app|2fead00e] Processing by Api::V2::HostsController#facts as JSON
2019-07-22T08:22:46 [I|app|2fead00e]   Parameters: {"facts"=>"[FILTERED]", "name"=>"li-lc-1681.hag.hilti.com", "certname"=>"li-lc-1681.hag.hilti.com", "apiv"=>"v2", "host"=>{"certname"=>"li-lc-1681.hag.hilti.com", "name"=>"li-lc-1681.hag.hilti.com"}}
2019-07-22T08:22:46 [D|app|2fead00e] Importer Katello::RhsmFactImporter does not implement authorized_smart_proxy_features.
2019-07-22T08:22:46 [D|app|2fead00e] Examining client certificate to extract dn and sans
2019-07-22T08:22:46 [D|app|2fead00e] Client sent certificate with subject 'li-lc-2224.hag.hilti.com' and subject alt names '["li-lc-2224.hag.hilti.com", "fibssat6c.hag.hilti.com"]'
2019-07-22T08:22:46 [D|app|2fead00e] Verifying request from ["li-lc-2224.hag.hilti.com", "fibssat6c.hag.hilti.com"] against ["li-lc-2224.hag.hilti.com"]
2019-07-22T08:22:47 [D|app|2fead00e] Body: {"message":"ERF42-9911 [Foreman::Exception]: Host is pending for Build"}
2019-07-22T08:22:47 [I|app|2fead00e] Completed 422 Unprocessable Entity in 244ms (Views: 0.6ms | ActiveRecord: 34.7ms)

Requiring debug mode to see the reason for an error is not good. It should always write the error at least at level info when returning '422 Unprocessable Entity'

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

How reproducible:

Steps to Reproduce:
1. Set host to build=true
2. Upload facts
3. What the production.log at level INFO

Actual results:
No root cause why facts upload is failing

Expected results:
Root cause (host is in build mode) is written at least at level INFO

Additional info:

Comment 3 Peter Vreman 2019-07-22 09:34:20 UTC

--- controllers/api/v2/hosts_controller.rb.190722-1     2019-06-26 11:52:05.460091801 +0000
+++ controllers/api/v2/hosts_controller.rb      2019-07-22 09:18:28.300754718 +0000
@@ -289,6 +289,7 @@
         state = @host.import_facts(factshash, detected_proxy)
         process_response state
       rescue ::Foreman::Exception => e
+        logger.info("Facts processing failed: #{e.to_s}")
         render_message(e.to_s, :status => :unprocessable_entity)

Comment 5 Marek Hulan 2019-08-08 15:10:17 UTC
Created redmine issue https://projects.theforeman.org/issues/27556 from this bug

Comment 6 Bryan Kearney 2019-08-09 10:05:37 UTC
Upstream bug assigned to lzap

Comment 7 Bryan Kearney 2019-08-09 10:05:39 UTC
Upstream bug assigned to lzap

Comment 8 Bryan Kearney 2019-08-28 08:05:42 UTC
Moving this bug to POST for triage into Satellite 6 since the upstream issue https://projects.theforeman.org/issues/27556 has been resolved.

Comment 10 Peter Dragun 2019-09-18 12:53:58 UTC
Verified on Satellite 6.6 snap 20.1. Reason is now written at warning level.

2019-09-18T08:47:07 [W|app|e3967e5b] ERF42-9911 [Foreman::Exception]: Host is pending for Build

Comment 11 Bryan Kearney 2019-10-22 19:50:18 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.