search

goauthentik / authentik

The authentication glue you need.
https://goauthentik.io
Other
12.53k stars 843 forks source link

broken ldap cached session after "failed to execute flow" #9972

Open calbrecht opened 3 months ago

calbrecht commented 3 months ago

A note upfront, the instance is deployed using the https://github.com/nix-community/authentik-nix module. If you think the issue is related to the installation method in use feel free to close it, although it seems to me the cause is an oversight in refactoring. But then again, what do i know,

Describe the bug Suddenly authentication via ldap provider fails on client with Invalid credentials. The failure is reproducible. In authentik ldap logs at the time of the first client authentication failure, is this error "failed to submit challenge 502 Bad Gateway" and event "failed to execute flow", followed by timespaced recurring events "authenticated from session". Changing the bind method of the ldap provider to direct bind, authenticating, and changing back to cached bind fixes the failure.

To Reproduce Don't know how to reproduce the bind failure "failed to execute flow". See logs.

Expected behavior The ldap cached bind should not cache broken sessions, i guess.

Logs

Jun 03 15:40:47 authentik ldap[479322]: {"bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","client":"same::ipv:6","error":"failed to submit challenge 502 Bad Gateway","event":"failed to execute flow","level":"warning","requestId":"same-redacted-req-id","timestamp":"2024-06-03T15:40:47Z"}
Jun 03 15:40:47 authentik ldap[479322]: {"bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","client":"same::ipv:6","event":"Bind request","level":"info","requestId":"same-redacted-req-id","timestamp":"2024-06-03T15:40:47Z","took-ms":164}

From now on, the client fails to authenticate, despite time-spaced recurring lines like

Jun 03 15:40:49 authentik ldap[479322]: {"bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","event":"authenticated from session","level":"info","logger":"authentik.outpost.ldap.binder.session","timestamp":"2024-06-03T15:40:49Z"}
Jun 03 15:40:49 authentik ldap[479322]: {"bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","client":"same::ipv:6","event":"Bind request","level":"info","requestId":"different-redacted-req-id","timestamp":"2024-06-03T15:40:49Z","took-ms":0}

Version and Deployment (please complete the following information):

Additional context "failed to execute flow" https://github.com/goauthentik/authentik/blob/60c88370822d28637d61170dd4edc148e0ade681/internal/outpost/ldap/bind/direct/bind.go#L47

Supposedly caching the broken session https://github.com/goauthentik/authentik/blob/60c88370822d28637d61170dd4edc148e0ade681/internal/outpost/ldap/bind/memory/memory.go#L62

calbrecht commented 3 months ago

@d-schiffner @BeryJu could it be that this comparison https://github.com/goauthentik/authentik/blob/60c88370822d28637d61170dd4edc148e0ade681/internal/outpost/ldap/bind/memory/memory.go#L58 needs the same refactoring as that comparison https://github.com/goauthentik/authentik/blob/7cedc840b07ae7d974f9dc7abe93e41dca6c46ea/internal/outpost/ldap/search/memory/memory.go#L78 which was added in https://github.com/goauthentik/authentik/pull/6096

Although i do not speak go, i can see that there is a change of behavior which i can imagine to cause the caching of an assumably (by interpreting the behavior without understanding) broken session. Are you able to see the point?

calbrecht commented 2 months ago

While this was happening for a dovecot service user and therefore affecting all users wanting to authenticate their Mailclient, it now happened for a specific human user again.

On the mailer server:

Jun 07 11:34:46 mailer dovecot[3423100]: imap-login: Disconnected: Connection closed (auth failed, 3 attempts in 15 secs): user=<redacted>, method=PLAIN, rip=redacted, lip=redacted, TLS, session=<redacted>

On authentik server:

