fix: log credentials verifier error details #713

grantzvolsky · 2021-05-03T00:50:50Z

Proposed changes

Log error details reported by CredentialsVerifier instead of discarding them.

Checklist

I have read the contributing guidelines.
I have read the security policy.
I confirm that this pull request does not address a security
vulnerability. If this pull request addresses a security. vulnerability, I
confirm that I got green light (please contact
security@ory.sh) from the maintainers to push
the changes.
I have added tests that prove my fix is effective or that my feature
works.
I have added or changed the documentation.

Further comments

Below is an example output with this change applied. Please review the format of the 'missing kid header' error.

INFO[2021-05-03T00:35:08Z]/root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:139 github.com/ory/x/reqlog.(*Middleware).ServeHTTP() completed handling request                    http_request=map[headers:map[accept:*/* x-forwarded-for:192.168.0.24,10.1.131.132 x-forwarded-proto:https] host:api.websecute.local method:GET path:/api/anon/telemetry/8df166db-06f1-4cea-a1b2-6ad2cedece3d/view-count query:<nil> remote:127.0.0.1:35970 scheme:http] http_response=map[status:200 text_status:OK took:164.476µs]
INFO[2021-05-03T00:38:51Z]/root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:131 github.com/ory/x/reqlog.(*Middleware).ServeHTTP() started handling request                      http_request=map[headers:map[accept:*/* authorization:Bearer [censored] x-forwarded-for:192.168.0.24,10.1.131.132 x-forwarded-proto:https] host:api.websecute.local method:POST path:/decisions/api/user/articles query:<nil> remote:127.0.0.1:39636 scheme:http]
INFO[2021-05-03T00:38:51Z]/oathkeeper/gz/oathkeeper/proxy/request_handler.go:227 github.com/ory/oathkeeper/proxy.(*RequestHandler).HandleRequest() Access credentials are invalid                audience=application service_name=ORY Oathkeeper service_version=master
INFO[2021-05-03T00:38:51Z]/oathkeeper/gz/oathkeeper/api/decision.go:114 github.com/ory/oathkeeper/api.(*DecisionHandler).decisions() Access request denied                         audience=application error=map[debug: details:map[jwt_claims:{"amr":["pwd"],"aud":["api1"],"auth_time":1592982259,"client_id":"js","exp":"1620005931","idp":"local","iss":"https://websecute.local","nbf":1493002040,"scope":["openid","profile","api1"],"sub":"727f3ab0-a85e-4620-9a39-c3e0dad3acb4"}] message:Access credentials are invalid reason:[rid=
error=An internal server error occurred, please contact the system administrator
reason=The JSON Web Token must contain a kid header value but did not.
details=map[]
debug=

github.com/ory/oathkeeper/credentials.(*VerifierDefault).Verify.func1
        /oathkeeper/gz/oathkeeper/credentials/verifier_default.go:45
github.com/form3tech-oss/jwt-go.(*Parser).ParseWithClaims
        /root/go/pkg/mod/github.com/form3tech-oss/jwt-go@v3.2.2+incompatible/parser.go:51
github.com/form3tech-oss/jwt-go.ParseWithClaims
        /root/go/pkg/mod/github.com/form3tech-oss/jwt-go@v3.2.2+incompatible/token.go:93
github.com/ory/oathkeeper/credentials.(*VerifierDefault).Verify
        /oathkeeper/gz/oathkeeper/credentials/verifier_default.go:38
github.com/ory/oathkeeper/pipeline/authn.(*AuthenticatorJWT).Authenticate
        /oathkeeper/gz/oathkeeper/pipeline/authn/authenticator_jwt.go:90
github.com/ory/oathkeeper/proxy.(*RequestHandler).HandleRequest
        /oathkeeper/gz/oathkeeper/proxy/request_handler.go:216
github.com/ory/oathkeeper/api.(*DecisionHandler).decisions
        /oathkeeper/gz/oathkeeper/api/decision.go:109
github.com/ory/oathkeeper/api.(*DecisionHandler).ServeHTTP
        /oathkeeper/gz/oathkeeper/api/decision.go:63
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/x/reqlog.(*Middleware).ServeHTTP
        /root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:134
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/oathkeeper/metrics.(*Middleware).ServeHTTP
        /oathkeeper/gz/oathkeeper/metrics/middleware.go:88
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/x/metricsx.(*Service).ServeHTTP
        /root/go/pkg/mod/github.com/ory/x@v0.0.163/metricsx/middleware.go:261
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/urfave/negroni.(*Negroni).ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96
net/http.serverHandler.ServeHTTP
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/net/http/server.go:2843
net/http.(*conn).serve
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/net/http/server.go:1925
runtime.goexit
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/runtime/asm_amd64.s:1374] status:Unauthorized status_code:401 trace:
github.com/ory/herodot.(*DefaultError).WithTrace
        /root/go/pkg/mod/github.com/ory/herodot@v0.8.4/error_default.go:52
github.com/ory/oathkeeper/pipeline/authn.(*AuthenticatorJWT).Authenticate
        /oathkeeper/gz/oathkeeper/pipeline/authn/authenticator_jwt.go:101
github.com/ory/oathkeeper/proxy.(*RequestHandler).HandleRequest
        /oathkeeper/gz/oathkeeper/proxy/request_handler.go:216
github.com/ory/oathkeeper/api.(*DecisionHandler).decisions
        /oathkeeper/gz/oathkeeper/api/decision.go:109
github.com/ory/oathkeeper/api.(*DecisionHandler).ServeHTTP
        /oathkeeper/gz/oathkeeper/api/decision.go:63
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/x/reqlog.(*Middleware).ServeHTTP
        /root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:134
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/oathkeeper/metrics.(*Middleware).ServeHTTP
        /oathkeeper/gz/oathkeeper/metrics/middleware.go:88
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/x/metricsx.(*Service).ServeHTTP
        /root/go/pkg/mod/github.com/ory/x@v0.0.163/metricsx/middleware.go:261
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/urfave/negroni.(*Negroni).ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96
net/http.serverHandler.ServeHTTP
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/net/http/server.go:2843
net/http.(*conn).serve
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/net/http/server.go:1925
runtime.goexit
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/runtime/asm_amd64.s:1374] granted=false http_host=api.websecute.local http_method=POST http_url=https://api.websecute.local/api/user/articles http_user_agent= service_name=ORY Oathkeeper service_version=master
ERRO[2021-05-03T00:38:51Z]/root/go/pkg/mod/github.com/ory/herodot@v0.8.4/error_reporter.go:30 github.com/ory/herodot.DefaultErrorReporter.func1() An error occurred while handling a request    code=401 debug= details=map[jwt_claims:{"amr":["pwd"],"aud":["api1"],"auth_time":1592982259,"client_id":"js","exp":"1620005931","idp":"local","iss":"https://websecute.local","nbf":1493002040,"scope":["openid","profile","api1"],"sub":"727f3ab0-a85e-4620-9a39-c3e0dad3acb4"}] error=Access credentials are invalid reason=[rid=
error=An internal server error occurred, please contact the system administrator
reason=The JSON Web Token must contain a kid header value but did not.
details=map[]
debug=

github.com/ory/oathkeeper/credentials.(*VerifierDefault).Verify.func1
        /oathkeeper/gz/oathkeeper/credentials/verifier_default.go:45
github.com/form3tech-oss/jwt-go.(*Parser).ParseWithClaims
        /root/go/pkg/mod/github.com/form3tech-oss/jwt-go@v3.2.2+incompatible/parser.go:51
github.com/form3tech-oss/jwt-go.ParseWithClaims
        /root/go/pkg/mod/github.com/form3tech-oss/jwt-go@v3.2.2+incompatible/token.go:93
github.com/ory/oathkeeper/credentials.(*VerifierDefault).Verify
        /oathkeeper/gz/oathkeeper/credentials/verifier_default.go:38
github.com/ory/oathkeeper/pipeline/authn.(*AuthenticatorJWT).Authenticate
        /oathkeeper/gz/oathkeeper/pipeline/authn/authenticator_jwt.go:90
github.com/ory/oathkeeper/proxy.(*RequestHandler).HandleRequest
        /oathkeeper/gz/oathkeeper/proxy/request_handler.go:216
github.com/ory/oathkeeper/api.(*DecisionHandler).decisions
        /oathkeeper/gz/oathkeeper/api/decision.go:109
github.com/ory/oathkeeper/api.(*DecisionHandler).ServeHTTP
        /oathkeeper/gz/oathkeeper/api/decision.go:63
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/x/reqlog.(*Middleware).ServeHTTP
        /root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:134
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/oathkeeper/metrics.(*Middleware).ServeHTTP
        /oathkeeper/gz/oathkeeper/metrics/middleware.go:88
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/ory/x/metricsx.(*Service).ServeHTTP
        /root/go/pkg/mod/github.com/ory/x@v0.0.163/metricsx/middleware.go:261
github.com/urfave/negroni.middleware.ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
github.com/urfave/negroni.(*Negroni).ServeHTTP
        /root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96
net/http.serverHandler.ServeHTTP
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/net/http/server.go:2843
net/http.(*conn).serve
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/net/http/server.go:1925
runtime.goexit
        /nix/store/28w6zm2qkxhlbhv1s1ixn434vsnx5qps-go-1.15.5/share/go/src/runtime/asm_amd64.s:1374] request-id= status=401 writer=JSON
