Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Logout sometimes fails with 401 response #160

Open
gabrielcocenza opened this issue Jul 16, 2024 · 3 comments
Open

Logout sometimes fails with 401 response #160

gabrielcocenza opened this issue Jul 16, 2024 · 3 comments

Comments

@gabrielcocenza
Copy link

gabrielcocenza commented Jul 16, 2024 •
edited
Loading

I was not able to manually reproduce it, but sometimes it seems that the logout is failing with 401.

Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Login returned code 201: {"@Message.ExtendedInfo":[{"Message":"The resource has been created successfully.","MessageArgs":[],"[email protected]":0,"MessageId":"Base.1.12.Created","RelatedProperties":[],"[email protected]":0,"Resolution":"None.","Severity":"OK"},{"Message":"A new resource is successfully created.","MessageArgs":[],"[email protected]":0,"MessageId":"IDRAC.2.8.SYS414","RelatedProperties":[],"[email protected]":0,"Resolution":"No response action is required.","Severity":"Informational"}],"@odata.context":"/redfish/v1/$metadata#Session.Session","@odata.id":"/redfish/v1/SessionService/Sessions/132562","@odata.type":"#Session.v1_6_0.Session","ClientOriginIPAddress":"IP_FOR_BOND_M","CreatedTime":"2024-07-16T13:59:10-05:00","Description":"User Session","Id":"132562","Name":"User Session","Password":null,"SessionType":"Redfish","UserName":"root"}
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting redfish sensor info...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/Systems/System.Embedded.1/Memory/DIMM.Socket.A4: 0.1320378198288381 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting smart storage health data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.23425848316401243 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting processor data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.01082204794511199 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting storage controller data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.010600307956337929 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting network adapter data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.0182824837975204 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting chassis data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.4267375646159053 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting storage drive data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.03342375298961997 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting memory dimm data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.01948211621493101 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Getting smart storage health data...
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for GET to /redfish/v1/: 0.09171967394649982 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Attempt 1 of /redfish/v1/SessionService/Sessions/132562
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 INFO Response Time for DELETE to /redfish/v1/SessionService/Sessions/132562: 0.045607013162225485 seconds.
Jul 16 13:59:30 hostname python3[3681]: 2024-07-16 13:59:30 ERROR Invalid session resource: /redfish/v1/SessionService/Sessions/132562, return code: 401

From the logs it's possible to create a session and fetch information, but if fails to logout. I'm not understanding how the authorization can break during this process.

originally found on canonical/prometheus-hardware-exporter#76
@mraineri
Copy link
Contributor

I'm guessing the BMC you're using might not be properly closing sessions. Would it be possible to enable the tracing facilities in the library and reproduce the issue? The following code block should create a log file for your with all HTTP traces captured to the file "RedfishHTTPDebug.log".

from redfish import redfish_logger

# Config logger used by Restful library
LOGGERFILE = "RedfishHTTPDebug.log"
LOGGERFORMAT = "%(asctime)s - %(name)s - %(levelname)s - %(message)s"
LOGGER = redfish_logger(LOGGERFILE, LOGGERFORMAT, logging.DEBUG)
LOGGER.info("Redfish HTTP Tracing")

@gabrielcocenza
Copy link
Author

gabrielcocenza commented Jul 17, 2024 •
edited
Loading

I'll try to add this capability in our product to try to put some light in this issue.

We identify that this is happening on Dell and HPE servers:

BIOS Version: 2.21.2
iDRAC Firmware Version: 7.00.00.171

BIOS Version: 2.19.1
iDRAC Firmware Version: 6.10.80.00

I also tried to stress one server by opening multiple sessions (20 sessions) and continuously making requests. It also failed with 401, but to create a new session and not to delete as the bug description.

