You are viewing a plain text version of this content. The canonical link for it is here.
Posted to bugs@httpd.apache.org by bu...@apache.org on 2017/03/27 15:42:03 UTC
[Bug 60923] New: Server Error 500 if no LDAPConnectionPoolTTL is set
and the LDAP server has a keepalive set
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
Bug ID: 60923
Summary: Server Error 500 if no LDAPConnectionPoolTTL is set
and the LDAP server has a keepalive set
Product: Apache httpd-2
Version: 2.4.20
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: mod_ldap
Assignee: bugs@httpd.apache.org
Reporter: guido.wischrop@mgm-tp.com
Target Milestone: ---
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
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #8 from Eric Covener <co...@gmail.com> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #4 from Eric Covener <co...@gmail.com> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
Eric Covener <co...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--- Comment #2 from Eric Covener <co...@gmail.com> ---
(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?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
Torsten Krah <kr...@gmail.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
CC| |krah.tm+apache@gmail.com
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #7 from Guido W. <gu...@mgm-tp.com> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #6 from Eric Covener <co...@gmail.com> ---
> 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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #3 from Guido W. <gu...@mgm-tp.com> ---
(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).
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
Guido W. <gu...@mgm-tp.com> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEEDINFO |NEW
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #9 from Guido W. <gu...@mgm-tp.com> ---
(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).
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #5 from Guido W. <gu...@mgm-tp.com> ---
(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.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org
[Bug 60923] Server Error 500 if no LDAPConnectionPoolTTL is set and
the LDAP server has a keepalive set
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=60923
--- Comment #1 from Guido W. <gu...@mgm-tp.com> ---
Addendum
Suggested Fix:
--------------
3) Please don't use the error message "Administrative limit exceeded", because
it is misleading in this case.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org