Tenant namespaces provisioned with delay

[alexeykazakov]

I'm not sure what's going on but I registered couple of new users but after login I didn't see any namespaces in OSO. In the logs I saw messages from tenant service saying that it can't retrieve OSO user tokens. For example:

{"err":"could not resolve user token. Caused by: error while resolving the token for https://api.starter-us-east-1b.openshift.com/: Unauthorized error: 401 unauthorized_error, token is missing\n","error_message":"could not resolve user token. Caused by: error while resolving the token for https://api.starter-us-east-1b.openshift.com/: Unauthorized error: 401 unauthorized_error, token is missing\n","file":"/tmp/go/src/github.com/fabric8-services/fabric8-tenant/jsonapi/jsonapi_utility.go","func":"github.com/fabric8-services/fabric8-tenant/jsonapi.ErrorToJSONAPIError","identity_id":"e2f59d84-eb97-4338-a453-bbdbfe7b39ce","level":"error","line":40,"msg":"an error occurred in our api","pid":1,"pkg":"github.com/fabric8-services/fabric8-tenant/jsonapi","req_headers":{"Accept-Encoding":["gzip"],"Authorization":"*****","Content-Length":["0"],"User-Agent":["Go-http-client/1.1"],"X-Request-Id":["7ab7d399-3184-411e-98bb-73d530b8159b"]},"req_id":"7ab7d399-3184-411e-98bb-73d530b8159b","time":"2018-11-30 00:39:09"}

But in Auth logs for that request I see status 200:

{"action":"show","bytes":848,"ctrl":"UserController","duration":11.28802,"duration_unit":"ms","identity_id":"e2f59d84-eb97-4338-a453-bbdbfe7b39ce","level":"info","msg":"completed","pkg":"log.LogRequest.func1","req_id":"7ab7d399-3184-411e-98bb-73d530b8159b","status":200,"time":"2018-11-30 00:39:09"}

And UI can retrieve the token without problem too.

While I was looking at logs the namespaces magically appeared in the OSO cluster.

[MatousJobanek]

These two logs don't relate to each other I'm afraid. That one retrieved from tenant service is a failure while retrieving user token: https://github.com/fabric8-services/fabric8-tenant/blob/master/auth/service.go#L204-L215 which calls Retrieve endpoint in TokenController. The log from auth service you mentioned is for show endpoint in UserController.

Anyway, such a 401 errors are (in this case) caused by not-linked accounts: https://github.com/fabric8-services/fabric8-auth/blob/master/controller/token.go#L289 see the description https://github.com/fabric8-services/fabric8-auth/blob/master/design/token.go#L62 Unfortunately, the tenant service didn't log the error message that is added as a header to the response by auth service - this should change it, so we could get more information: https://github.com/fabric8-services/fabric8-tenant/pull/689

[MatousJobanek]

I wasn't successful in reproducing it in prod-preview. Here is PR to promote the change to prod https://github.com/openshiftio/saas-openshiftio/pull/1152 and as soon as the issue accurs again, we will be able to figure out which account wasn't more likely linked or if there was any other issue

[alexeykazakov]

The log from auth service you mentioned is for show endpoint in UserController.

Oh, right. Sorry, my bad.

[MatousJobanek]

Unfortunately, after this PR being merged, the additional error response message is still not printed - still getting the short version:

{"cluster_url":"https://api.starter-us-east-1b.openshift.com/","err":"error while resolving the token for https://api.starter-us-east-1b.openshift.com/: Unauthorized error: 401 unauthorized_error, token is missing\n","file":"/tmp/go/src/github.com/fabric8-services/fabric8-tenant/auth/service.go","func":"github.com/fabric8-services/fabric8-tenant/auth.(*authService).GetUser","identity_id":"44233454-bc2c-420a-bb74-601b86d77474","level":"error","line":94,"msg":"unable to fetch tenant token from auth","pid":1,"pkg":"github.com/fabric8-services/fabric8-tenant/auth","req_headers":{"Accept-Encoding":["gzip"],"Authorization":"*****","Content-Length":["0"],"User-Agent":["Go-http-client/1.1"],"X-Request-Id":["24756ce7-0900-4f04-afa5-5605c3518d9f"]},"req_id":"24756ce7-0900-4f04-afa5-5605c3518d9f","time":"2018-12-03 10:58:51"}

So it is either not correctly added to the header on the auth side or not correctly read on tenant side. I will try to change the logging to print all information about the response when the error occurs. I hope that this will help.

[alexeykazakov]

This is not 100% reproducible. Reducing to sev-2

[MatousJobanek]

I found a related error log in the auth service console (related to different identity_id, but same issue):

{"GET":"/api/token?for=https%3A%2F%2Fgithub.com","action":"Retrieve","ctrl":"token","from":"83.31.194.114","identity_id":"ae37460a-bfba-40a1-99d3-4de8b9ee88e0","level":"info","msg":"request started","pkg":"log.LogRequest.func1","req_id":"3c7b110d-c74e-4cd8-b731-3f896ebf1d51","time":"2018-12-03 15:44:20"}
{"err":"token is missing","file":"/tmp/go/src/github.com/fabric8-services/fabric8-auth/controller/token.go","func":"github.com/fabric8-services/fabric8-auth/controller.(*TokenController).Retrieve","identity_id":"ae37460a-bfba-40a1-99d3-4de8b9ee88e0","level":"error","line":209,"msg":"failed to retrieve token","pid":1,"pkg":"controller","req_headers":{"Accept":["application/json, text/plain, */*"],"Accept-Encoding":["gzip, deflate, br"],"Accept-Language":["pl-PL,pl;q=0.9,en-US;q=0.8,en;q=0.7"],"Authorization":"*****","Content-Type":["application/json"],"Forwarded":["for=83.31.194.114;host=auth.openshift.io;proto=https;proto-version="],"Origin":["https://openshift.io"],"Referer":["https://openshift.io/friendkuc0/Przestrzen"],"User-Agent":["Mozilla/5.0  (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"],"X-Forwarded-For":["83.31.194.114"],"X-Forwarded-Host":["auth.openshift.io"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Request-Id":["3c7b110d-c74e-4cd8-b731-3f896ebf1d51"]},"req_id":"3c7b110d-c74e-4cd8-b731-3f896ebf1d51","req_params":{"for":["https://github.com"]},"time":"2018-12-03  15:44:20"}
{"err":"token is missing","error_message":"token is missing","identity_id":"ae37460a-bfba-40a1-99d3-4de8b9ee88e0","level":"info","msg":"an error occurred in our api","pkg":"jsonapi","req_id":"3c7b110d-c74e-4cd8-b731-3f896ebf1d51","time":"2018-12-03 15:44:20"}
{"action":"Retrieve","bytes":115,"ctrl":"token","duration":5.5390939999999995,"duration_unit":"ms","identity_id":"ae37460a-bfba-40a1-99d3-4de8b9ee88e0","level":"info","msg":"completed","pkg":"log.LogRequest.func1","req_id":"3c7b110d-c74e-4cd8-b731-3f896ebf1d51","status":401,"time":"2018-12-03 15:44:20"}

It seem that there is bad timing in linking with GH token and requesting for tenant namespaces creation

[MatousJobanek]

I found a related error log in the auth service console (related to different identity_id, but same issue):

After clarification from today - this log that I referenced is not related - it contains a different for parameter. Sorry for confusions (looking forward to having Kibana working for me)