Bug 1731861 - Uploading facts when host is in build mode does log error at info or higher
Summary: Uploading facts when host is in build mode does log error at info or higher
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Provisioning
Version: 6.5.0
Hardware: Unspecified
OS: Unspecified
Target Milestone: 6.6.0
Assignee: Lukas Zapletal
QA Contact: Peter Dragun
Depends On:
Blocks: 1122832
TreeView+ depends on / blocked
Reported: 2019-07-22 08:45 UTC by Peter Vreman
Modified: 2019-10-22 19:50 UTC (History)
4 users (show)

Fixed In Version: foreman-
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Last Closed: 2019-10-22 19:50:18 UTC
Target Upstream Version:

Attachments (Terms of Use)

System ID Private Priority Status Summary Last Updated
Foreman Issue Tracker 27556 0 Normal Closed Uploading facts when host is in build mode does log error at info or higher 2020-03-27 23:34:11 UTC

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.


Note You need to log in before you can comment on or make changes to this bug.