Login sessions that are invalidated through headless logout (by sid) are incorrectly handled on the next login

sgal commented 1 year ago

Preflight checklist

[X] I could not find a solution in the existing issues, docs, nor discussions.
[X] I agree to follow this project's Code of Conduct.
[X] I have read and am following this repository's Contribution Guidelines.
[X] This issue affects my Ory Network project.
[ ] I have joined the Ory Community Slack.
[ ] I am signed up to the Ory Security Patch Newsletter.

Describe the bug

The login session cookie that belongs to the login session that was invalidated through revokeOAuth2LoginSessions are breaking the next login attempt for the user with remember: false.

It looks like for remember: false login sessions, the login session cookie is still read and in case of the invalid value, 404 error is thrown, discarding the current login attempt.

Reproducing the bug

In the OIDC flow, login with remember: true for both login and consent requests
Log out via revokeOAuth2LoginSessions by either subject or sid
Verify that ory_hydra_session cookie is still present (it is not invalidated in the revokeOAuth2LoginSessions call)
Initiate a new OIDC login and select remember: false in the login request
Observe that Hydra redirects to the client with Not found error

If you manually delete the ory_hydra_session cookie before step 4, the problem disappears.

Relevant log output

This is the error log from Hydra. It looks like it tries to delete the login session (because it is not valid), but fails because it is already deleted. This happens during /oauth2/auth?consent_verifier=... request

{
  "audience": "audit",
  "error": {
    "debug": "",
    "message": "Not Found",
    "reason": "",
    "stack_trace": "\ngithub.com/ory/x/errorsx.WithStack\n\t/root/go/pkg/mod/github.com/ory/x@v0.0.547/errorsx/errors.go:41\ngithub.com/ory/hydra/v2/persistence/sql.(*Persister).DeleteLoginSession\n\t/tmp/hydra/persistence/sql/persister_consent.go:392\ngithub.com/ory/hydra/v2/consent.(*DefaultStrategy).revokeAuthenticationSession\n\t/tmp/hydra/consent/strategy_default.go:292\ngithub.com/ory/hydra/v2/consent.(*DefaultStrategy).verifyAuthentication\n\t/tmp/hydra/consent/strategy_default.go:423\ngithub.com/ory/hydra/v2/consent.(*DefaultStrategy).HandleOAuth2AuthorizationRequest\n\t/tmp/hydra/consent/strategy_default.go:1026\ngithub.com/ory/hydra/v2/oauth2.(*Handler).oAuth2Authorize\n\t/tmp/hydra/oauth2/handler.go:967\ngithub.com/ory/x/httprouterx.NoCacheHandle.func1\n\t/root/go/pkg/mod/github.com/ory/x@v0.0.547/httprouterx/nocache.go:21\ngithub.com/ory/x/httprouterx.NoCacheHandle.func1\n\t/root/go/pkg/mod/github.com/ory/x@v0.0.547/httprouterx/nocache.go:21\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/root/go/pkg/mod/github.com/julienschmidt/httprouter@v1.3.0/router.go:387\ngithub.com/urfave/negroni.Wrap.func1\n\t/root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/ory/hydra/v2/x.RejectInsecureRequests.func1\n\t/tmp/hydra/x/tls_termination.go:65\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/metricsx.(*Service).ServeHTTP\n\t/root/go/pkg/mod/github.com/ory/x@v0.0.547/metricsx/middleware.go:259\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/root/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerResponseSize.func1\n\t/root/go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:284\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerCounter.func1\n\t/root/go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:142\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func1\n\t/root/go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:92\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func2\n\t/root/go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:104\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerRequestSize.func1\n\t/root/go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:234\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/ory/x/prometheusx.Metrics.instrumentHandlerStatusBucket.func1\n\t/root/go/pkg/mod/github.com/ory/x@v0.0.547/prometheusx/metrics.go:111\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/src/net/http/server.go:2109\ngithub.com/ory/x/prometheusx.(*MetricsManager).ServeHTTP\n\t/root/go/pkg/mod/github.com/ory/x@v0.0.547/prometheusx/middleware.go:39",
    "status": "Not Found",
    "status_code": 404
  },
  "http_request": {
    "headers": {
      "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7",
      "accept-encoding": "gzip, deflate, br",
      "accept-language": "en-GB,en-US;q=0.9,en;q=0.8,sv;q=0.7,ru;q=0.6",
      "cache-control": "no-cache",
      "connection": "close",
      "cookie": [
        "amp_bdf73e_127.0.0.1=z-Ji39y-JPSu6nGhjrtL8t...1ficign5g.1ficj97rc.1b.14d.15o; amp_aad5a4_127.0.0.1=zvqWpYtXeELFHoP7kok8LQ...1ficign60.1ficj97rd.s.st.tp; ory_hydra_login_csrf_dev_1664308220=MTY4Mjg3NTI4OHxkOWI0ZWR5NjNHTnZBUG05Ty11SldxMXZ6OVBtRVNjNzBXNXN4QXU0Sktrdi1iUExPaW9TdWVPbFdPNWJWb2Z0eTU0bjd2VVVlaURoOHJybXZwWUMyU3lNMHk5UGoxNV9jVHdOd2YwN1RlTm5pV1o1WTFhc3o2V21MengzUkE9PXwM0lRwo2SSfYZOA5ECjVvkfDazgrdNfjWhom0gRWXINg==; remember_me=false; ory_hydra_session_dev=MTY4Mjg3Njc3M3x5SFo0QjFDRnF3bmxtU0hIanVCeEgxUTNmNlBKUUgxNGNPZHFESGIwUl9pN3cyaVRldTZzTXljNTJ0b3AtenVaQVBTZ01fOHNsZ0UxZ3ZlSGFMdDhBWFBncGZRcnhNajJoOGVUME00eGZIalp1ZUJCYVROd0YxMHRKcThJQjRPZzBnPT18sr9zEX3qT6j60RP5YCFyxsWoBu_Q5zwut8JSDkYlmnE=; ory_hydra_consent_csrf_dev_4122305931=MTY4Mjg3Njc3M3xZZlYwem0zalh3bWtYZ0R6MkV3aDgyRGxZQzA2MG9PZDdRYnNweWdHWVY3OXBONWJtNl9adFZOdGFNN1lFajFDYk43XzRTOFF2SC1ISGp5R3pnQk9GRWs5WnExSkNzbEdvbjdlOE5UbFNBZGhXWEw4S0puVkR3RUhKRGVYRFE9PXyd6Xz_TZYdGmivtrEm7Y-x9w2k-_x-PJvhZ3NrT5t1-A==; ory_hydra_login_csrf_dev_4122305931=MTY4Mjg3NjkzOXxob1ZzcEE0VU1haXplazBDQ1JtdlpYcS04ZVlxdl9OV25IdW9TejRSUFNJMEtSWmR1NzJMbWVGZDUzYTVBeV9feUVEbkxIN0VXZExFZG1nQzcwU1VKUjMyYmJxOGJ2WmNLd3pZS1c0c2dzOEMtSE9fcUZtalNUcGRyeG5wc3c9PXyQbBvT95yPbRJ9sZUy1suvPB1raBJZyXqAzqHlIRNMfQ==; klp_lsid=s%3A429c4a37-e66f-4337-95be-d1437f88d031.Uyk03gP1DmwrbuECFnqH8b8ymQHZYakVCroYgQpDfF0; klp_ls_funnel_id=aec1f953-d22a-4822-8741-85fd93ef14ef"
      ],
      "pragma": "no-cache",
      "referer": "http://127.0.0.1:5005/",
      "sec-ch-ua": "\"Chromium\";v=\"112\", \"Google Chrome\";v=\"112\", \"Not:A-Brand\";v=\"99\"",
      "sec-ch-ua-mobile": "?0",
      "sec-ch-ua-platform": "\"macOS\"",
      "sec-fetch-dest": "document",
      "sec-fetch-mode": "navigate",
      "sec-fetch-site": "same-site",
      "sec-fetch-user": "?1",
      "upgrade-insecure-requests": "1",
      "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36",
      "x-forwarded-for": "172.19.0.1",
      "x-real-ip": "172.19.0.1"
    },
    "host": "127.0.0.1",
    "method": "GET",
    "path": "/oauth2/auth",
    "query": "client_id=a458caaa-be9b-4380-8f16-14b11a987a54&code_challenge=7dd6R1PQDwU7Z1kT4yuY8HmqCcmNpcSukiRAQyu2aR0&code_challenge_method=S256&login_verifier=2fe2cc54ff8b435d97c305cbe7ed39f6&market=CH&mode=login&nonce=6fc44b16e485cdb9e8f0c6644f93c83a3410c81d02efcc47cf6b9e3a7a0b2280&redirect_uri=http%3A%2F%2F127.0.0.1%3A5001%2Fcallback&response_type=code&scope=openid+offline_access+default&state=3812242991d182c5bfa911afd3c146bced7db8b8e8e72867c4ddd4d08253421b&ui_locales=en-CH",
    "remote": "127.0.0.1:42542",
    "scheme": "http"
  },
  "level": "info",
  "msg": "access denied",
  "service_name": "Ory Hydra",
  "service_version": "master",
  "time": "2023-04-30T17:49:11.220046867Z"
}

