From: Jim Jagielski Date: Mon, 14 Jul 2014 12:07:55 +0000 (+0000) Subject: Merge r1452551, r1607960 from trunk: X-Git-Tag: 2.4.10~29 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=7d3ce74b785e3ed077ec12e7ff1bab12ca2c71f0;p=apache Merge r1452551, r1607960 from trunk: PR54587: LDAP connections used for authn were not respecting LDAPConnectionPoolTimeout due to confusion over what "bound" means. Added some LDAP trace at TRACE5 to track how LDAP connections are reused and rebound. make LDAPConnectionPoolTTL more conservative, use r->request_time rather than end-of-request time, and only update it after a round-trip with the LDAP server rather than every time we check back into the pool. Submitted by: covener Reviewed/backported by: jim git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/branches/2.4.x@1610396 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/CHANGES b/CHANGES index 9c14956eed..6697d8eee8 100644 --- a/CHANGES +++ b/CHANGES @@ -28,6 +28,12 @@ Changes with Apache 2.4.10 forward "100 Continue" (interim) response to the client if it does not expect one. [Yann Ylavic] + *) mod_ldap: Be more conservative with the last-used time for + LDAPConnectionPoolTTL. PR54587 [Eric Covener] + + *) mod_ldap: LDAP connections used for authn were not respecting + LDAPConnectionPoolTTL. PR54587 [Eric Covener] + *) mod_proxy_fcgi: Fix occasional high CPU when handling request bodies. [Jeff Trawick] diff --git a/STATUS b/STATUS index 3ff689a1a4..24b4450436 100644 --- a/STATUS +++ b/STATUS @@ -100,15 +100,6 @@ RELEASE SHOWSTOPPERS: PATCHES ACCEPTED TO BACKPORT FROM TRUNK: [ start all new proposals below, under PATCHES PROPOSED. ] - * mod_ldap: LDAPConnectionPoolTTL enhancements -- apply properly to authn and - only update the last used time when we hit the backend server - AND use r->request_time instead of end-of-request-time. - PR54587 - trunk patch: http://svn.apache.org/r1452551 - http://svn.apache.org/r1607960 - 2.4.x patch: http://people.apache.org/~covener/patches/httpd-2.4.x-ldap-connttl-conservative.diff - +1 covener, jim, trawick - * mod_deflate: Don't fail when asked to flush inflated data to the user-agent and that coincides with the end of stream ("Zlib error flushing inflate buffer"). PR 56196. diff --git a/docs/manual/mod/mod_ldap.xml b/docs/manual/mod/mod_ldap.xml index 3a6b3d7360..ba17358bc1 100644 --- a/docs/manual/mod/mod_ldap.xml +++ b/docs/manual/mod/mod_ldap.xml @@ -752,13 +752,18 @@ connection client certificates.

A setting of 0 causes connections to never be saved in the backend connection pool. The default value of -1, and any other negative value, - allows connections of any age to be reused.

- -

The timemout is based on when the LDAP connection is returned to the - pool, not based on the last time I/O has been performed over the backend - connection. If the information is cached, the apparent idle time can exceed - the LDAPConnectionPoolTTL.

- + allows connections of any age to be reused.

+ +

For performance reasons, the reference time used by this directive is + based on when the LDAP connection is returned to the pool, not the time + of the last successful I/O with the LDAP server.

+ +

Since 2.4.10, new measures are in place to avoid the reference time + from being inflated by cache hits or slow requests. First, the reference + time is not updated if no backend LDAP conncetions were needed. Second, + the reference time uses the time the HTTP request was received instead + of the time the request is completed.

+

This timeout defaults to units of seconds, but accepts suffixes for milliseconds (ms), minutes (min), and hours (h).

