Bug 1924816 - Misleading error messages in ironic-conductor log
Summary: Misleading error messages in ironic-conductor log
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Bare Metal Hardware Provisioning
Version: 4.7
Hardware: Unspecified
OS: Unspecified
low
low
Target Milestone: ---
: 4.8.0
Assignee: Bob Fournier
QA Contact: Lubov
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2021-02-03 17:07 UTC by Lubov
Modified: 2021-07-27 22:41 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Cause: When Ironic attempted to access the redfish/v1/SessionService URL it would log a Authentication error because this URL requires authentication. Consequence: This is just a nuisance error message in the logs, its not a functional problem. Fix: Prevent logging this error message. Result: The logs no longer have the error message.
Clone Of:
Environment:
Last Closed: 2021-07-27 22:40:58 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
example of conductor log (315.81 KB, application/zip)
2021-02-03 17:07 UTC, Lubov
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Github openshift ironic-image pull 150 0 None closed Start using current ironic versions 2021-03-17 18:39:50 UTC
OpenStack gerrit 774760 0 None MERGED Don't log ERROR if GET of /redfish/v1/SessionService fails 2021-02-15 13:00:05 UTC
Red Hat Product Errata RHSA-2021:2438 0 None None None 2021-07-27 22:41:22 UTC

Description Lubov 2021-02-03 17:07:40 UTC
Created attachment 1754818 [details]
example of conductor log

Description of problem:
There are errors reported in ironic-conductor log that causes confusion and hide the real failure reason.
These errors are reported even in the case of successful deployment.
May they be reported as a warning and be reported as an error only in case of causing a real failure? 


 ERROR sushy.connector [req-794f4ed3-eb06-4375-91cb-52d1a8b67e56 bootstrap-user - - - -] Authentication error detected. Cannot proceed: HTTP GET https://10.46.61.40/redfish/v1/SessionService returned code 401. Base.1.0.GeneralError: The authentication credentials included with this request are missing or invalid. Extended information: [{'@odata.type': '#Message.v1_0_0.Message', 'MessageId': 'Base.1.2.AccessDenied', 'Message': 'The authentication credentials included with this request are missing or invalid.', 'MessageArgs': [], 'MessageArgs': 0, 'RelatedProperties': [], 'RelatedProperties': 0, 'Severity': 'Critical', 'Resolution': 'Attempt to ensure that the URI is correct and that the service has the appropriate credentials.'}]: sushy.exceptions.AccessError: HTTP GET https://10.46.61.40/redfish/v1/SessionService returned code 401. Base.1.0.GeneralError: The authentication credentials included with this request are missing or invalid. Extended information: [{'@odata.type': '#Message.v1_0_0.Message', 'MessageId': 'Base.1.2.AccessDenied', 'Message': 'The authentication credentials included with this request are missing or invalid.', 'MessageArgs': [], 'MessageArgs': 0, 'RelatedProperties': [], 'RelatedProperties': 0, 'Severity': 'Critical', 'Resolution': 'Attempt to ensure that the URI is correct and that the service has the appropriate credentials.

ERROR ironic.conductor.cleaning [req-64b1172d-3068-48ab-903b-7dbbbf9ad52f bootstrap-user - - - -] Caching of bios settings failed on node 8aab2e24-ae1c-4905-9a21-59df23db06d8. Continuing with node cleaning.: ironic.common.exception.InvalidParameterValue: The following errors were encountered while parsing driver_info:
'drac_address' not supplied to DracDriver.
'drac_username' not supplied to DracDriver.
'drac_password' not supplied to DracDriver.
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning Traceback (most recent call last):
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning   File "/usr/lib/python3.6/site-packages/ironic/conductor/cleaning.py", line 83, in do_node_clean
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning     task.driver.bios.cache_bios_settings(task)
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning   File "/usr/lib/python3.6/site-packages/ironic/drivers/modules/drac/bios.py", line 366, in cache_bios_settings
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning     client = drac_common.get_drac_client(node)
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning   File "/usr/lib/python3.6/site-packages/ironic/drivers/modules/drac/common.py", line 109, in get_drac_client
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning     driver_info = parse_driver_info(node)
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning   File "/usr/lib/python3.6/site-packages/ironic/drivers/modules/drac/common.py", line 92, in parse_driver_info
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning     raise exception.InvalidParameterValue(msg)
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning ironic.common.exception.InvalidParameterValue: The following errors were encountered while parsing driver_info:
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_address' not supplied to DracDriver.
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_username' not supplied to DracDriver.
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_password' not supplied to DracDriver.
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning
 

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