Jun 07 11:34:31 authentik ldap[479322]: {"attributes":["mail"],"baseDN":"ou=users,dc=goauthentik,dc=io","bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","client":"redacted","event":"Search request","filter":"(&(objectClass=inetOrgPerson)(!(goauthentikio-user-service-account=true))(!(cn=redacted))(mail=redacted))","level":"info","requestId":"c6b5810c-bc60-4350-ace8-37db980102fb","scope":"Whole Subtree","timestamp":"2024-06-07T11:34:31Z","took-ms":3}
Jun 07 11:34:31 authentik server[1810923]: {"auth_via": "unauthenticated", "domain_url": "redacted", "event": "/api/v3/flows/executor/no-mfa-authentication-flow/?query=goauthentik.io%252Foutpost%252Fldap%3Dtrue", "host": "redacted", "level": "info", "logger": "authentik.asgi", "method": "GET", "pid": 1810923, "remote": "redacted", "request_id": "c0ff07646d3b493b839658311946f513", "runtime": 133, "schema_name": "public", "scheme": "https", "status": 200, "timestamp": "2024-06-07T11:34:31.987917", "user": "", "user_agent": "goauthentik.io/outpost/2024.4.2"}
Jun 07 11:34:31 authentik server[1810923]: {"event": "Error while closing socket [Errno 9] Bad file descriptor", "level": "info", "logger": "gunicorn.error", "timestamp": 1717760071.9952555}
Jun 07 11:34:31 authentik server[479321]: {"error":"read unix @->/tmp/authentik-core.sock: read: connection reset by peer","event":"failed to proxy to backend","level":"warning","logger":"authentik.router","timestamp":"2024-06-07T11:34:31Z"}
Jun 07 11:34:31 authentik server[479321]: {"error":"websocket: close 1012","event":"ws read error","level":"warning","logger":"authentik.outpost.ak-api-controller","loop":"ws-handler","timestamp":"2024-06-07T11:34:31Z"}
Jun 07 11:34:31 authentik ldap[479322]: {"error":"websocket: close 1012","event":"ws read error","level":"warning","logger":"authentik.outpost.ak-api-controller","loop":"ws-handler","timestamp":"2024-06-07T11:34:31Z"}
Jun 07 11:34:32 authentik ldap[479322]: {"bindDN":"cn=redacted,ou=users,dc=goauthentik,dc=io","client":"redacted","error":"failed to submit challenge 502 Bad Gateway","event":"failed to execute flow","level":"warning","requestId":"eaa4bc9b-24cf-4726-816d-a6a1eae2558a","timestamp":"2024-06-07T11:34:31Z"}
Jun 07 11:34:32 authentik ldap[479322]: {"bindDN":"cn=redacted,ou=users,dc=goauthentik,dc=io","client":"redacted","event":"Bind request","level":"info","requestId":"eaa4bc9b-24cf-4726-816d-a6a1eae2558a","timestamp":"2024-06-07T11:34:31Z","took-ms":178}

Followed by authenticated from session

Jun 07 11:34:38 authentik ldap[479322]: {"attributes":["mail"],"baseDN":"ou=users,dc=goauthentik,dc=io","bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","client":"redacted","event":"Search request","filter":"(&(objectClass=inetOrgPerson)(!(goauthentikio-user-service-account=true))(!(cn=redacted))(mail=redacted))","level":"info","requestId":"b179953b-a46c-40c6-af84-efeaf84986e0","scope":"Whole Subtree","timestamp":"2024-06-07T11:34:38Z","took-ms":3}
Jun 07 11:34:38 authentik ldap[479322]: {"bindDN":"cn=redacted,ou=users,dc=goauthentik,dc=io","event":"authenticated from session","level":"info","logger":"authentik.outpost.ldap.binder.session","timestamp":"2024-06-07T11:34:38Z"}
Jun 07 11:34:38 authentik ldap[479322]: {"bindDN":"cn=redacted,ou=users,dc=goauthentik,dc=io","client":"redacted","event":"Bind request","level":"info","requestId":"b5528cb6-91ab-4b67-aa7f-d79f47f0fa34","timestamp":"2024-06-07T11:34:38Z","took-ms":0}
Jun 07 11:34:44 authentik ldap[479322]: {"attributes":["mail"],"baseDN":"ou=users,dc=goauthentik,dc=io","bindDN":"cn=service,ou=users,dc=goauthentik,dc=io","client":"redacted","event":"Search request","filter":"(&(objectClass=inetOrgPerson)(!(goauthentikio-user-service-account=true))(!(cn=redacted))(mail=redacted))","level":"info","requestId":"46eeae49-265e-401b-a1b1-75b48634bde3","scope":"Whole Subtree","timestamp":"2024-06-07T11:34:44Z","took-ms":3}
Jun 07 11:34:44 authentik ldap[479322]: {"bindDN":"cn=redacted,ou=users,dc=goauthentik,dc=io","event":"authenticated from session","level":"info","logger":"authentik.outpost.ldap.binder.session","timestamp":"2024-06-07T11:34:44Z"}
Jun 07 11:34:44 authentik ldap[479322]: {"bindDN":"cn=redacted,ou=users,dc=goauthentik,dc=io","client":"redacted","event":"Bind request","level":"info","requestId":"06bddd3f-46b3-406c-8ffd-ed9b33d431d8","timestamp":"2024-06-07T11:34:44Z","took-ms":0}
calbrecht commented 2 months ago

No, that does not fix the cached authentication failure after the flow execution failure.

calbrecht commented 2 months ago

Naa, happened again. This was stupid anyway, because if the "failed to execute flow" event is triggered, the direct binder returns LDAPResultInvalidCredentials instead of the LDAPResultOperationsError, which i somehow assumed to be returned.

authentik-automation[bot] commented 2 weeks ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

calbrecht commented 2 weeks ago

And finally that one https://github.com/mayflower/authentik/commit/7e11c4f38223cca155054e29a57735f1846ff0f0 fixed it together with the previous commits.