broken ldap cached session after "failed to execute flow"

[calbrecht]

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):

• authentik version: 2024.4.2
• Deployment: https://github.com/nix-community/authentik-nix

Additional context
"failed to execute flow"

authentik/internal/outpost/ldap/bind/direct/bind.go

Line 47 in 60c8837

req.Log().WithError(err).Warning("failed to execute flow")

Supposedly caching the broken session

authentik/internal/outpost/ldap/bind/memory/memory.go

Line 62 in 60c8837

sb.sessions.Set(Credentials{

[calbrecht]

@d-schiffner @BeryJu could it be that this comparison

authentik/internal/outpost/ldap/bind/memory/memory.go

Line 58 in 60c8837

if flags == nil {

needs the same refactoring as that comparison

authentik/internal/outpost/ldap/search/memory/memory.go

Line 78 in 7cedc84

if flag == nil || (flag.UserInfo == nil && flag.UserPk == flags.InvalidUserPK) {

which was added in #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]

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]

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

[calbrecht]

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]

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]

And finally that one mayflower@7e11c4f fixed it together with the previous commits.

[authentik-automation]

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.