Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1878473

Summary: [Assisted-4.6] [Staging] host got disconnected after boot
Product: OpenShift Container Platform Reporter: Lital Alon <lalon>
Component: assisted-installerAssignee: Michael Filanov <mfilanov>
assisted-installer sub component: assisted-service QA Contact: Yuri Obshansky <yobshans>
Status: CLOSED ERRATA Docs Contact:
Severity: urgent    
Priority: urgent CC: alazar, aos-bugs, frolland, iovadia
Version: 4.5Keywords: TestBlocker
Target Milestone: ---   
Target Release: 4.6.z   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: OCP-Metal-juke-4
Fixed In Version: OCP-Metal-v1.0.9.5 Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-08-25 13:49:22 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:
Embargoed:
Attachments:
Description Flags
OCM responses none

Description Lital Alon 2020-09-13 09:04:27 UTC
Description of problem:
Simply booted the nodes, and waited, then one of the masters became disconnected, and with the following error message:
"User is not authenticated to perform the operation"
According to cluster events, 8 min passed since boot until got to disconnected.

Steps to Reproduce:
1. Boot nodes, and wait until node got to disconnected state


Actual results:
One node became disconnected

Expected results:
node should not move to disconnected unless it indeed disconnected

Additional info:

1. Error from Agent journal:
Sep 13 08:05:39 master-0-0 agent[2029]: time="13-09-2020 08:05:39" level=error msg="User is not authenticated to perform the operation, going to sleep forever" file="step_processor.go:97" error="[GET /clusters/>

2. Not sure why it reproduced only for one node and not the others. Also not sure if reproduce 100% of the time. still trying to understand.

Comment 1 Michael Filanov 2020-09-13 11:36:32 UTC
Any logs related to this host in the service?

Comment 2 Ronnie Lazar 2020-09-13 14:10:28 UTC
server logs:
ime="2020-09-13T08:05:38Z" level=error msg="Failed to authorize user: can't get access token: can't send request: Post \"https://sso.redhat.com/auth/realms/redhat-external/protocol/openid-connect/token\": remote error: tls: internal error" func="github.com/openshift/assisted-service/pkg/auth.(*Au

Comment 3 Ronnie Lazar 2020-09-13 14:10:53 UTC
Related slack discussion: https://coreos.slack.com/archives/CUPJTHQ5P/p1599985225444200

Comment 4 Ido Ovadia 2020-09-13 15:43:22 UTC
Reproduced to me as well on staging

Comment 5 Michael Filanov 2020-09-14 07:56:20 UTC
full log:
{code}
time="2020-09-14T05:52:12Z" level=error msg="Failed to authorize user: can't send request: Post \"https://api.stage.openshift.com/api/authorizations/v1/access_review\": read tcp 10.128.4.222:42782->3.217.136.187:443: read: connection reset by peer" func="github.com/openshift/assisted-service/pkg/auth.(*AuthzHandler).Authorizer" file="/go/src/github.com/openshift/origin/pkg/auth/authz_handler.go:64" pkg=authz
{code}

Comment 6 Michael Filanov 2020-09-14 07:59:11 UTC
Another log:
{code}
time="2020-09-13T14:37:24Z" level=error msg="Failed to authorize user: can't get access token: can't send request: Post \"https://sso.redhat.com/auth/realms/redhat-external/protocol/openid-connect/token\": remote error: tls: internal error" func="github.com/openshift/assisted-service/pkg/auth.(*AuthzHandler).Authorizer" file="/go/src/github.com/openshift/origin/pkg/auth/authz_handler.go:64" pkg=authz
{code}

Comment 7 Michael Filanov 2020-09-14 08:04:17 UTC
I found this https://github.com/openshift-online/ocm-sdk-go/blob/master/send.go#L150
so it probably the source and the error type is fmt.Error so i will search for can't send request in the error and then return 503

Comment 8 Michael Filanov 2020-09-14 08:30:04 UTC
It looks like eventually every error will return forbidden https://github.com/go-openapi/runtime/blob/master/middleware/context.go#L436-L440

