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.

git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1452551 13f79535-47bb-0310-9956-ffa450edef68

diff --git a/include/ap_mmn.h b/include/ap_mmn.h
index b1cd0174d7575797929bc4c945ad7930d8a40453..cbcc513dedfa2f03aaab3cfe81a4d269b4cd2f25 100644 (file)
--- a/include/ap_mmn.h
+++ b/include/ap_mmn.h
@@ -415,6 +415,7 @@
  * 20121222.2 (2.5.0-dev)  Add ap_password_validate()
  * 20121222.3 (2.5.0-dev)  Add ppinherit to proxy_server_conf
  * 20121222.4 (2.5.0-dev)  Add uds_path to proxy_conn_rec
+ * 20121222.5 (2.5.0-dev)  Add "r" and "must_rebind" to util_ldap_connection_t
  */
 
 #define MODULE_MAGIC_COOKIE 0x41503235UL /* "AP25" */
@@ -422,7 +423,7 @@
 #ifndef MODULE_MAGIC_NUMBER_MAJOR
 #define MODULE_MAGIC_NUMBER_MAJOR 20121222
 #endif
-#define MODULE_MAGIC_NUMBER_MINOR 3                   /* 0...n */
+#define MODULE_MAGIC_NUMBER_MINOR 5                   /* 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 c31539817e285f8d9c25bb477af34413c1e0cb33..3d5faed965c79e6d0a2dc36321d9c544b7f4f518 100644 (file)
--- a/include/util_ldap.h
+++ b/include/util_ldap.h
@@ -129,6 +129,8 @@ 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 */
 } 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 f6db684796fe5218f6b83533ab9d4f4a5d5b0136..dc08dd40af9dc5a43fe50d3c65386b9181ede096 100644 (file)
--- a/modules/ldap/util_ldap.c
+++ b/modules/ldap/util_ldap.c
@@ -156,10 +156,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
@@ -178,6 +180,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;
         }
@@ -318,6 +323,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);
@@ -513,6 +520,9 @@ 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 { 
+        ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, ldc->r, "LDC %pp bind", ldc);
+    }
     return rc;
 }
 
@@ -537,7 +547,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;
@@ -618,6 +628,7 @@ static int uldap_connection_open(request_rec *r,
     }
     else {
         ldc->bound = 1;
+        ldc->must_rebind = 0;
         ldc->reason = "LDAP: connection open successful";
     }
 
@@ -719,9 +730,13 @@ static util_ldap_connection_t *
                     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);
+                    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;
         }
@@ -748,12 +763,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->freed) > 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);
+                        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
@@ -843,6 +871,7 @@ static util_ldap_connection_t *
 #if APR_HAS_THREADS
     apr_thread_mutex_unlock(st->mutex);
 #endif
+    l->r = r;
     return l;
 }
 
@@ -1768,10 +1797,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);
     }
 
     /*