[DEV] Improve authentication and middleware logging

[davidallendj]

Short Description The logging related to authentication and middleware does not return sufficient information to debug common issues such as SMD_JWKS_URL not being a reachable host to fetch the JWKS. This may require adding some logic to extend the jwtauth.Verifier and/or the jwtauth.Authenticator middleware.

Definition of Done This may be tricky to test, but we need some way to be able to verify that the log messages can be used to reasonably detect where issues are occurring.

[cjh1]

@davidallendj I am going to take a look at this as an introduction to smd, if that is OK?

[davidallendj]

Yes, absolutely! I'll go ahead and assign this one to you. If you need help understanding anything, just let me know.

[cjh1]

OK, so I have done a little digging into failures related to SMD_JWKS_URL being misconfigured. So if the host is not reachable I see the following in the logs at startup:

2024/06/21 18:54:28.639223 main.go:956: Fetching public key from server...
2024/06/21 18:54:58.813186 main.go:960: failed to initialize auth token: failed to fetch "http://opdfgaal:3333/keyss": Get "http://opdfgaal:3333/keyss": dial tcp 202.226.39.132:3333: i/o timeout
2024/06/21 18:55:33.844240 main.go:960: failed to initialize auth token: failed to fetch "http://opdfgaal:3333/keyss": Get "http://opdfgaal:3333/keyss": dial tcp 202.226.39.132:3333: i/o timeout
2024/06/21 18:56:08.860403 main.go:960: failed to initialize auth token: failed to fetch "http://opdfgaal:3333/keyss": Get "http://opdfgaal:3333/k

If the host is available but the URL is incorrect, I see the following:

024/06/21 18:34:51.473078 main.go:957: Fetching public key from server...
2024/06/21 18:34:52.071171 main.go:961: failed to initialize auth token: failed to unmarshal JWK set: error reading token: EOF
2024/06/21 18:34:57.207269 main.go:961: failed to initialize auth token: failed to unmarshal JWK set: error reading token: EOF
2024/06/21 18:35:02.490669 main.go:961: failed to initialize auth token: failed to unmarshal JWK set: error reading token: EOF

So the second one is not great, but points you in the general direction. However, I suspect that this issue is related requests failing after startup?

[davidallendj]

Yes, that's right. If I recall correctly, the HTTP response body is being passed to json.Unmarshal, but it's empty returning a NOT FOUND response code I think. Maybe it would be better to check the error code first, since the message itself would not indicate the root of the issue.

[cjh1]

Absolutely, I can add some error check, just wanted to check I was tackling the right ( or one of the right ) issue(s).

[cjh1]

@davidallendj I have pushed #24, let me know what you think.

[davidallendj]

LGTM.

[davidallendj]

I'm reopening this issue as I found another related not-so-good error message when setting the SMD_JWKS_URL endpoint that looks like JSON, but isn't the JWKS. I tried setting the environment variable to http://opaal:3333/token instead of http://opaal:3333/keys and get this:

main.go:954: failed to initialize auth token: failed to unmarshal JWK set: error reading token: EOF

I think the error message is good enough to point to being a JWK/JWKS related issue, but it doesn't seem obvious that it's related to the URL being set to an endpoint that returns a JSON response, but is not a JWKS as expected.

[cjh1]

@davidallendj I can take a look at this one as well.

[cjh1]

When I set SMD_JWKS_URL to http://opaal:3333/token I get the following:

2024/06/25 18:57:34.563365 main.go:960: failed to initialize auth token: failed to unmarshal JWK set: failed to parse sole key in key set

Which seems pretty reasonable? I think in your case the request is actually failing? Are you running with the changes from my PR?

[davidallendj]

Yes, but it looks like I was mistaken. My SMD_JWKS_URL is set to the correct endpoint, but my opaal container isn't able to fetch the keys from Hydra (at least that's what I think is happening). This is what I'm getting for my opaal logs:

docker logs opaal
Login with an identity provider:
    gitlab: /login?sso=7c0fab1153674a258a705976fcb9468350df3addd91de4ec622fc9ed24bfbcdd
failed to fetch keys using JWKS url...trying to fetch config and try again...
failed to fetch keys using JWKS url...trying to fetch config and try again...
failed to fetch keys using JWKS url...trying to fetch config and try again...
failed to fetch keys using JWKS url...trying to fetch config and try again...
failed to fetch keys using JWKS url...trying to fetch config and try again...
failed to fetch keys using JWKS url...trying to fetch config and try again...
failed to fetch keys using JWKS url...trying to fetch config and try again...

When I curl the opaal endpoint for the keys, I get this:

curl http://127.0.0.1:3333/keys
null%

I think this would explain why I'm getting the EOF error, but seeing what opaal is outputting is making me think the error from opaal needs to be improved as well.

[cjh1]

So the status code for curl http://127.0.0.1:3333/keys is 200? If so maybe opaal should be changed so it raises an appropriate status code if gets a request for keys and can't get the keys from Hydra, rather than returning an empty response?

[davidallendj]

Yes, the status code is 200 and yeah I think that would be the way to go. I'm still thinking there should be some type of indication that EOF errors are from empty responses and not something specific to SMD. That way, we should have a better idea where to look whenever they occur.

[cjh1]

I have pushed #25 that adds a more descriptive message in the case of EOF:

2024/06/25 20:07:07.317456 main.go:960: failed to initialize auth token: received empty response for key: failed to unmarshal JWK set: error reading token: EOF

[davidallendj]

I think that should be good enough for now. Thanks for helping out with this issue!