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

Intermittent false RESP_HEADERS_LINK_REL_DESCRIBED_BY errors, maybe related to Task use in Account creation #86

Open
blakehilliard opened this issue Oct 8, 2024 · 6 comments
Open

Intermittent false RESP_HEADERS_LINK_REL_DESCRIBED_BY errors, maybe related to Task use in Account creation #86

blakehilliard opened this issue Oct 8, 2024 · 6 comments

Comments

@blakehilliard
Copy link

blakehilliard commented Oct 8, 2024 •
edited
Loading

I have a redfish service where creating an Account is done with a task, like this:

> POST '{"UserName":"rfpvddf7", "RoleId": "ReadOnly", "Password": "blahblahblah"}' to /redfish/v1/AccountService/Accounts
HTTP/1.1 202 Accepted
...
Link: <http://redfish.dmtf.org/schemas/Task.v1_7_2.json>; rel=describedby
...
{
    "@odata.etag": "\"c297aa488d7e87beb9a69bf9e9c4b0a3\"",
    "@odata.id": "/redfish/v1/TaskService/Tasks/7a93bf9e30e74282b650282f887a2071",
    "@odata.type": "#Task.v1_7_2.Task",
    "Id": "7a93bf9e30e74282b650282f887a2071",
    "Messages": [],
    "Name": "Task 7a93bf9e30e74282b650282f887a2071",
    "Payload": {
        "HttpOperation": "POST",
        "JsonBody": "{\"UserName\": \"rfpvddf7\", \"RoleId\": \"ReadOnly\", \"Password\": null}",
        "TargetUri": "/redfish/v1/AccountService/Accounts"
    },
    "StartTime": "2024-10-08T14:29:29Z",
    "TaskMonitor": "/redfish/v1/TaskService/Tasks/7a93bf9e30e74282b650282f887a2071/Monitor",
    "TaskState": "New",
    "TaskStatus": "OK"
}

> GET /redfish/v1/TaskService/Tasks/7a93bf9e30e74282b650282f887a2071/Monitor
HTTP/1.1 201 Created
...
Link: <http://redfish.dmtf.org/schemas/ManagerAccount.v1_11_0.json>; rel=describedby
...
{
    "@Redfish.WriteableProperties": [
        "Password"
    ],
    "@odata.etag": "\"70fdff9c63bfcf9651c642cce13f4d2e\"",
    "@odata.id": "/redfish/v1/AccountService/Accounts/rfpvddf7",
    "@odata.type": "#ManagerAccount.v1_11_0.ManagerAccount",
    "AccountTypes": [
        "Redfish"
    ],
    "Enabled": true,
    "Id": "rfpvddf7",
    "Keys": {
        "@odata.id": "/redfish/v1/AccountService/Accounts/rfpvddf7/Keys"
    },
    "Links": {
        "Role": {
            "@odata.id": "/redfish/v1/AccountService/Roles/ReadOnly"
        }
    },
    "Locked": false,
    "Name": "User Account rfpvddf7",
    "Password": null,
    "RoleId": "ReadOnly",
    "UserName": "rfpvddf7"
}

Sometimes, Redfish-Protocol-Validator fails because it claims that /redfish/v1/AccountService/Accounts fails the test case RESP_HEADERS_LINK_REL_DESCRIBED_BY Link header: Services shall return the Link header containing rel=describedby on GET and HEAD requests. However, I can see that we always provide the Link header with that collection. So the first issue is that the error message is wrong when this tool hits whatever problem is causing the failure.

I noticed that when the test passes, I can see it creates a new account, gets the task to see that it is created, then does some other operations on the account. Here is a snippet from our log of https requests showing what it is doing with an Account for a passing run:

[14:51:03] "POST /redfish/v1/SessionService/Sessions HTTP/1.1" 201 558
[14:51:04] "DELETE /redfish/v1/SessionService/Sessions/Administrator1cbc22ce9695481f9d3c888abf583863 HTTP/1.1" 204 -
[14:51:04] "GET /redfish/v1/AccountService/Accounts/rfpv82c5 HTTP/1.1" 200 552
[14:51:04] "POST /redfish/v1/AccountService/Accounts HTTP/1.1" 202 623
[14:51:09] "GET /redfish/v1/TaskService/Tasks/7fa23010f20045698034ac88c9915471/Monitor HTTP/1.1" 201 552
[14:51:09] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:09] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:09] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:09] "PATCH /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 400 613
[14:51:10] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:10] "PATCH /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 400 613
[14:51:10] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:10] "PATCH /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 400 576
[14:51:10] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:10] "PATCH /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:10] "GET /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 200 552
[14:51:10] "PATCH /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 412 554
[14:51:10] "DELETE /redfish/v1/AccountService/Accounts/rfpvbcc8 HTTP/1.1" 204 -
[14:51:15] "POST /redfish/v1/SessionService/Sessions HTTP/1.1" 201 558
[14:51:15] "DELETE /redfish/v1/SessionService/Sessions/Administratorc4888a2787bb49cda92a71dca3248781 HTTP/1.1" 401 540
[14:51:15] "DELETE /redfish/v1/SessionService/Sessions/Administratorc4888a2787bb49cda92a71dca3248781 HTTP/1.1" 204 -