diff --git a/include/ap_mmn.h b/include/ap_mmn.h index 64769e62ee..7156f6015e 100644 --- a/include/ap_mmn.h +++ b/include/ap_mmn.h @@ -429,6 +429,8 @@ * 20120211.32 (2.4.10-dev) Add SSL reusable SNI to mod_proxy.h's proxy_conn_rec * 20120211.33 (2.4.10-dev) Add suspend_connection and resume_connection hooks * 20120211.34 (2.4.10-dev) AP_DEFAULT_HANDLER_NAME/AP_IS_DEFAULT_HANDLER_NAME + * 20120211.35 (2.4.10-dev) Add "r", "must_rebind", and last_backend_conn + to util_ldap_connection_t */ #define MODULE_MAGIC_COOKIE 0x41503234UL /* "AP24" */ @@ -436,7 +438,7 @@ #ifndef MODULE_MAGIC_NUMBER_MAJOR #define MODULE_MAGIC_NUMBER_MAJOR 20120211 #endif -#define MODULE_MAGIC_NUMBER_MINOR 34 /* 0...n */ +#define MODULE_MAGIC_NUMBER_MINOR 35 /* 0...n */ /** * Determine if the server's current MODULE_MAGIC_NUMBER is at least a diff --git a/include/util_ldap.h b/include/util_ldap.h index c7f7827370..aa79fc3065 100644 --- a/include/util_ldap.h +++ b/include/util_ldap.h @@ -133,6 +133,9 @@ typedef struct util_ldap_connection_t { int ReferralHopLimit; /* # of referral hops to follow (default = AP_LDAP_DEFAULT_HOPLIMIT) */ apr_time_t freed; /* the time this conn was placed back in the pool */ apr_pool_t *rebind_pool; /* frequently cleared pool for rebind data */ + int must_rebind; /* The connection was last bound with other then binddn/bindpw */ + request_rec *r; /* request_rec used to find this util_ldap_connection_t */ + apr_time_t last_backend_conn; /* the approximate time of the last backend LDAP requst */ } util_ldap_connection_t; typedef struct util_ldap_config_t { diff --git a/modules/ldap/util_ldap.c b/modules/ldap/util_ldap.c index bf37567ae8..0cc51c40ae 100644 --- a/modules/ldap/util_ldap.c +++ b/modules/ldap/util_ldap.c @@ -157,10 +157,12 @@ static void uldap_connection_close(util_ldap_connection_t *ldc) */ if (!ldc->keep) { uldap_connection_unbind(ldc); + ldc->r = NULL; } else { /* mark our connection as available for reuse */ ldc->freed = apr_time_now(); + ldc->r = NULL; #if APR_HAS_THREADS apr_thread_mutex_unlock(ldc->lock); #endif @@ -179,6 +181,9 @@ static apr_status_t uldap_connection_unbind(void *param) if (ldc) { if (ldc->ldap) { + if (ldc->r) { + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, ldc->r, "LDC %pp unbind", ldc); + } ldap_unbind_s(ldc->ldap); ldc->ldap = NULL; } @@ -319,6 +324,8 @@ static int uldap_connection_init(request_rec *r, return(result->rc); } + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, "LDC %pp init", ldc); + if (ldc->ChaseReferrals == AP_LDAP_CHASEREFERRALS_ON) { /* Now that we have an ldap struct, add it to the referral list for rebinds. */ rc = apr_ldap_rebind_add(ldc->rebind_pool, ldc->ldap, ldc->binddn, ldc->bindpw); @@ -516,6 +523,10 @@ static int uldap_simple_bind(util_ldap_connection_t *ldc, char *binddn, ldc->reason = "LDAP: ldap_simple_bind() parse result failed"; return uldap_ld_errno(ldc); } + else { + ldc->last_backend_conn = ldc->r->request_time; + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, ldc->r, "LDC %pp bind", ldc); + } return rc; } @@ -540,7 +551,7 @@ static int uldap_connection_open(request_rec *r, /* If the connection is already bound, return */ - if (ldc->bound) + if (ldc->bound && !ldc->must_rebind) { ldc->reason = "LDAP: connection open successful (already bound)"; return LDAP_SUCCESS; @@ -621,6 +632,7 @@ static int uldap_connection_open(request_rec *r, } else { ldc->bound = 1; + ldc->must_rebind = 0; ldc->reason = "LDAP: connection open successful"; } @@ -718,13 +730,17 @@ static util_ldap_connection_t * && !compare_client_certs(dc->client_certs, l->client_certs)) { if (st->connection_pool_ttl > 0) { - if (l->bound && (now - l->freed) > st->connection_pool_ttl) { + if (l->bound && (now - l->last_backend_conn) > st->connection_pool_ttl) { ap_log_rerror(APLOG_MARK, APLOG_TRACE1, 0, r, "Removing LDAP connection last used %" APR_TIME_T_FMT " seconds ago", - (now - l->freed) / APR_USEC_PER_SEC); + (now - l->last_backend_conn) / APR_USEC_PER_SEC); + l->r = r; uldap_connection_unbind(l); /* Go ahead (by falling through) and use it, so we don't create more just to unbind some other old ones */ } + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, + "Reuse %s LDC %pp", + l->bound ? "bound" : "unbound", l); } break; } @@ -751,12 +767,25 @@ static util_ldap_connection_t * (l->deref == deref) && (l->secure == secureflag) && !compare_client_certs(dc->client_certs, l->client_certs)) { - /* the bind credentials have changed */ - /* no check for connection_pool_ttl, since we are unbinding any way */ - uldap_connection_unbind(l); + if (st->connection_pool_ttl > 0) { + if (l->bound && (now - l->last_backend_conn) > st->connection_pool_ttl) { + ap_log_rerror(APLOG_MARK, APLOG_TRACE1, 0, r, + "Removing LDAP connection last used %" APR_TIME_T_FMT " seconds ago", + (now - l->last_backend_conn) / APR_USEC_PER_SEC); + l->r = r; + uldap_connection_unbind(l); + /* Go ahead (by falling through) and use it, so we don't create more just to unbind some other old ones */ + } + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, + "Reuse %s LDC %pp (will rebind)", + l->bound ? "bound" : "unbound", l); + } + /* the bind credentials have changed */ + l->must_rebind = 1; util_ldap_strdup((char**)&(l->binddn), binddn); util_ldap_strdup((char**)&(l->bindpw), bindpw); + break; } #if APR_HAS_THREADS @@ -846,6 +875,7 @@ static util_ldap_connection_t * #if APR_HAS_THREADS apr_thread_mutex_unlock(st->mutex); #endif + l->r = r; return l; } @@ -965,6 +995,7 @@ start_over: return result; } + ldc->last_backend_conn = r->request_time; entry = ldap_first_entry(ldc->ldap, res); searchdn = ldap_get_dn(ldc->ldap, entry); @@ -1116,6 +1147,7 @@ start_over: goto start_over; } + ldc->last_backend_conn = r->request_time; ldc->reason = "Comparison complete"; if ((LDAP_COMPARE_TRUE == result) || (LDAP_COMPARE_FALSE == result) || @@ -1241,6 +1273,7 @@ start_over: return res; } + ldc->last_backend_conn = r->request_time; entry = ldap_first_entry(ldc->ldap, sga_res); /* @@ -1723,6 +1756,7 @@ start_over: * We should have found exactly one entry; to find a different * number is an error. */ + ldc->last_backend_conn = r->request_time; count = ldap_count_entries(ldc->ldap, res); if (count != 1) { @@ -1788,10 +1822,10 @@ start_over: /* * We have just bound the connection to a different user and password * combination, which might be reused unintentionally next time this - * connection is used from the connection pool. To ensure no confusion, - * we mark the connection as unbound. + * connection is used from the connection pool. */ - ldc->bound = 0; + ldc->must_rebind = 0; + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, "LDC %pp used for authn, must be rebound", ldc); } /* @@ -1983,6 +2017,7 @@ start_over: * We should have found exactly one entry; to find a different * number is an error. */ + ldc->last_backend_conn = r->request_time; count = ldap_count_entries(ldc->ldap, res); if (count != 1) {