Comment 9 Fred Rolland 2020-09-15 08:47:55 UTC
Created attachment 1714902 [details]
OCM responses

Comment 10 Michael Filanov 2020-09-15 10:59:05 UTC
assisted-service https://github.com/openshift/assisted-service/pull/363

Comment 11 Ido Ovadia 2020-09-15 19:06:39 UTC
Verified
========
on staging Sep 15

Comment 12 Lital Alon 2020-09-17 08:31:34 UTC
Issue still persist in Staging
Sep 17 04:26:27 master-0-0 agent[2002]: time="17-09-2020 04:26:27" level=error msg="User is not authenticated to perform the operation, going to sleep forever" file="step_processor.go:97" error="[GET /clusters/{cluster_id}/hosts/{host_id}/instructions][401] getNextStepsUnauthorized  &{Code:0xc0007e42a0 Message:0xc00080e670}" request_id=85bdfae8-ad9e-4c22-b49f-93fc53a04d51


Cluster id: c097015c-9cd5-4de0-a7be-a7d1e7295983

Comment 13 Lital Alon 2020-09-17 08:35:17 UTC
7h passed (from known --> Disconnected)

9/17/2020, 7:28:09 AM	warning Host master-0-0: updated status from "known" to "disconnected" (Host has stopped communicating with the installation service)
9/17/2020, 3:22:53 AM	Deleted image from backend because it expired. It may be generated again at any time.
9/16/2020, 11:55:53 PM	Updated status of cluster ocp-edge34-cluster-0 to ready
9/16/2020, 11:55:52 PM	Host master-0-0: updated status from "discovering" to "known" (Host is ready to be installed)

Comment 14 Lital Alon 2020-09-17 08:36:55 UTC
host ID: 9ed62e95-27ba-4981-be77-9bbae8777227
Cluster id: c097015c-9cd5-4de0-a7be-a7d1e7295983

Comment 15 Fred Rolland 2020-09-17 09:05:46 UTC
OCM debug log:

time="2020-09-17T07:15:10Z" level=debug msg="OpenID token URL wasn't provided, will use 'https://sso.redhat.com/auth/realms/redhat-external/protocol/openid-connect/token'" p
kg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Bearer token isn't available" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Refresh token isn't available" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Requesting new token using the client credentials grant" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Request method is POST" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Request URL is 'https://sso.redhat.com/auth/realms/redhat-external/protocol/openid-connect/token'" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Request header 'Accept' is 'application/json'" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Request header 'Content-Type' is 'application/x-www-form-urlencoded'" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Request header 'User-Agent' is 'OCM/0.1.118'" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="Request body follows" pkg=ocm
time="2020-09-17T07:15:10Z" level=debug msg="client_id=assisted-installer-prod&client_secret=***&grant_type=client_credentials&scope=openid" pkg=ocm
{"file":"/go/src/github.com/openshift/origin/pkg/auth/auth_handler.go:86","func":"github.com/openshift/assisted-service/pkg/auth.(*AuthHandler).AuthAgentAuth","level":"error","msg":"Error Authenticating PullSecret token: can't get access token: can't send request: Post \"https://sso.redhat.com/auth/realms/redhat-external/protocol/openid-connect/token\": remote error: tls: internal error","pkg":"auth","time":"2020-09-17T07:15:12Z"}

Comment 16 Michael Filanov 2020-09-17 11:29:11 UTC
Handled in https://issues.redhat.com/browse/MGMT-2181 
Added more logs and improve the implementation.

Comment 18 Michael Filanov 2020-09-21 16:20:38 UTC
Thanks Fred, we will wait for another release in order to test it.

Comment 19 Lital Alon 2020-09-23 10:33:04 UTC
Verified on Staging v1.0.9.5

Comment 22 errata-xmlrpc 2021-08-25 13:49:22 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 (OpenShift Container Platform 4.6.43 bug fix 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/RHBA-2021:3197