Hello Christian,
> Could you please forward the null pointer exceptions. This is very important.
As I tried to imply, this was speculation. I do not have anything "black and white" that shows null pointers.
Having read more about the LDAP configuration, what I saw here is probably the LDAP pools (search/auth) and the "idle_pool_size" (2x LDAP connections) and the others are then connected on-demand.
I had wondered if the "LDAP free/busy state #3 is busy or closed" was informing me that the connection was non-functional and if a thread used this connection that it would fail. Now I think I understand this better, and these are "just" currently unused LDAP
connection instances.
> What I see from the logs is that LDAP is telling you that it did not find the user: UserFound:false
> Do you see LDAP-filter logs? If so, can you manually check if that filter works?
I thought that I had stated, and shown with logs, if I perform a "?mode=no-auth" for the
same user that is failing, the user is found via the LDAP search. (see my first message and the logs supplied).
Simply said, "yes, the filter works".
The LDAP filter is identical to that in our legacy codebase.
I would need to do some correlation with the LDAP server and the logs, but I believe that Nauthilus is not performing a LDAP search against the LDAP server when I am seeing "passdb_backend=unknown" and "Backend='unknown'" in the Nauthilus logs.
While composing this answer, I have been trying to see more in the logs. I think that I have a few clues.
I have looked at the following cases:
-
Login Success
-
Login Failure (incorrect - our problem case)
-
Login Failure (correct - user does not exist)
-
Login Failure (correct - password false)
Comparing a "success" to a "failure" (incorrect) and "failure" (correct) I am seeing some key differences.
The most significant to me, is that for all the correct use cases, I can see the LDAP filter in the LDAP debug. However, in the "failure" (incorrect) case, the LDAP debug line with the filter is missing.
Some log extracts (journald - heavily edited) re-arranged to read top-down.
Login Success:
level=NOTICE msg="Processing incoming request"
level=DEBUG msg="Connection #1 is free, using it" … pool=lookup
level=DEBUG … filter="redacted" debug_module=ldap
level=DEBUG msg="Connection #1 is free, using it" … pool=auth
level=DEBUG … passdb=ldap result="Authenticated='true' UserFound='true' BackendName='__meta_default__'
level=NOTICE msg="Authentication request was successful" … mode=auth backend_name=__meta_default__ protocol=pop3 … auth_method=plain username=redacted passdb_backend=ldap
… cache to redis and succeed.
Login Fail - user not exist:
level=NOTICE msg="Processing incoming request"
level=DEBUG msg="Connection #1 is free, using it" … pool=lookup
level=DEBUG … filter="redacted" debug_module=ldap
level=DEBUG … passdb=ldap username=redacted passdb_result="{Authenticated:false UserFound:false
level=NOTICE msg="Authentication request has failed" … mode=auth backend_name=N/A protocol=imap … auth_method=plain username=redacted passdb_backend=unknown
Login Fail - wrong PWD:
level=NOTICE msg="Processing incoming request"
level=DEBUG msg="Connection #1 is free, using it" … pool=lookup
level=DEBUG … filter="redacted" debug_module=ldap
level=DEBUG msg="Connection #1 is free, using it" … pool=auth
level=DEBUG … passdb=ldap result="Authenticated='false' UserFound='true' BackendName='__meta_default__'
level=NOTICE msg="Authentication request has failed" … mode=auth backend_name=__meta_default__ protocol=imap … auth_method=plain username=redacted passdb_backend=ldap
Login Fail - Our problem use case:
level=NOTICE msg="Processing incoming request"
level=DEBUG msg="Connection #1 is free, using it" … pool=lookup
<NOTE> Here missing 'level=DEBUG … filter="redacted" debug_module=ldap'</NOTE>
level=DEBUG … passdb=ldap username=redacted passdb_result="{Authenticated:false UserFound:false
level=NOTICE msg="Authentication request has failed" … mode=auth backend_name=N/A protocol=imap … auth_method=plain username=redacted passdb_backend=unknown
So, if I see correctly, in a subset of cases, we are seeing that the LDAP module is possibly(?) not querying the LDAP server, not getting any results and failing the request.
The lack of "BackendName='__meta_default__'" may or may not be a clue? However where a LDAP query returns no result (unknown user), this is also the case.
I have a feeling that this might have a link with "connection stability" or "persistence" with our legacy LDAP servers. It could well be that newer LDAP servers have better connection handling code and that you do not see this as you have "more functional"
LDAP servers. That said, I do not see directly any errors on the LDAP server side. I mention this as a possibility as this would not be a use-case that you have tested against.
Given the above observation, I will, when I have time and energy, try to look at the source code to the LDAP module and identify what might be happening between 'Connection #1 is free, using it' and 'filter="redacted"'.
Any further insights from your side are naturally welcome.
Seasons Greetings,
Chris
From: Christian Rößner <christian@roessner.email>
Sent: Wednesday, December 17, 2025 08:22
To: Christopher Moules <Christopher.Moules@post.lu>; Main list for Nauthilus users <nauthilus-users@lists.nauthilus.org>
Subject: Re: [Nauthilus-users] Why do I get "passdb_backend=unknown" for a subset of requests
ATTENTION: Ce mail provient de l'extérieur de Post. Ne cliquez pas sur les liens ou n'ouvrez pas les pièces jointes à moins de connaitre l'expéditeur et d'être sûr que le contenu est inoffensif. En cas de doute sur son origine
ou si vous pensez qu'il est suspect, nous vous prions de rapporter cet évènement par email à cybersos@post.lu.
Hi Christopher,
>> 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?
No
>>
>> 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:
Could you please forward the null pointer exceptions. This is very important.
>> 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.(*ldapPoolImpl).u>
>> 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.(*ldapPoolImpl).u>
>> 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?
I don’t think so, but of course I will investigate this.
What I see from the logs is that LDAP is telling you that it did not find the user: UserFound:false
Do you see LDAP-filter logs? If so, can you manually check if that filter works?
Kind regards
Christian
Rößner-Network-Solutions
Zertifizierter ITSiBe / CISO
Marburger Str. 70a, 36304 Alsfeld
Mobil: +49 171 9905345
USt-IdNr.: DE225643613,
https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Froessner.website%2F&data=05%7C02%7CChristopher.Moules%40post.lu%7C11ad69a8420549984f5808de3d3d1488%7C090a1bf958cc49fa8a9e3f7b0a100fa9%7C0%7C0%7C639015529720025415%7CUnknown%7CTWFpbGZsb3d8eyJFbXB0eU1hcGkiOnRydWUsIlYiOiIwLjAuMDAwMCIsIlAiOiJXaW4zMiIsIkFOIjoiTWFpbCIsIldUIjoyfQ%3D%3D%7C0%7C%7C%7C&sdata=zmSm%2Byegf7BO%2BqEQoOXE%2Firfse6OZJEZS3NfjTBE%2Fyc%3D&reserved=0
PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5