How reproducible:
100%

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:
attaching conductor log as an example

Comment 1 Bob Fournier 2021-02-09 20:19:53 UTC
I think these are 2 separate issues:

The first ERROR message occurs before the session has been authenticated. This is as expected, there was a fix here https://review.opendev.org/c/openstack/sushy/+/747960 to remove the warning and instead print text regarding "If this happens before authentication". 

2021-02-03 05:43:46.132 1 ERROR sushy.connector [req-ac25c507-557b-4b69-923f-4933bc9f3601 bootstrap-user - - - -] Authentication error detected. Cannot proceed: HTTP GET https://10.46.61.42/redfish/v1/SessionService returned code 401. Base.1.0.GeneralError: The authentication credentials included with this request are missing or invalid
<snip>

2021-02-03 05:43:46.132 1 DEBUG sushy.resources.sessionservice.sessionservice [req-ac25c507-557b-4b69-923f-4933bc9f3601 bootstrap-user - - - -] Received access error "HTTP GET https://10.46.61.42/redfish/v1/SessionService returned code 401. Base.1.0.GeneralError: The authentication credentials included with this request are missing or invalid. Extended information: [{'@odata.type': '#Message.v1_0_0.Message', 'MessageId': 'Base.1.2.AccessDenied', 'Message': 'The authentication credentials included with this request are missing or invalid.', 'MessageArgs': [], 'MessageArgs': 0, 'RelatedProperties': [], 'RelatedProperties': 0, 'Severity': 'Critical', 'Resolution': 'Attempt to ensure that the URI is correct and that the service has the appropriate credentials.'}]" when trying to refresh the SessionService. If this happens before authentication, we'll have to guess the Sessions URL. __init__ /usr/lib/python3.6/site-packages/sushy/resources/sessionservice/sessionservice.py

The first ERROR message though should probably be handled better here - https://github.com/openstack/sushy/blob/master/sushy/connector.py#L145 although its not clear we can distinguish this expected behaviour from an actual authentication error.

Comment 2 Bob Fournier 2021-02-10 02:24:29 UTC
Will add a patch shortly for the first issue above...

The second issue, the failure with getting bios_settings and the errors:
driver_info:
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_address' not supplied to DracDriver.
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_username' not supplied to DracDriver.
2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_password' not supplied to DracDriver.

is happening because of the bios_interface configuration.
'bios_interface': 'idrac-wsman'
but redfish credentials are provided, not idrac.

Can you set the bios_interface to 'redfish' and try this again?

Comment 3 Lubov 2021-02-11 11:14:13 UTC
(In reply to Bob Fournier from comment #2)
> Will add a patch shortly for the first issue above...
> 
> The second issue, the failure with getting bios_settings and the errors:
> driver_info:
> 2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_address' not
> supplied to DracDriver.
> 2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_username'
> not supplied to DracDriver.
> 2021-02-03 05:51:35.688 1 ERROR ironic.conductor.cleaning 'drac_password'
> not supplied to DracDriver.
> 
> is happening because of the bios_interface configuration.
> 'bios_interface': 'idrac-wsman'
> but redfish credentials are provided, not idrac.
> 
> Can you set the bios_interface to 'redfish' and try this again?

No such error when running with redfish-virtualmedia

Comment 4 Bob Fournier 2021-02-15 15:37:16 UTC
I'm going to split this bug as there are 2 separate issues.  This bug will be used to track the "Authentication error detected." log which has a fix. This new bug 
https://bugzilla.redhat.com/show_bug.cgi?id=1928816 will be used to track the bios_interface issue.

Comment 5 Bob Fournier 2021-03-17 18:39:52 UTC
Sushy fix is in python-sushy-3.6.2-0.20210210081213.07ca7f4.el8 which was added to ironic-image with this change https://github.com/openshift/ironic-image/pull/150.

Moving to ON_QA.

Comment 6 Lubov 2021-03-18 16:36:36 UTC
verified on 4.8.0-0.nightly-2021-03-18-075013

Comment 9 errata-xmlrpc 2021-07-27 22:40:58 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 (Moderate: OpenShift Container Platform 4.8.2 bug fix and security update), 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-2021:2438


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