But when I watch our log of https requests on a failing case, I see it never checks the task for the Account creation:

[14:41:19] "POST /redfish/v1/SessionService/Sessions HTTP/1.1" 201 558
[14:41:20] "DELETE /redfish/v1/SessionService/Sessions/Administrator59a5aa56749b417da5936c9ca2c7290c HTTP/1.1" 204 -
[14:41:20] "POST /redfish/v1/AccountService/Accounts HTTP/1.1" 202 623
[14:41:25] "POST /redfish/v1/SessionService/Sessions HTTP/1.1" 201 558
[14:41:26] "DELETE /redfish/v1/SessionService/Sessions/Administrator445c624a444b4bf4b9148b49dc538444 HTTP/1.1" 401 540
[14:41:26] "DELETE /redfish/v1/SessionService/Sessions/Administrator445c624a444b4bf4b9148b49dc538444 HTTP/1.1" 204 -

I do not know why the tool behaves differently in these cases.

I also notice that, regardless of whether it passes or fails, I see this in the output of Redfish-Protocol-Validator:

ERROR:root:Accounts collection could not be read
ERROR:root:Accounts collection could not be read
ERROR:root:Accounts collection could not be read

In a failing case, I see this additional line:

ERROR:root:GET on /redfish/v1/TaskService/Tasks/9bbb588ede8942118c99f43494f5eae3/Monitor caused ConnectionError exception; building HTTP 600 response
ERROR:root:Accounts collection could not be read
ERROR:root:Accounts collection could not be read

But my log shows no attempt to GET that task monitor.
@mraineri
Copy link
Contributor

mraineri commented Oct 8, 2024

Can you provide the HTML report and debug output (with --log-level DEBUG)?

The test itself does not check POST responses or task monitor responses. It only checks the GET and HEAD responses for the following resources:

  • ServiceRoot
  • ManagerNetworkProtocol
  • ComputerSystemCollection
  • ManagerAccountCollection
  • AccountService
  • PrivilegeRegistry

@blakehilliard
Copy link
Author

The debug output: rf_protocol_validator.log

@blakehilliard
Copy link
Author

The HTML report (renamed .log so github would let me attach it): RedfishProtocolValidationReport_10_08_2024_160057.log

@mraineri
Copy link
Contributor

mraineri commented Oct 8, 2024

I see in the HTML report it's showing an "HTTP 600" status code, which is a dummy code we use when the lower requests layers are throwing exceptions.

It looks like there is a connection being dropped (by the service or transient network issue) according to the debug output. This happens after the POST operation to make the new account on the first GET to check the task status:

DEBUG:urllib3.connectionpool:https://REDACTED:443 "POST /redfish/v1/AccountService/Accounts HTTP/1.1" 202 None
ERROR:root:GET on /redfish/v1/TaskService/Tasks/f00ef35a960d4798b783edaef98664a9/Monitor caused ConnectionError exception; building HTTP 600 response
DEBUG:root:response status = 600, method = GET, uri = /redfish/v1/AccountService/Accounts, resource_type = None, request_type = RequestType.NORMAL

I suspect because in this context we're performing a GET, and the original operation is on /redfish/v1/AccountService/Accounts, the task monitor polling is getting lumped into the results tracking. That behavior is not really correct, but the source of the issue is the fact we're taking exceptions when accessing the service.

@blakehilliard
Copy link
Author

It looks like there is a connection being dropped (by the service or transient network issue)

IMO this is unlikely. This happens, in this exact spot, around 50% of the time we run this tool. But we never have problems with dropped connections in any other context.

@mraineri
Copy link
Contributor

The log output shows it right here:

ERROR:root:GET on /redfish/v1/TaskService/Tasks/f00ef35a960d4798b783edaef98664a9/Monitor caused ConnectionError exception; building HTTP 600 response

That funnels through requests.get, which can throw ConnectionError when it can't communicate with the target server. This spot is also unique in that I don't see anything else in the log that indicates a task monitor is produced.

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 @blakehilliard