Bug 60923 - Server Error 500 if no LDAPConnectionPoolTTL is set and the LDAP server has a keepalive set
Summary: Server Error 500 if no LDAPConnectionPoolTTL is set and the LDAP server has a...
Status: NEW
Alias: None
Product: Apache httpd-2
Classification: Unclassified
Component: mod_ldap (show other bugs)
Version: 2.4.20
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: ---
Assignee: Apache HTTPD Bugs Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-03-27 15:42 UTC by Guido W.
Modified: 2017-03-31 15:18 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Guido W. 2017-03-27 15:42:03 UTC
Observations:
-------------
We see Server Error 500 response codes on our reverse proxy for an SVN server. Those errors occur randomly and may cause wrong checkout, because the SVN client silently ignores the 500 error.

Please note this error in the logs below:

AH01695: auth_ldap authenticate: user svnuser1 authentication failed; ... [ldap_search_ext_s() for user failed][Administrative limit exceeded]

This causes a Server Error 500 response even if the authentication was successful on the next try.


Possible cause:
---------------
Our initial configuration did not have LDAPConnectionPoolTTL set, but the LDAP server has a 180s keepalive for client connections. So the LDAP server will disconnect an unused connection, while the connection may be still in the apache LDAP connection pool.


Suggested Fix:
--------------
1) Please log those errors AH01695 at least at level WARN, otherwise this problem is very hard to find.
2) It seems the module already handles the problem with the broken connection because it logs "AH01626: authorization result of <RequireAny>: granted" at the end. So instead of returning the Server Error 500 it should continue the request.



apache reverse proxy config:
----------------------------

LDAPSharedCacheSize 8000000
LDAPOpCacheEntries 16384
LDAPOpCacheTTL 900
LDAPCacheEntries 16384
LDAPCacheTTL 900

##########################################
# this fixes the problem for us, because our LDAP server has a 180s keepalive
#
# LDAPConnectionPoolTTL 150
##########################################

AuthLDAPURL ldaps://ldap.myserver.net:1234/dc=com?loginName,uid?sub
AuthLDAPBindDN uid=ldapuser1,ou=people,dc=mydomain,dc=com

AuthLDAPBindPassword PASSWORD

AuthType basic
AuthName "Secured by LDAP"
AuthBasicProvider ldap
Require ldap-attribute permissionRole=USE_SVN




apache reverse proxy access log:
--------------------------------
10.10.10.56 svn.myserver.net - [28/Feb/2017:12:54:36 +0100] "OPTIONS /svn/asc091/Components/System_Tests/trunk HTTP/1.1" 401 - "-" "SVN/1.6.17 (r1128011) neon/0.29.6"
10.10.10.56 svn.myserver.net svnuser1 [28/Feb/2017:12:54:36 +0100] "OPTIONS /svn/asc091/Components/System_Tests/trunk HTTP/1.1" 500 1177 "-" "SVN/1.6.17 (r1128011) neon/0.29.6"


