Linux – Apache auth_ldap “authentication failed” only for a single user

We have a tricky problem with apache and auth_ldap against AD. Only a single user is not allowed to login, although it is in one of the allowed groups and other users of this group are allowed.

When this user tries to login he gets an 401 status code and in the apache error log (in debug mode) we get:

[Mon Jun 18 13:34:37.699991 2018] [ssl:debug] [pid 7097] ssl_engine_kernel.c(225): [client 10.0.0.1:45287] AH02034: Initial (No.1) HTTPS request received for child 4 
(server xxxxxxxxxxxxx.at:80)
[Mon Jun 18 13:34:37.700189 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group1,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700201 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group2,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700206 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group3,OU=zuChecken,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700210 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group4,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700214 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group5,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700218 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group6,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700244 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=
group7,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700248 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=group8,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700252 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group CN=group9,xxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700256 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of Require ldap-group cn=group10,xxxxxxxxxxxxxxxxxxxxxxxxxx,dc=at: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700260 2018] [authz_core:debug] [pid 7097] mod_authz_core.c(809): [client 10.0.0.1:45287] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Mon Jun 18 13:34:37.700381 2018] [authnz_ldap:debug] [pid 7097] mod_authnz_ldap.c(501): [client 10.0.0.1:45287] AH01691: auth_ldap authenticate: using URL ldap://xxxxxxxxxxxxxxxxxxxxxxxxxx/xxxxxxxxxxxxxxxxxxxxxxxxxx,dc=at?sAMAccountName
[Mon Jun 18 13:34:37.700522 2018] [ldap:debug] [pid 7097] util_ldap.c(379): AH01278: LDAP: Setting referrals to On.
[Mon Jun 18 13:34:37.953306 2018] [ldap:debug] [pid 7097] util_ldap.c(379): AH01278: LDAP: Setting referrals to On.
[Mon Jun 18 13:34:38.003997 2018] [authnz_ldap:info] [pid 7097] [client 10.0.0.1:45287] AH01695: auth_ldap authenticate: user domain\\username authentication failed; URI / [User not found][No such object]
[Mon Jun 18 13:34:38.004050 2018] [auth_basic:error] [pid 7097] [client 10.0.0.1:45287] AH01618: user domain\\username not found: /

Apache config file looks like:

Header set Access-Control-Allow-Origin "*"
LogLevel debug

<Location />

        AuthName "Login with User"
        AuthType Basic
        AuthBasicProvider ldap
        AuthLDAPBindDN "CN=xxxxxxxxxxxxxxxxxx,DC=at"
        AuthLDAPBindPassword xxxxxxxxxxxxxx

        AuthLDAPURL "ldap://xxxxxxxxxx/xxxxxxxxxxx,dc=at?sAMAccountName"

        Require ldap-group CN=group1,xxxxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at
        Require ldap-group CN=group2,xxxxxxxxxxxxxxxxxxxxxxxxxxxx,DC=at
        Require ldap-group ....
</Location>

As I said, all other users work, but not this one.

So I went further and did an ldapquery for a few users counting the size of the ldap objects. I got this result:

for eh in username1 username2 username3 username4 username5; do echo "######### $eh"; ldapsearch -x -h xxxxxxxxxxxxxxxxxx:389 -D "CN=xxxxxxxxxxxxxxxxxx,DC=at" -w 'xxxxxxxxxxxxxxxxxx'  -b  "xxxxxxxxxxxxxxxxxx" "(sAMAccountName=$eh)"|wc ; done
######### username1
    473     778   26675
######### username2
    711    1294   40586
######### username3
    503     963   25752
######### username4
    309     591   15015
######### username5
    321     581   16972

The one with the problem is username2. And this is the only real difference. I have to add, this user was able to login in the past but we actually don't know what had changed. So the question is, is it possible, that mod_auth_ldap is not able to handle results larger than 32KiB? Or do we have another problem?

Sadly there is no documentation about apaches new error numbers like AH01618 :/ .

Our system description:

# cat /etc/redhat-release 
CentOS Linux release 7.4.1708 (Core)
# rpm -qa|grep httpd
httpd-2.4.6-67.el7.centos.6.x86_64
httpd-tools-2.4.6-67.el7.centos.6.x86_64
# rpm -qa|grep ldap
sssd-ldap-1.15.2-50.el7_4.8.x86_64
mod_ldap-2.4.6-67.el7.centos.6.x86_64
openldap-2.4.44-5.el7.x86_64
openldap-clients-2.4.44-5.el7.x86_64
python-ldap-2.4.15-2.el7.x86_64
apr-util-ldap-1.5.2-6.el7.x86_64

Edit:
We checked for max token size like described @ms.com and got following output with the affected user:

The computer is Windows Server 2012 R2 and is a member server.

Token Details for user affectedUser
**********************************
User's domain is xxxxxxxx.
Total estimated token size is 7408.
For access to DCs and delegatable resources the total estimated token delegation size is 14816.
Effective MaxTokenSize value is: 48000
Problem not detected.

Compared to another (working) user:

Token Details for user workingUser
**********************************
User's domain is xxxxxxxxxx.
Total estimated token size is 4192.
For access to DCs and delegatable resources the total estimated token delegation size is 8384.
Effective MaxTokenSize value is: 48000
Problem not detected.