Relevant configuration

No response

Version

2.1.1

On which operating system are you observing this issue?

Linux

In which environment are you deploying?

Docker

Additional Context

No response

aeneasr commented 1 year ago

It's probably as simple as easy as handling sqlcon.ErrNotFound in https://github.com/ory/hydra/blob/872720b3c0d92341a78791004ded44ac8d4ff7c8/consent/strategy_default.go#L292 and return a nil error for that case:

err :=  s.r.ConsentManager().DeleteLoginSession(r.Context(), sid)
if errors.Is(sqlcon.ErrNoRows) {
  return nil
}
return err

Maybe add one e2e test for it to prevent future regressions?

sgal commented 1 year ago

@aeneasr I'm not sure that will be enough. If we handle the Not found error in that line, it would still fail here https://github.com/ory/hydra/blob/872720b3c0d92341a78791004ded44ac8d4ff7c8/consent/strategy_default.go#L353.

And that entire block is quite wrong, because the cookie session was invalidated and therefore should not be used.

sgal commented 1 year ago

I found the issue it seems. It starts in the correct place here https://github.com/ory/hydra/blob/master/consent/strategy_default.go#L420-L426 Since skip: false and remember: false.

Then it goes into https://github.com/ory/hydra/blob/master/consent/strategy_default.go#L283 where it invalidates the cookie by setting its max-age to -1. The problem here is that the cookie belongs to the old session that was already deleted by a headless logout.

The sid of the already invalidated session is returned back to revokeAuthenticationSession, where we try to delete it via this https://github.com/ory/hydra/blob/master/consent/strategy_default.go#L292. And it fails with Not Found since the session is already deleted.

Not sure how to best handle this, what are your thoughts @aeneasr @hperl?

sgal commented 1 year ago

Head-on approach would be to ignore Not Found errors in https://github.com/ory/hydra/blob/master/consent/strategy_default.go#L292, but that feels like a hack to me.

kmherrmann commented 1 year ago

IMHO this should be OK - the session is deleted, so the Not Found is acceptable. Would you be able to send a PR? Thanks a lot!

ory / hydra