Nauthilus-users

Download

nauthilus-users@lists.nauthilus.org

2 participants
2 discussions

Re: Why do I get "passdb_backend=unknown" for a subset of requests
by Christopher Moules 16 Dec '25

16 Dec '25

Hello Christian, Thank you for your fast answer. Sorry that I missed adding some basic information, I realized after I had sent the message: Originally: OS: Debian 13.2 Version: nauthilus 1.11.3 amd64 (from github package: {sha256}3eba20ed95001c7d321516915079c1861ed41389b672ca1aab5518cbde708527) Now: OS: Debian 13.2 Version: nauthilus 1.11.4 amd64 (from github package: {sha256}7e249215dbf0e82632e6f955dcd7449d735d60c586d5aa13324b32dc584850d0) After installing the updated package and restarting the service, I still see the same behavior. Dec 16 12:52:47 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T12:52:47.538Z level=NOTICE msg="Authentication request has failed" instance=nauthilus session=36vabD3LkHy0cvnV50UWamrPhfH mode=auth backend_name=N/A protocol=imap oidc_cid=N/A local_ip=N/A port=N/A client_ip=1.2.3.4 client_port=N/A client_host=N/A tls_protocol=N/A tls_cipher=N/A auth_method=plain username=user2(a)example.org passdb_backend=unknown current_password_retries=1 account_passwords_seen=0 total_passwords_seen=0 user_agent=N/A client_id=N/A brute_force_bucket=N/A feature=N/A status_message="Invalid login or password" uri_path=/api/v1/auth/nginx authenticated=fail authz=true authn=false latency=2.556ms curl -v -X POST -H "Auth-User: user2(a)example.org" -H "Auth-Method: plain" -H "Auth-Protocol: imap" "http://192.168.0.6:9443/api/v1/auth/nginx?mode=no-auth" * Trying 192.168.0.6:9443... * Connected to 192.168.0.6 (192.168.0.6) port 9443 * using HTTP/1.x > POST /api/v1/auth/nginx?mode=no-auth HTTP/1.1 > Host: 192.168.0.6:9443 > User-Agent: curl/8.14.1 > Accept: */* > Auth-User: user2(a)example.org > Auth-Method: plain > Auth-Protocol: imap > * Request completely sent off < HTTP/1.1 200 OK < Auth-Port: 143 < Auth-Server: 192.168.0.5 < Auth-Status: OK < Auth-User: user2(a)example.org < X-Nauthilus-Memory-Cache: Miss < X-Nauthilus-Session: 36vb8ONSo0MJTjECvOKOQbpd4Fh < Date: Tue, 16 Dec 2025 12:57:11 GMT < Content-Length: 0 < * Connection #0 to host 192.168.0.6 left intact Is there anything else that you might suggest or observe? Are there any flags in the 1.11 branch (similar to "server.dedup.in_process_enabled") that might (need to) be set? Is there any more information that I might be able to supply to assist? What we do not understand and cannot explain is this "passdb_backend=unknown". It is like for some request instances there is a null pointer for the server … and typing this and seeing the logs, I note: Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #1 is free" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapPoolI…> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #2 is free" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapPoolI…> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #3 is busy or closed" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapP> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #4 is busy or closed" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapP> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #5 is busy or closed" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapP> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #6 is busy or closed" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapP> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #7 is busy or closed" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapP> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="LDAP free/busy state #8 is busy or closed" instance=nauthilus pool=auth debug_module=ldappool function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapP> Dec 16 13:34:43 hostpack-nauthilus-01 nauthilus[71980]: time=2025-12-16T13:34:43.796Z level=DEBUG msg="State open connections" instance=nauthilus pool=auth needClosing=0 openConnections=2 idlePoolSize=2 debug_module=ldappool function=github.com/croessner/nauthilus/ser> Could these "busy or closed" LDAP instances #3-#8 be causing the "unknown" backend? Regards, Chris M. ________________________________ From: Christian Rößner Sent: Tuesday, December 16, 2025 12:19 To: Christopher Moules Cc: Main list for Nauthilus users Subject: Re: [Nauthilus-users] Why do I get "passdb_backend=unknown" for a subset of requests Hi, > Am 16.12.2025 um 11:35 schrieb Christopher Moules via Nauthilus-users <nauthilus-users(a)lists.nauthilus.org>: > > Hello, > We are trying to deploy Nauthilus as a replacement to some legacy software, initially as a nginx ‘auth_http’ service. > Initially, we are working with a configuration based on your “Getting started” example: > https://nauthilus.org/docs/about/getting-started#basic-configuration > We have 2 backends: LDAP and Redis Cache (KeyDB in practice): > backends: > - cache > - ldap # Or "lua" if using Lua backend > All testing performed worked fine. > After going into production, we had a small but significant percentage of connections that were failed with: > status_message="Invalid login or password" > passdb_backend=unknown > Initially, it looked like they were just “valid” failed logins, but we received a number of tickets so we looked closer at the logs. > We noted that the affected logins/accounts had this “passdb_backend=unknown” as opposed to “passdb_backend=ldap” or “passdb_backend=cache”. > Performing debugging with cURL and the “?mode=no-auth” we are able to get ‘positive’ results and seeing that the users are found in the LDAP DB. > We are unable to see why for some requests Nauthilus is not finding the user. > Some anonymised debug logs: … I had some issues in 1.10.x and <1.11.4 with Request-deduplication. If you use 1.10.x, can you set server.dedup.in_process_enabled to false or better give 1.11.4 a try. Kind regards Christian Rößner -- Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5

1 0

Why do I get "passdb_backend=unknown" for a subset of requests
by Christopher Moules 16 Dec '25

16 Dec '25

Hello, We are trying to deploy Nauthilus as a replacement to some legacy software, initially as a nginx 'auth_http' service. Initially, we are working with a configuration based on your "Getting started" example: https://nauthilus.org/docs/about/getting-started#basic-configuration We have 2 backends: LDAP and Redis Cache (KeyDB in practice): backends: - cache - ldap # Or "lua" if using Lua backend All testing performed worked fine. After going into production, we had a small but significant percentage of connections that were failed with: status_message="Invalid login or password" passdb_backend=unknown Initially, it looked like they were just "valid" failed logins, but we received a number of tickets so we looked closer at the logs. We noted that the affected logins/accounts had this "passdb_backend=unknown" as opposed to "passdb_backend=ldap" or "passdb_backend=cache". Performing debugging with cURL and the "?mode=no-auth" we are able to get 'positive' results and seeing that the users are found in the LDAP DB. We are unable to see why for some requests Nauthilus is not finding the user. Some anonymised debug logs: Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.813Z level=NOTICE msg="Processing incoming request" instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD mode=auth protocol=imap oidc_cid=N/A local_ip=N/A port=N/A client_ip=213.135.240.182 client_port=N/A client_host=N/A tls_protocol=N/A tls_cipher=N/A auth_method=plain username=user(a)example.org user_agent=N/A client_id=N/A uri_path=/api/v1/auth/nginx Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.814Z level=DEBUG msg="Creating new PassDBResult object" instance=nauthilus debug_module=auth function=main.main.InitPassDBResultPool.func1 Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.814Z level=DEBUG msg=debug instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD passdb=cache username=user(a)example.org passdb_result="{Authenticated:false UserFound:false BackendName: AccountField: TOTPSecretField: TOTPRecoveryField: UniqueUserIDField: DisplayNameField: Backend:unknown Attributes:map[] AdditionalFeatures:map[]}" debug_module=auth function=github.com/croessner/nauthilus/server/core.ProcessPassDBResult Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.814Z level=DEBUG msg=debug instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD passdb=cache result="Authenticated='false' UserFound='false' BackendName='' AccountField='' TOTPSecretField='' TOTPRecoveryField='' UniqueUserIDField='' DisplayNameField='' Backend='unknown' Attributes='map[]' AdditionalFeatures='map[]'" debug_module=auth function=github.com/croessner/nauthilus/server/core.VerifyPasswordPipeline Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.814Z level=DEBUG msg="Creating new PassDBResult object" instance=nauthilus debug_module=auth function=main.main.InitPassDBResultPool.func1 Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.814Z level=DEBUG msg="Connection #1 is free, using it" instance=nauthilus pool=lookup session=36vDhQLfWoARPq7WaDfRnO2hJKD debug_module=ldap function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapPoolI… Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.815Z level=DEBUG msg=debug instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD passdb=ldap username=user(a)example.org passdb_result="{Authenticated:false UserFound:false BackendName: AccountField: TOTPSecretField: TOTPRecoveryField: UniqueUserIDField: DisplayNameField: Backend:unknown Attributes:map[] AdditionalFeatures:map[]}" debug_module=auth function=github.com/croessner/nauthilus/server/core.ProcessPassDBResult Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.815Z level=DEBUG msg=debug instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD passdb=ldap result="Authenticated='false' UserFound='false' BackendName='' AccountField='' TOTPSecretField='' TOTPRecoveryField='' UniqueUserIDField='' DisplayNameField='' Backend='unknown' Attributes='map[]' AdditionalFeatures='map[]'" debug_module=auth function=github.com/croessner/nauthilus/server/core.VerifyPasswordPipeline Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.815Z level=NOTICE msg="Authentication request has failed" instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD mode=auth backend_name=N/A protocol=imap oidc_cid=N/A local_ip=N/A port=N/A client_ip=213.135.240.182 client_port=N/A client_host=N/A tls_protocol=N/A tls_cipher=N/A auth_method=plain username=user(a)example.org passdb_backend=unknown current_password_retries=1 account_passwords_seen=0 total_passwords_seen=0 user_agent=N/A client_id=N/A brute_force_bucket=N/A feature=N/A status_message="Invalid login or password" uri_path=/api/v1/auth/nginx authenticated=fail authz=true authn=false latency=2.075ms Dec 16 09:44:29 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T09:44:29.815Z level=INFO msg="HTTP request" instance=nauthilus session=36vDhQLfWoARPq7WaDfRnO2hJKD client_ip=192.168.0.5http_method=GET protocol=HTTP/1.0 http_status=200 latency=2.395ms user_agent=N/A tls_protocol=N/A tls_cipher=N/A uri_path=/api/v1/auth/nginx auth_method=none Testing the same user with cURL: curl -v -H "Auth-User: user(a)example.org" -H "Auth-Method: plain" -H "Auth-Protocol: imap" http://192.168.0.6:9443/api/v1/auth/nginx?mode=no-auth * Trying 192.168.0.6:9443... * Connected to 192.168.0.6 (192.168.0.6) port 9443 * using HTTP/1.x > GET /api/v1/auth/nginx?mode=no-auth HTTP/1.1 > Host: 192.168.0.6:9443 > User-Agent: curl/8.14.1 > Accept: */* > Auth-User: user(a)example.org > Auth-Method: plain > Auth-Protocol: imap > * Request completely sent off < HTTP/1.1 200 OK < Auth-Port: 143 < Auth-Server: 192.168.0.5 < Auth-Status: OK < Auth-User: user(a)example.org < X-Nauthilus-Memory-Cache: Miss < X-Nauthilus-Session: 36vI2lUpJrwOrrrJinFYMMSpxab < Date: Tue, 16 Dec 2025 10:20:13 GMT < Content-Length: 0 < * Connection #0 to host 192.168.0.6 left intact The equivalent logs for the cURL request: Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.238Z level=DEBUG msg="mode=no-auth" instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab debug_module=auth function=github.com/croessner/nauthilus/server/core.(*AuthState).SetOperati… Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.238Z level=NOTICE msg="Processing incoming request" instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab mode=no-auth protocol=imap oidc_cid=N/A local_ip=N/A port=N/A client_ip=N/A client_port=N/A client_host=N/A tls_protocol=N/A tls_cipher=N/A auth_method=plain username=user(a)example.org user_agent=curl/8.14.1 client_id=N/A uri_path=/api/v1/auth/nginx Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.239Z level=DEBUG msg="Creating new PassDBResult object" instance=nauthilus debug_module=auth function=main.main.InitPassDBResultPool.func1 Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.240Z level=DEBUG msg=debug instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab passdb=cache username=user(a)example.org passdb_result="{Authenticated:false UserFound:false BackendName: AccountField: TOTPSecretField: TOTPRecoveryField: UniqueUserIDField: DisplayNameField: Backend:unknown Attributes:map[] AdditionalFeatures:map[]}" debug_module=auth function=github.com/croessner/nauthilus/server/core.ProcessPassDBResult Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.240Z level=DEBUG msg=debug instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab passdb=cache result="Authenticated='false' UserFound='false' BackendName='' AccountField='' TOTPSecretField='' TOTPRecoveryField='' UniqueUserIDField='' DisplayNameField='' Backend='unknown' Attributes='map[]' AdditionalFeatures='map[]'" debug_module=auth function=github.com/croessner/nauthilus/server/core.VerifyPasswordPipeline Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.240Z level=DEBUG msg="Creating new PassDBResult object" instance=nauthilus debug_module=auth function=main.main.InitPassDBResultPool.func1 Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.240Z level=DEBUG msg="Connection #1 is free, using it" instance=nauthilus pool=lookup session=36vI2lUpJrwOrrrJinFYMMSpxab debug_module=ldap function=github.com/croessner/nauthilus/server/backend/ldappool.(*ldapPoolI… Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.241Z level=DEBUG msg=debug instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab filter="(&(|(uid=user@example.org)(mailLocalAddress=user@example.org))(!(expirationdate=*))(!(pwdAccountLockedTime=*)))" debug_module=ldap function=github.com/croessner/nauthilus/server/backend/ldappool.(*LDAPConne… Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.241Z level=DEBUG msg=debug instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab passdb=ldap username=user(a)example.org passdb_result="{Authenticated:true UserFound:true BackendName:__meta_default__ AccountField:uid TOTPSecretField: TOTPRecoveryField: UniqueUserIDField: DisplayNameField:uid Backend:ldap Attributes:map[dn:[uid=user@example.org,ou=mailboxes,o=webhost4.pt.lu,dmdName=confixx] uid:[user@example.org] userPassword:[{crypt}$1$Yx8idnJk$mT7J7kAFNRGMMBEnC3aYs.]] AdditionalFeatures:map[]}" debug_module=auth function=github.com/croessner/nauthilus/server/core.ProcessPassDBResult Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.241Z level=DEBUG msg=debug instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab passdb=ldap result="Authenticated='true' UserFound='true' BackendName='__meta_default__' AccountField='uid' TOTPSecretField='' TOTPRecoveryField='' UniqueUserIDField='' DisplayNameField='uid' Backend='ldap' Attributes='map[dn:[uid=user@example.org,ou=mailboxes,o=webhost4.pt.lu,dmdName=confixx] uid:[user@example.org] userPassword:[{crypt}$1$Yx8idnJk$mT7J7kAFNRGMMBEnC3aYs.]]' AdditionalFeatures='map[]'" debug_module=auth function=github.com/croessner/nauthilus/server/core.VerifyPasswordPipeline Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.242Z level=DEBUG msg="Save password history to redis" instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab type=bktype.PositivePasswordCache debug_module=cache function=github.com/croessner/nauthilus/server/backend.SaveUserDataToRedis Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.243Z level=DEBUG msg=debug instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab redis="Fields set: 4" debug_module=cache function=github.com/croessner/nauthilus/server/backend.SaveUserDataToRedis Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.243Z level=DEBUG msg="Stored positive cache to redis" instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab key=nt:UCP:mail:user@example.org Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.243Z level=NOTICE msg="Authentication request was successful" instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab mode=no-auth backend_name=__meta_default__ protocol=imap oidc_cid=N/A local_ip=N/A port=N/A client_ip=N/A client_port=N/A client_host=N/A tls_protocol=N/A tls_cipher=N/A auth_method=plain username=user(a)example.org passdb_backend=ldap current_password_retries=0 account_passwords_seen=0 total_passwords_seen=0 user_agent=curl/8.14.1 client_id=N/A brute_force_bucket=N/A feature=N/A status_message=OK uri_path=/api/v1/auth/nginx authenticated=N/A authz=true authn=true latency=4.740ms Dec 16 10:20:13 hostpack-nauthilus-01 nauthilus[68703]: time=2025-12-16T10:20:13.245Z level=INFO msg="HTTP request" instance=nauthilus session=36vI2lUpJrwOrrrJinFYMMSpxab client_ip=192.168.0.5 http_method=GET protocol=HTTP/1.1 http_status=200 latency=4.853ms user_agent=curl/8.14.1 tls_protocol=N/A tls_cipher=N/A uri_path=/api/v1/auth/nginx auth_method=none Here it can be seen that the LDAP query returns a HIT (UserFound:true & passdb_backend=ldap) where as above (failing request) there seems to be a MISS (UserFound:false & passdb_backend=unknown). Might anybody have any insight as to why the one case is working and the other not. Again, this is not for all requests, the majority is working, however a significant number are failing with "passdb_backend=unknown". Thanks and Regards, Chris M. [ptlogo] Ce message et toutes les pi?ces jointes (ci-apr?s le "message") sont ?tablis ? l'intention exclusive de ses destinataires. Ils peuvent contenir des informations confidentielles, prot?g?es le cas ?ch?ant par le secret professionnel (article 41 de la loi du 5 avril 1993 relative au secteur financier). Si vous recevez ce message par erreur, merci de le d?truire et d'en avertir imm?diatement l'exp?diteur. Toute utilisation de ce message non conforme ? sa destination, toute diffusion ou toute publication, totale ou partielle, est interdite, sauf autorisation expresse. Tous les avis ou opinions pr?sent?s sont exclusivement ceux de l'auteur et ne repr?sentent pas n?cessairement ceux de POST Luxembourg. Internet ne permettant pas d'assurer l'int?grit? de ce message, POST Luxembourg d?cline toute responsabilit? au titre de ce message, dans l'hypoth?se o? il aurait ?t? modifi?.

2 1