INFO[2021-05-03T00:38:51Z]/root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:139 github.com/ory/x/reqlog.(*Middleware).ServeHTTP() completed handling request                    http_request=map[headers:map[accept:*/* authorization:Bearer [censored] x-forwarded-for:192.168.0.24,10.1.131.132 x-forwarded-proto:https] host:api.websecute.local method:POST path:/api/user/articles query:<nil> remote:127.0.0.1:39636 scheme:http] http_response=map[status:401 text_status:Unauthorized took:742.407µs]
INFO[2021-05-03T00:39:06Z]/root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:131 github.com/ory/x/reqlog.(*Middleware).ServeHTTP() started handling request                      http_request=map[headers:map[accept:*/* authorization:Bearer [censored] x-forwarded-for:192.168.0.24,10.1.131.132 x-forwarded-proto:https] host:api.websecute.local method:POST path:/decisions/api/user/articles query:<nil> remote:127.0.0.1:39864 scheme:http]
INFO[2021-05-03T00:39:06Z]/oathkeeper/gz/oathkeeper/api/decision.go:123 github.com/ory/oathkeeper/api.(*DecisionHandler).decisions() Access request granted                        audience=application granted=true http_host=api.websecute.local http_method=POST http_url=https://api.websecute.local/api/user/articles http_user_agent= service_name=ORY Oathkeeper service_version=master
INFO[2021-05-03T00:39:06Z]/root/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:139 github.com/ory/x/reqlog.(*Middleware).ServeHTTP() completed handling request                    http_request=map[headers:map[accept:*/* authorization:Bearer [censored] x-forwarded-for:192.168.0.24,10.1.131.132 x-forwarded-proto:https] host:api.websecute.local method:POST path:/api/user/articles query:<nil> remote:127.0.0.1:39864 scheme:http] http_response=map[status:200 text_status:OK took:2.110661ms]

pipeline/authn/authenticator_jwt.go

eroznik · 2021-06-30T14:09:25Z

This change introduced a possible side effect, now the decisions API also returns the stack trace as the response, thus end users get the full Oathkeeper stack trace - disclosing which tooling is used to secure requests. Was this expected as a feature or should it be changed?
The log information is very useful, not sure about the API response.
{ "error": { "code": 401, "details": { "jwt_claims": "removed" }, "message": "Access credentials are invalid", "reason": "rid=\nerror=An internal server error occurred, please contact the system administrator\nreason=JSON Web Key ID \"xxxxxx\" with use \"sig\" could not be found in any of the provided URIs.\ndetails=map[jwks_urls:[{ xxxxx false } { xxxxx false } { xxxx false }]]\ndebug=Check that the provided JSON Web Key URIs contain a key that can verify the signature of the provided JSON Web Key ID.\n\ngithub.com/ory/oathkeeper/credentials.(*FetcherDefault).ResolveKey\n\t/home/ory/credentials/fetcher_default.go:145\ngithub.com/ory/oathkeeper/credentials.(*VerifierDefault).Verify.func1\n\t/home/ory/credentials/verifier_default.go:48\ngithub.com/form3tech-oss/jwt-go.(*Parser).ParseWithClaims\n\t/go/pkg/mod/github.com/form3tech-oss/jwt-go@v3.2.2+incompatible/parser.go:51\ngithub.com/form3tech-oss/jwt-go.ParseWithClaims\n\t/go/pkg/mod/github.com/form3tech-oss/jwt-go@v3.2.2+incompatible/token.go:93\ngithub.com/ory/oathkeeper/credentials.(*VerifierDefault).Verify\n\t/home/ory/credentials/verifier_default.go:38\ngithub.com/ory/oathkeeper/pipeline/authn.(*AuthenticatorJWT).Authenticate\n\t/home/ory/pipeline/authn/authenticator_jwt.go:91\ngithub.com/ory/oathkeeper/proxy.(*RequestHandler).HandleRequest\n\t/home/ory/proxy/request_handler.go:216\ngithub.com/ory/oathkeeper/api.(*DecisionHandler).decisions\n\t/home/ory/api/decision.go:109\ngithub.com/ory/oathkeeper/api.(*DecisionHandler).ServeHTTP\n\t/home/ory/api/decision.go:63\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.163/reqlog/middleware.go:134\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/oathkeeper/metrics.(*Middleware).ServeHTTP\n\t/home/ory/metrics/middleware.go:88\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.163/metricsx/middleware.go:261\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371", "status": "Unauthorized" } }

aeneasr · 2021-07-01T09:34:35Z

Yeah, we can change that. PRs welcomed

eroznik · 2021-07-01T18:27:16Z

I just finished reviewing the "possible side effect" into details, seems like the change just brought additional information to the response only if you are using the JSON error handler with the verbose:true configuration.
Till now, even if Oathkeeper was configured with verbose:true there was no sensitive information printed in the user response JSONs(at least not with the JWT authorizer - didn't have the chance to test others yet).
The solution is easy, set the configuration verbose to false.

grantzvolsky · 2021-07-02T11:18:41Z

Oathkeeper can already be identified by other strings that are returned, even with verbose=false.

The fundamental problem here is that with verbose=true, we are returning "black box" strings that could potentially contain sensitive information, so maybe it would be preferable to deprecate the option? Does anyone depend on it?

Alternatively, a more considerate solution:

Instead of serializing the verifier error into the ReasonField, serialize it into the DebugField.
Delete the DebugField before ErrorJSON.Handle writes it to the response.
DebugField is used in 9 other errors whose JSON responses would be affected as well.

fix: log credentials verifier error details

13898a7

aeneasr approved these changes May 8, 2021

View reviewed changes

pipeline/authn/authenticator_jwt.go Outdated Show resolved Hide resolved

Update pipeline/authn/authenticator_jwt.go

ea3fbaa

aeneasr merged commit 766b071 into ory:master May 8, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: log credentials verifier error details #713

fix: log credentials verifier error details #713

grantzvolsky commented May 3, 2021

eroznik commented Jun 30, 2021 •

edited

aeneasr commented Jul 1, 2021

eroznik commented Jul 1, 2021

grantzvolsky commented Jul 2, 2021

fix: log credentials verifier error details #713

fix: log credentials verifier error details #713

Conversation

grantzvolsky commented May 3, 2021

Proposed changes

Checklist

Further comments

eroznik commented Jun 30, 2021 • edited

aeneasr commented Jul 1, 2021

eroznik commented Jul 1, 2021

grantzvolsky commented Jul 2, 2021

eroznik commented Jun 30, 2021 •

edited