apache reverse proxy error log:
-------------------------------
[Tue Feb 28 12:54:36.336309 2017] [ssl:info] [pid 38022:tid 139731039868672] [client 10.10.10.56:38730] AH01964: Connection to child 150 established (server svn.myserver.net:443)
[Tue Feb 28 12:54:36.336628 2017] [ssl:debug] [pid 38022:tid 139731039868672] ssl_engine_kernel.c(2101): [client 10.10.10.56:38730] AH02043: SSL virtual host for servername svn.myserver.net found
[Tue Feb 28 12:54:36.389053 2017] [socache_shmcb:debug] [pid 38022:tid 139731039868672] mod_socache_shmcb.c(495): AH00831: socache_shmcb_store (0x49 -> subcache 9)
[Tue Feb 28 12:54:36.389073 2017] [socache_shmcb:debug] [pid 38022:tid 139731039868672] mod_socache_shmcb.c(786): AH00845: about to force-expire, subcache: idx_used=68, data_used=13982
[Tue Feb 28 12:54:36.389077 2017] [socache_shmcb:debug] [pid 38022:tid 139731039868672] mod_socache_shmcb.c(813): AH00846: finished force-expire, subcache: idx_used=67, data_used=13776
[Tue Feb 28 12:54:36.389081 2017] [socache_shmcb:debug] [pid 38022:tid 139731039868672] mod_socache_shmcb.c(849): AH00847: insert happened at idx=8, data=(10722:10754)
[Tue Feb 28 12:54:36.389084 2017] [socache_shmcb:debug] [pid 38022:tid 139731039868672] mod_socache_shmcb.c(854): AH00848: finished insert, subcache: idx_pos/idx_used=32/68, data_pos/data_used=11122/13982
[Tue Feb 28 12:54:36.389097 2017] [socache_shmcb:debug] [pid 38022:tid 139731039868672] mod_socache_shmcb.c(516): AH00834: leaving socache_shmcb_store successfully
[Tue Feb 28 12:54:36.389109 2017] [ssl:debug] [pid 38022:tid 139731039868672] ssl_engine_kernel.c(2028): [client 10.10.10.56:38730] AH02041: Protocol: TLSv1.2, Cipher: DHE-RSA-AES256-SHA256 (256/256 bits)
[Tue Feb 28 12:54:36.442749 2017] [ssl:debug] [pid 38022:tid 139731039868672] ssl_engine_kernel.c(366): [client 10.10.10.56:38730] AH02034: Initial (No.1) HTTPS request received for child 150 (server svn.myserver.net:443)
[Tue Feb 28 12:54:36.442786 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of Require ldap-attribute permissionRole=USE_SVN: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.442793 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.442866 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of Require ldap-attribute permissionRole=USE_SVN: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.442871 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.457405 2017] [ssl:debug] [pid 38022:tid 139731039868672] ssl_engine_kernel.c(366): [client 10.10.10.56:38730] AH02034: Subsequent (No.2) HTTPS request received for child 150 (server svn.myserver.net:443)
[Tue Feb 28 12:54:36.457449 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of Require ldap-attribute permissionRole=USE_SVN: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.457456 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.457469 2017] [authnz_ldap:debug] [pid 38022:tid 139731039868672] mod_authnz_ldap.c(516): [client 10.10.10.56:38730] AH01691: auth_ldap authenticate: using URL ldaps://ldap.myserver.net:1234/dc=com?loginName,uid?sub
[Tue Feb 28 12:54:36.457546 2017] [authnz_ldap:info] [pid 38022:tid 139731039868672] [client 10.10.10.56:38730] AH01695: auth_ldap authenticate: user svnuser1 authentication failed; URI /svn/asc091/Components/System_Tests/trunk [ldap_search_ext_s() for user failed][Administrative limit exceeded]
[Tue Feb 28 12:54:36.457626 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of Require ldap-attribute permissionRole=USE_SVN: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.457632 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of <RequireAny>: denied (no authenticated user yet)
[Tue Feb 28 12:54:36.457637 2017] [authnz_ldap:debug] [pid 38022:tid 139731039868672] mod_authnz_ldap.c(516): [client 10.10.10.56:38730] AH01691: auth_ldap authenticate: using URL ldaps://ldap.myserver.net:1234/dc=com?loginName,uid?sub
[Tue Feb 28 12:54:36.475358 2017] [authnz_ldap:debug] [pid 38022:tid 139731039868672] mod_authnz_ldap.c(613): [client 10.10.10.56:38730] AH01697: auth_ldap authenticate: accepting svnuser1
[Tue Feb 28 12:54:36.475384 2017] [authnz_ldap:debug] [pid 38022:tid 139731039868672] mod_authnz_ldap.c(1217): [client 10.10.10.56:38730] AH01734: auth_ldap authorize: checking attribute permissionRole has value USE_SVN
[Tue Feb 28 12:54:36.477798 2017] [authnz_ldap:debug] [pid 38022:tid 139731039868672] mod_authnz_ldap.c(1223): [client 10.10.10.56:38730] AH01735: auth_ldap authorize: require attribute: authorization successful
[Tue Feb 28 12:54:36.477826 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of Require ldap-attribute permissionRole=USE_SVN: granted
[Tue Feb 28 12:54:36.477831 2017] [authz_core:debug] [pid 38022:tid 139731039868672] mod_authz_core.c(809): [client 10.10.10.56:38730] AH01626: authorization result of <RequireAny>: granted
[Tue Feb 28 12:54:36.480561 2017] [ssl:debug] [pid 38022:tid 139731039868672] ssl_engine_io.c(1033): [client 10.10.10.56:38730] AH02001: Connection closed to child 150 with standard shutdown (server svn.myserver.net:443)



ldap server log:
----------------
[2017-02-28 12:54:36.424 +0100] CONNECT conn=50284005 from=192.168.1.23:57034 to=192.168.1.24:1234 protocol=LDAPS
[2017-02-28 12:54:36.424 +0100] BIND conn=50284005 op=0 msgID=1 version=3 type=SIMPLE dn="uid=ldapuser1,ou=people,dc=mydomain,dc=com" result=0 authDN="uid=ldapuser1,ou=people,dc=mydomain,dc=com" etime=107275
[2017-02-28 12:54:36.424 +0100] SEARCH conn=50284005 op=1 msgID=2 base="dc=com" scope=sub filter="(&(objectclass=*)(loginName=svnuser1))" attrs="loginName,uid" result=0 nentries=1 etime=302872
[2017-02-28 12:54:36.424 +0100] BIND conn=50284005 op=2 msgID=3 version=3 type=SIMPLE dn="uid=svnuser1,ou=people,dc=mydomain,dc=com" result=0 authDN="uid=svnuser1,ou=people,dc=mydomain,dc=com" etime=113956
[2017-02-28 12:54:36.424 +0100] BIND conn=50284005 op=3 msgID=4 version=3 type=SIMPLE dn="uid=ldapuser1,ou=people,dc=mydomain,dc=com" result=0 authDN="uid=ldapuser1,ou=people,dc=mydomain,dc=com" etime=112638
[2017-02-28 12:54:36.424 +0100] COMPARE conn=50284005 op=4 msgID=5 dn="uid=svnuser1,ou=people,dc=mydomain,dc=com" attr=permissionRole result=6 etime=132232


svn access log:
---------------
NO ENTRY
Comment 1 Guido W. 2017-03-27 15:56:59 UTC
Addendum


Suggested Fix:
--------------
3) Please don't use the error message "Administrative limit exceeded", because it is misleading in this case.
Comment 2 Eric Covener 2017-03-27 16:41:57 UTC
(In reply to Guido W. from comment #1)
> Addendum
> 
> 
> Suggested Fix:
> --------------
> 3) Please don't use the error message "Administrative limit exceeded",
> because it is misleading in this case.

Unless something unique is happening here, this generally come from the SDK. In what cases should it be second-guessed?
Comment 3 Guido W. 2017-03-27 16:47:52 UTC
(In reply to Eric Covener from comment #2)
> (In reply to Guido W. from comment #1)
> > Addendum
> > 
> > 
> > Suggested Fix:
> > --------------
> > 3) Please don't use the error message "Administrative limit exceeded",
> > because it is misleading in this case.
> 
> Unless something unique is happening here, this generally come from the SDK.
> In what cases should it be second-guessed?

That would imply that the response actually came from the LDAP server, but I don't think that is the case here, because the failed request is not logged at the LDAP server (not even at debug level).
Comment 4 Eric Covener 2017-03-31 13:58:02 UTC
(In reply to Guido W. from comment #3)
> (In reply to Eric Covener from comment #2)
> > (In reply to Guido W. from comment #1)
> > > Addendum
> > > 
> > > 
> > > Suggested Fix:
> > > --------------
> > > 3) Please don't use the error message "Administrative limit exceeded",
> > > because it is misleading in this case.
> > 
> > Unless something unique is happening here, this generally come from the SDK.
> > In what cases should it be second-guessed?
> 
> That would imply that the response actually came from the LDAP server, but I
> don't think that is the case here, because the failed request is not logged
> at the LDAP server (not even at debug level).

Perhaps you could log in the client SDK itself?  Everything mod_ldap knows about the backend LDAP server is via the calls to the LDAP SDK.
Comment 5 Guido W. 2017-03-31 14:35:35 UTC
(In reply to Eric Covener from comment #4)

> Perhaps you could log in the client SDK itself?
I'm sorry, I won't be able to do that.

So you are saying the ldap module logs

[Tue Feb 28 12:54:36.457546 2017] [authnz_ldap:info] [pid 38022:tid 139731039868672] [client 10.10.10.56:38730] AH01695: auth_ldap authenticate: user svnuser1 authentication failed; URI /svn/asc091/Components/System_Tests/trunk [ldap_search_ext_s() for user failed][Administrative limit exceeded]

because it got exactly that from the SDK: "Administrative limit exceeded"?

If that is so, then maybe it's possible to check the connection state at that moment and if it's closed log that information too?

Thanks,
Guido

> (In reply to Guido W. from comment #3)
> > (In reply to Eric Covener from comment #2)
> > > (In reply to Guido W. from comment #1)
> > > > Addendum
> > > > 
> > > > 
> > > > Suggested Fix:
> > > > --------------
> > > > 3) Please don't use the error message "Administrative limit exceeded",
> > > > because it is misleading in this case.
> > > 
> > > Unless something unique is happening here, this generally come from the SDK.
> > > In what cases should it be second-guessed?
> > 
> > That would imply that the response actually came from the LDAP server, but I
> > don't think that is the case here, because the failed request is not logged
> > at the LDAP server (not even at debug level).
> 
> Perhaps you could log in the client SDK itself?  Everything mod_ldap knows
> about the backend LDAP server is via the calls to the LDAP SDK.
Comment 6 Eric Covener 2017-03-31 14:44:02 UTC
> So you are saying the ldap module logs
> 
> [Tue Feb 28 12:54:36.457546 2017] [authnz_ldap:info] [pid 38022:tid
> 139731039868672] [client 10.10.10.56:38730] AH01695: auth_ldap authenticate:
> user svnuser1 authentication failed; URI
> /svn/asc091/Components/System_Tests/trunk [ldap_search_ext_s() for user
> failed][Administrative limit exceeded]
> 
> because it got exactly that from the SDK: "Administrative limit exceeded"?

Yes, nearly.   ldap_serch_ext_s() returned a numeric error code. We passed the numeric code into ldap_err2string() and it returned that string.

We don't even have an underlying socket for the LDAP server. It's encapsulated by the LDAP client SDK -- we can just open, bind, search and look at LDAP-specific return codes.

In this case, we get what looks like a pretty vague/generic error back from the SDK.
Comment 7 Guido W. 2017-03-31 14:51:18 UTC
(In reply to Eric Covener from comment #6)

Hmm - in the documentation here

https://httpd.apache.org/docs/2.4/mod/mod_ldap.html#pool

it sound like the ldap module / apache server handles the connection pool.

If the ldap module is not the right point to fix this can you please point me to the correct place?

> > So you are saying the ldap module logs
> > 
> > [Tue Feb 28 12:54:36.457546 2017] [authnz_ldap:info] [pid 38022:tid
> > 139731039868672] [client 10.10.10.56:38730] AH01695: auth_ldap authenticate:
> > user svnuser1 authentication failed; URI
> > /svn/asc091/Components/System_Tests/trunk [ldap_search_ext_s() for user
> > failed][Administrative limit exceeded]
> > 
> > because it got exactly that from the SDK: "Administrative limit exceeded"?
> 
> Yes, nearly.   ldap_serch_ext_s() returned a numeric error code. We passed
> the numeric code into ldap_err2string() and it returned that string.
> 
> We don't even have an underlying socket for the LDAP server. It's
> encapsulated by the LDAP client SDK -- we can just open, bind, search and
> look at LDAP-specific return codes.
> 
> In this case, we get what looks like a pretty vague/generic error back from
> the SDK.
Comment 8 Eric Covener 2017-03-31 15:05:24 UTC
(In reply to Guido W. from comment #7)
> (In reply to Eric Covener from comment #6)
> 
> Hmm - in the documentation here
> 
> https://httpd.apache.org/docs/2.4/mod/mod_ldap.html#pool
> 
> it sound like the ldap module / apache server handles the connection pool.
> 
> If the ldap module is not the right point to fix this can you please point
> me to the correct place?

It's a pool of objects from the LDAP client SDK that represent connections to the server. 

There are several issues in the bug report. We are usually careful about raising severity of messages.  I am not sure if you're misinterpreting some logs here, but the real culprit may be that no retry occurred where you expected one.

A stronger case would be needed to raise the severity of the message. Having a connection go south like this does not seem extraordinary.  

e.g. Maybe mod_ldap doesn't think the error is retryable.

The only thing to take up externally is if you wanted to understand precisely why this error code is and is not returned and make some kind of case for special handling of it.
Comment 9 Guido W. 2017-03-31 15:18:03 UTC
(In reply to Eric Covener from comment #8)

Ok, to avoid misunderstandings here, if 2) get's fixed, then there might no need for the change 1) and 3). But otherwise the (proxy-) server returns error 500 with no indication what has gone wrong, which seems to be a problem (at least for me).