2024-07-17 14:43:13,620 - redfish.rest.v1 - DEBUG - HTTP REQUEST (POST) for /redfish/v1/SessionService/Sessions:
Headers:
        Accept: */*
        OData-Version: 4.0
        Content-Type: application/json

Body: {"UserName": "", "Password": "<REDACTED>"}

2024-07-17 14:43:13,620 - redfish.rest.v1 - INFO - Attempt 1 of /redfish/v1/SessionService/Sessions
2024-07-17 14:43:13,946 - redfish.rest.v1 - INFO - Response Time for POST to /redfish/v1/SessionService/Sessions: 0.3257996898610145 seconds.
2024-07-17 14:43:13,946 - redfish.rest.v1 - DEBUG - HTTP RESPONSE for /redfish/v1/SessionService/Sessions:
Code: 401 Unauthorized

Headers:
        Date: Wed, 17 Jul 2024 19:43:03 GMT
        Server: Apache
        WWW-Authenticate: Basic realm="RedfishService"
        OData-Version: 4.0
        Access-Control-Allow-Origin: *
        Cache-Control: no-cache
        X-Frame-Options: DENY
        Strict-Transport-Security: max-age=63072000; includeSubDomains; preload
        Content-Type: application/json; charset=utf-8
        Content-Length: 517
        Keep-Alive: timeout=60, max=99
        Connection: Keep-Alive

Body Response of /redfish/v1/SessionService/Sessions: b'{"error":{"@Message.ExtendedInfo":[{"Message":"Unable to complete the operation because an invalid username and/or password is entered, and therefore authentication failed.","MessageArgs":[],"[email protected]":0,"MessageId":"IDRAC.2.4.SYS415","RelatedProperties":[],"[email protected]":0,"Resolution":"Enter valid user name and password and retry the operation.","Severity":"Warning"}],"code":"Base.1.7.GeneralError","message":"A general error has occurred. See ExtendedInfo for more information"}}'

2024-07-17 14:43:13,946 - redfish.rest.v1 - INFO - Login returned code 401: {"error":{"@Message.ExtendedInfo":[{"Message":"Unable to complete the operation because an invalid username and/or password is entered, and therefore authentication failed.","MessageArgs":[],"[email protected]":0,"MessageId":"IDRAC.2.4.SYS415","RelatedProperties":[],"[email protected]":0,"Resolution":"Enter valid user name and password and retry the operation.","Severity":"Warning"}],"code":"Base.1.7.GeneralError","message":"A general error has occurred. See ExtendedInfo for more information"}}

gabrielcocenza added a commit to gabrielcocenza/prometheus-hardware-exporter that referenced this issue Jul 17, 2024
@gabrielcocenza
Igonore if redfish fails to logout with 401 as as response
dd61061 
Redfish sometimes fails to logout after scraping the data and this
end up generating the metric redfish_collector_failed that trigger
prometheus alerts that can be noise.

This can be a BMC problem that might not be properly closing
sessions.

For more info see:
DMTF/python-redfish-library#160

Closes: canonical#76
@gabrielcocenza gabrielcocenza mentioned this issue Jul 17, 2024
Merged
@mraineri
Copy link
Contributor

mraineri commented Jul 18, 2024 •
edited
Loading

If you're seeing it from different firmware on different vendors, then that makes it less likely a BMC issue. Perhaps the library is hitting a timeout or other networking issue when it issues a DELETE to the session, which would invoke a retry, and if the BMC already processed the DELETE, a 401 would return...

For that stress test you tried, it's possible you might be hitting a session limit on the BMC. At least the systems I have will return a 503 once you hit their session limit, so it might be something else entirely different.

I'll double check, but the logging traces I recommended adding should capture retry attempts as well.
Update: it does show retry attempts.

gabrielcocenza added a commit to canonical/prometheus-hardware-exporter that referenced this issue Aug 1, 2024
@gabrielcocenza
Ignore if redfish fails to logout (#78)
5ddd4d2 
* Igonore if redfish fails to logout with 401 as as response

Redfish sometimes fails to logout after scraping the data and this
end up generating the metric redfish_collector_failed that trigger
prometheus alerts that can be noise.

This can be a BMC problem that might not be properly closing
sessions.

For more info see:
DMTF/python-redfish-library#160

Closes: #76
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mraineri @gabrielcocenza