Attachment 17038 Details for Bug 14694 – v3 patch, with cherry-pick markers

[patch] v3 patch, with cherry-pick markers

CVE-2021-3670-ldap_spin-v4-15-v3.patch (text/plain), 23.36 KB, created by Douglas Bagnall on 2021-12-01 21:36:47 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Douglas Bagnall

Created: 2021-12-01 21:36:47 UTC

Size: 23.36 KB

patch

obsolete

>From af92c3ae6de14138150b7e12e54fe02d1c8c1e00 Mon Sep 17 00:00:00 2001
>From: Joseph Sutton <josephsutton@catalyst.net.nz>
>Date: Thu, 26 Aug 2021 21:18:26 +1200
>Subject: [PATCH 1/7] CVE-2021-3670 tests/krb5/test_ldap.py: Add test for LDAP
> timeouts
>
>We allow a timeout of 2x over to avoid this being a flapping test.
>Samba is not very accurate on the timeout, which is not otherwise an
>issue but makes this test fail sometimes.
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Joseph Sutton <josephsutton@catalyst.net.nz>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>(cherry picked from commit dcfcafdbf756e12d9077ad7920eea25478c29f81)
>---
> selftest/knownfail.d/ldap-timeout       |  1 +
> source4/dsdb/tests/python/large_ldap.py | 63 +++++++++++++++++++++++++
> 2 files changed, 64 insertions(+)
> create mode 100644 selftest/knownfail.d/ldap-timeout
>
>diff --git a/selftest/knownfail.d/ldap-timeout b/selftest/knownfail.d/ldap-timeout
>new file mode 100644
>index 00000000000..378ca1f4821
>--- /dev/null
>+++ b/selftest/knownfail.d/ldap-timeout
>@@ -0,0 +1 @@
>+samba4.ldap.large_ldap\..*\.python\(.*\).__main__.LargeLDAPTest.test_timeout\(.*\)
>\ No newline at end of file
>diff --git a/source4/dsdb/tests/python/large_ldap.py b/source4/dsdb/tests/python/large_ldap.py
>index 0bf73f988d8..f1fc13939e5 100644
>--- a/source4/dsdb/tests/python/large_ldap.py
>+++ b/source4/dsdb/tests/python/large_ldap.py
>@@ -23,6 +23,7 @@ import optparse
> import sys
> import os
> import random
>+import time
> 
> sys.path.insert(0, "bin/python")
> import samba
>@@ -244,6 +245,68 @@ class LargeLDAPTest(samba.tests.TestCase):
>         # Assert we don't get all the entries but still the error
>         self.assertGreater(count, count_jpeg)
> 
>+    def test_timeout(self):
>+        policy_dn = ldb.Dn(self.ldb,
>+                           'CN=Default Query Policy,CN=Query-Policies,'
>+                           'CN=Directory Service,CN=Windows NT,CN=Services,'
>+                           f'{self.ldb.get_config_basedn().get_linearized()}')
>+
>+        # Get the current value of lDAPAdminLimits.
>+        res = self.ldb.search(base=policy_dn,
>+                              scope=ldb.SCOPE_BASE,
>+                              attrs=['lDAPAdminLimits'])
>+        msg = res[0]
>+        admin_limits = msg['lDAPAdminLimits']
>+
>+        # Ensure we restore the previous value of the attribute.
>+        admin_limits.set_flags(ldb.FLAG_MOD_REPLACE)
>+        self.addCleanup(self.ldb.modify, msg)
>+
>+        # Temporarily lower the value of MaxQueryDuration so we can test
>+        # timeout behaviour.
>+        timeout = 5
>+        query_duration = f'MaxQueryDuration={timeout}'.encode()
>+
>+        admin_limits = [limit for limit in admin_limits
>+                        if not limit.lower().startswith(b'maxqueryduration=')]
>+        admin_limits.append(query_duration)
>+
>+        # Set the new attribute value.
>+        msg = ldb.Message(policy_dn)
>+        msg['lDAPAdminLimits'] = ldb.MessageElement(admin_limits,
>+                                                    ldb.FLAG_MOD_REPLACE,
>+                                                    'lDAPAdminLimits')
>+        self.ldb.modify(msg)
>+
>+        # Use a new connection so that the limits are reloaded.
>+        samdb = SamDB(url, credentials=creds,
>+                      session_info=system_session(lp),
>+                      lp=lp)
>+
>+        # Create a large search expression that will take a long time to
>+        # evaluate.
>+        expression = '(anr=l)' * 10000
>+        expression = f'(|{expression})'
>+
>+        # Perform the LDAP search.
>+        prev = time.time()
>+        with self.assertRaises(ldb.LdbError) as err:
>+            samdb.search(base=self.ou_dn,
>+                         scope=ldb.SCOPE_SUBTREE,
>+                         expression=expression,
>+                         attrs=['objectGUID'])
>+        now = time.time()
>+        duration = now - prev
>+
>+        # Ensure that we timed out.
>+        enum, _ = err.exception.args
>+        self.assertEqual(ldb.ERR_TIME_LIMIT_EXCEEDED, enum)
>+
>+        # Ensure that the time spent searching is within the limit we
>+        # set.  We allow a margin of 100% over as the Samba timeout
>+        # handling is not very accurate (and does not need to be)
>+        self.assertLess(timeout - 1, duration)
>+        self.assertLess(duration, timeout * 2)
> 
> 
> if "://" not in url:
>-- 
>2.25.1
>
>
>From 893c62d75ae9972669ce63c0fec9a8a8dfc5cf9b Mon Sep 17 00:00:00 2001
>From: Joseph Sutton <josephsutton@catalyst.net.nz>
>Date: Thu, 26 Aug 2021 13:53:23 +1200
>Subject: [PATCH 2/7] CVE-2021-3670 ldap_server: Set timeout on requests based
> on MaxQueryDuration
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Joseph Sutton <josephsutton@catalyst.net.nz>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>(cherry picked from commit 86fe9d48883f87c928bf31ccbd275db420386803)
>---
> source4/ldap_server/ldap_backend.c | 12 +++++++++++-
> 1 file changed, 11 insertions(+), 1 deletion(-)
>
>diff --git a/source4/ldap_server/ldap_backend.c b/source4/ldap_server/ldap_backend.c
>index e19f82cf5df..c7405f66643 100644
>--- a/source4/ldap_server/ldap_backend.c
>+++ b/source4/ldap_server/ldap_backend.c
>@@ -869,7 +869,17 @@ static NTSTATUS ldapsrv_SearchRequest(struct ldapsrv_call *call)
> 		}
> 	}
> 
>-	ldb_set_timeout(samdb, lreq, req->timelimit);
>+	{
>+		time_t timeout = call->conn->limits.search_timeout;
>+
>+		if (timeout == 0
>+		    || (req->timelimit != 0
>+			&& req->timelimit < timeout))
>+		{
>+			timeout = req->timelimit;
>+		}
>+		ldb_set_timeout(samdb, lreq, timeout);
>+	}
> 
> 	if (!call->conn->is_privileged) {
> 		ldb_req_mark_untrusted(lreq);
>-- 
>2.25.1
>
>
>From dddabd8ed885a4dccaaa1d08025d63434f69b468 Mon Sep 17 00:00:00 2001
>From: Joseph Sutton <josephsutton@catalyst.net.nz>
>Date: Tue, 28 Sep 2021 17:20:43 +1300
>Subject: [PATCH 3/7] CVE-2021-3670 ldap_server: Ensure value of
> MaxQueryDuration is greater than zero
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Joseph Sutton <josephsutton@catalyst.net.nz>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>(cherry picked from commit e1ab0c43629686d1d2c0b0b2bcdc90057a792049)
>---
> source4/ldap_server/ldap_server.c | 4 +++-
> 1 file changed, 3 insertions(+), 1 deletion(-)
>
>diff --git a/source4/ldap_server/ldap_server.c b/source4/ldap_server/ldap_server.c
>index ce4fd4f41d6..fbea5859756 100644
>--- a/source4/ldap_server/ldap_server.c
>+++ b/source4/ldap_server/ldap_server.c
>@@ -255,7 +255,9 @@ static int ldapsrv_load_limits(struct ldapsrv_connection *conn)
> 			continue;
> 		}
> 		if (strcasecmp("MaxQueryDuration", policy_name) == 0) {
>-			conn->limits.search_timeout = policy_value;
>+			if (policy_value > 0) {
>+				conn->limits.search_timeout = policy_value;
>+			}
> 			continue;
> 		}
> 	}
>-- 
>2.25.1
>
>
>From 1edad2354369c9fb2dc3dc6d04800a7ecd1a9333 Mon Sep 17 00:00:00 2001
>From: Andrew Bartlett <abartlet@samba.org>
>Date: Mon, 27 Sep 2021 16:47:46 +1300
>Subject: [PATCH 4/7] CVE-2021-3670 ldb: Confirm the request has not yet timed
> out in ldb filter processing
>
>The LDB filter processing is where the time is spent in the LDB stack
>but the timeout event will not get run while this is ongoing, so we
>must confirm we have not yet timed out manually.
>
>RN: Ensure that the LDB request has not timed out during filter processing
>as the LDAP server MaxQueryDuration is otherwise not honoured.
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Andrew Bartlett <abartlet@samba.org>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>(cherry picked from commit 1d5b155619bc532c46932965b215bd73a920e56f)
>---
> lib/ldb/ldb_key_value/ldb_kv.c        |  2 ++
> lib/ldb/ldb_key_value/ldb_kv.h        | 10 +++++++
> lib/ldb/ldb_key_value/ldb_kv_index.c  | 41 +++++++++++++++++++++++++++
> lib/ldb/ldb_key_value/ldb_kv_search.c | 33 ++++++++++++++++++++-
> selftest/knownfail.d/ldap-timeout     |  1 -
> 5 files changed, 85 insertions(+), 2 deletions(-)
> delete mode 100644 selftest/knownfail.d/ldap-timeout
>
>diff --git a/lib/ldb/ldb_key_value/ldb_kv.c b/lib/ldb/ldb_key_value/ldb_kv.c
>index ed0f760b5a2..aea6f0c1be0 100644
>--- a/lib/ldb/ldb_key_value/ldb_kv.c
>+++ b/lib/ldb/ldb_key_value/ldb_kv.c
>@@ -2078,6 +2078,8 @@ static int ldb_kv_handle_request(struct ldb_module *module,
> 		}
> 	}
> 
>+	ac->timeout_timeval = tv;
>+
> 	/* set a spy so that we do not try to use the request context
> 	 * if it is freed before ltdb_callback fires */
> 	ac->spy = talloc(req, struct ldb_kv_req_spy);
>diff --git a/lib/ldb/ldb_key_value/ldb_kv.h b/lib/ldb/ldb_key_value/ldb_kv.h
>index f9dffae2dcf..ac474b04b4c 100644
>--- a/lib/ldb/ldb_key_value/ldb_kv.h
>+++ b/lib/ldb/ldb_key_value/ldb_kv.h
>@@ -152,6 +152,16 @@ struct ldb_kv_context {
> 	struct ldb_module *module;
> 	struct ldb_request *req;
> 
>+	/*
>+	 * Required as we might not get to the event loop before the
>+	 * timeout, so we need some old-style cooperative multitasking
>+	 * here.
>+	 */
>+	struct timeval timeout_timeval;
>+
>+	/* Used to throttle calls to gettimeofday() */
>+	size_t timeout_counter;
>+
> 	bool request_terminated;
> 	struct ldb_kv_req_spy *spy;
> 
>diff --git a/lib/ldb/ldb_key_value/ldb_kv_index.c b/lib/ldb/ldb_key_value/ldb_kv_index.c
>index 1cc042aa84f..d70e5f619ef 100644
>--- a/lib/ldb/ldb_key_value/ldb_kv_index.c
>+++ b/lib/ldb/ldb_key_value/ldb_kv_index.c
>@@ -2352,6 +2352,47 @@ static int ldb_kv_index_filter(struct ldb_kv_private *ldb_kv,
> 	for (i = 0; i < num_keys; i++) {
> 		int ret;
> 		bool matched;
>+
>+		/*
>+		 * Check the time every 64 records, to reduce calls to
>+		 * gettimeofday().  This is a compromise, not all
>+		 * calls to ldb_match_message() will take the same
>+		 * time, most will run quickly but by luck it might be
>+		 * possible to have 64 records that are slow, doing a
>+		 * recursive search via LDAP_MATCHING_RULE_IN_CHAIN.
>+		 *
>+		 * Thankfully this is after index processing so only
>+		 * on the subset that matches some index (but still
>+		 * possibly a big one like objectclass=user)
>+		 */
>+		if (i % 64 == 0) {
>+			struct timeval now = tevent_timeval_current();
>+			int timeval_cmp = tevent_timeval_compare(&ac->timeout_timeval,
>+								 &now);
>+
>+			/*
>+			 * The search has taken too long.  This is the
>+			 * most likely place for our time to expire,
>+			 * as we are checking the records after the
>+			 * index set intersection.  This is now the
>+			 * slow process of checking if the records
>+			 * actually match.
>+			 *
>+			 * The tevent based timeout is not likely to
>+			 * be hit, sadly, as we don't run an event
>+			 * loop.
>+			 *
>+			 * While we are indexed and most of the work
>+			 * should have been done already, the
>+			 * ldb_match_* calls can be quite expensive if
>+			 * the caller uses LDAP_MATCHING_RULE_IN_CHAIN
>+			 */
>+			if (timeval_cmp <= 0) {
>+				talloc_free(keys);
>+				return LDB_ERR_TIME_LIMIT_EXCEEDED;
>+			}
>+		}
>+
> 		msg = ldb_msg_new(ac);
> 		if (!msg) {
> 			talloc_free(keys);
>diff --git a/lib/ldb/ldb_key_value/ldb_kv_search.c b/lib/ldb/ldb_key_value/ldb_kv_search.c
>index a0e1762bc90..46031b99c16 100644
>--- a/lib/ldb/ldb_key_value/ldb_kv_search.c
>+++ b/lib/ldb/ldb_key_value/ldb_kv_search.c
>@@ -314,7 +314,8 @@ static int search_func(_UNUSED_ struct ldb_kv_private *ldb_kv,
> 	struct ldb_context *ldb;
> 	struct ldb_kv_context *ac;
> 	struct ldb_message *msg, *filtered_msg;
>-	int ret;
>+	struct timeval now;
>+	int ret, timeval_cmp;
> 	bool matched;
> 
> 	ac = talloc_get_type(state, struct ldb_kv_context);
>@@ -341,6 +342,36 @@ static int search_func(_UNUSED_ struct ldb_kv_private *ldb_kv,
> 		return 0;
> 	}
> 
>+	/*
>+	 * Check the time every 64 records, to reduce calls to
>+	 * gettimeofday().  This is a compromise, not all calls to
>+	 * ldb_match_message() will take the same time, most will fail
>+	 * quickly but by luck it might be possible to have 64 records
>+	 * that are slow, doing a recursive search via
>+	 * LDAP_MATCHING_RULE_IN_CHAIN.
>+	 */
>+	if (ac->timeout_counter++ % 64 == 0) {
>+		now = tevent_timeval_current();
>+		timeval_cmp = tevent_timeval_compare(&ac->timeout_timeval,
>+						     &now);
>+
>+		/*
>+		 * The search has taken too long.  This is the most
>+		 * likely place for our time to expire, as we are in
>+		 * an un-indexed search and we return the data from
>+		 * within this loop.  The tevent based timeout is not
>+		 * likely to be hit, sadly.
>+		 *
>+		 * ldb_match_msg_error() can be quite expensive if a
>+		 * LDAP_MATCHING_RULE_IN_CHAIN extended match was
>+		 * specified.
>+		 */
>+		if (timeval_cmp <= 0) {
>+			ac->error = LDB_ERR_TIME_LIMIT_EXCEEDED;
>+			return -1;
>+		}
>+	}
>+
> 	msg = ldb_msg_new(ac);
> 	if (!msg) {
> 		ac->error = LDB_ERR_OPERATIONS_ERROR;
>diff --git a/selftest/knownfail.d/ldap-timeout b/selftest/knownfail.d/ldap-timeout
>deleted file mode 100644
>index 378ca1f4821..00000000000
>--- a/selftest/knownfail.d/ldap-timeout
>+++ /dev/null
>@@ -1 +0,0 @@
>-samba4.ldap.large_ldap\..*\.python\(.*\).__main__.LargeLDAPTest.test_timeout\(.*\)
>\ No newline at end of file
>-- 
>2.25.1
>
>
>From 49c883f67be35275832a0dde5e289a3e54dd913e Mon Sep 17 00:00:00 2001
>From: Andrew Bartlett <abartlet@samba.org>
>Date: Thu, 18 Nov 2021 15:27:08 +1300
>Subject: [PATCH 5/7] CVE-2021-3670 ldap_server: Remove duplicate print of LDAP
> search details
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Andrew Bartlett <abartlet@samba.org>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>(cherry picked from commit 2b3af3b560c9617a233c131376c870fce146c002)
>---
> source4/ldap_server/ldap_backend.c | 3 ---
> 1 file changed, 3 deletions(-)
>
>diff --git a/source4/ldap_server/ldap_backend.c b/source4/ldap_server/ldap_backend.c
>index c7405f66643..78d0de951c5 100644
>--- a/source4/ldap_server/ldap_backend.c
>+++ b/source4/ldap_server/ldap_backend.c
>@@ -729,9 +729,6 @@ static NTSTATUS ldapsrv_SearchRequest(struct ldapsrv_call *call)
> 	unsigned int i;
> 	int extended_type = 1;
> 
>-	DEBUG(10, ("SearchRequest"));
>-	DEBUGADD(10, (" basedn: %s", req->basedn));
>-	DEBUGADD(10, (" filter: %s\n", ldb_filter_from_tree(call, req->tree)));
> 
> 	local_ctx = talloc_new(call);
> 	NT_STATUS_HAVE_NO_MEMORY(local_ctx);
>-- 
>2.25.1
>
>
>From 55ae98191e902744628db9d6b90cf83aa0068d0e Mon Sep 17 00:00:00 2001
>From: Andrew Bartlett <abartlet@samba.org>
>Date: Thu, 18 Nov 2021 15:57:34 +1300
>Subject: [PATCH 6/7] CVE-2021-3670 dsdb/anr: Do a copy of the potentially anr
> query before starting to modify it
>
>RN: Do not modify the caller-supplied memory in the anr=* handling to
>allow clear logging of the actual caller request after it has been processed.
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Andrew Bartlett <abartlet@samba.org>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>(cherry picked from commit 5f0590362c5c0c5ee20503a67467f9be2d50e73b)
>---
> source4/dsdb/samdb/ldb_modules/anr.c | 73 +++++++++++++++++++++++++---
> 1 file changed, 65 insertions(+), 8 deletions(-)
>
>diff --git a/source4/dsdb/samdb/ldb_modules/anr.c b/source4/dsdb/samdb/ldb_modules/anr.c
>index 660ba271496..e083f5db17d 100644
>--- a/source4/dsdb/samdb/ldb_modules/anr.c
>+++ b/source4/dsdb/samdb/ldb_modules/anr.c
>@@ -148,8 +148,6 @@ static int anr_replace_value(struct anr_context *ac,
> 		return LDB_ERR_OPERATIONS_ERROR;
> 	}
> 
>-	ac->found_anr = true;
>-
> 	if (match->length > 1 && match->data[0] == '=') {
> 		struct ldb_val *match2 = talloc(mem_ctx, struct ldb_val);
> 		if (match2 == NULL){
>@@ -285,6 +283,49 @@ static int anr_replace_subtrees(struct anr_context *ac,
> 	return LDB_SUCCESS;
> }
> 
>+struct anr_present_ctx {
>+	bool found_anr;
>+	const char *attr;
>+};
>+
>+/*
>+  callback to determine if ANR is in use at all
>+ */
>+static int parse_tree_anr_present(struct ldb_parse_tree *tree, void *private_context)
>+{
>+	struct anr_present_ctx *ctx = private_context;
>+	switch (tree->operation) {
>+	case LDB_OP_EQUALITY:
>+	case LDB_OP_GREATER:
>+	case LDB_OP_LESS:
>+	case LDB_OP_APPROX:
>+		if (ldb_attr_cmp(tree->u.equality.attr, ctx->attr) == 0) {
>+			ctx->found_anr = true;
>+		}
>+		break;
>+	case LDB_OP_SUBSTRING:
>+		if (ldb_attr_cmp(tree->u.substring.attr, ctx->attr) == 0) {
>+			ctx->found_anr = true;
>+		}
>+		break;
>+	case LDB_OP_PRESENT:
>+		if (ldb_attr_cmp(tree->u.present.attr, ctx->attr) == 0) {
>+			ctx->found_anr = true;
>+		}
>+		break;
>+	case LDB_OP_EXTENDED:
>+		if (tree->u.extended.attr &&
>+		    ldb_attr_cmp(tree->u.extended.attr, ctx->attr) == 0) {
>+			ctx->found_anr = true;
>+		}
>+		break;
>+	default:
>+		break;
>+	}
>+	return LDB_SUCCESS;
>+}
>+
>+
> static int anr_search_callback(struct ldb_request *req, struct ldb_reply *ares)
> {
> 	struct anr_context *ac;
>@@ -322,8 +363,21 @@ static int anr_search(struct ldb_module *module, struct ldb_request *req)
> 	struct ldb_parse_tree *anr_tree;
> 	struct ldb_request *down_req;
> 	struct anr_context *ac;
>+	struct anr_present_ctx ctx;
>+	const char *attr = "anr";
> 	int ret;
> 
>+	ctx.found_anr = false;
>+	ctx.attr = attr;
>+
>+	ldb_parse_tree_walk(req->op.search.tree,
>+			    parse_tree_anr_present,
>+			    &ctx);
>+
>+	if (!ctx.found_anr) {
>+		return ldb_next_request(module, req);
>+	}
>+
> 	ldb = ldb_module_get_ctx(module);
> 
> 	ac = talloc(req, struct anr_context);
>@@ -333,20 +387,23 @@ static int anr_search(struct ldb_module *module, struct ldb_request *req)
> 
> 	ac->module = module;
> 	ac->req = req;
>-	ac->found_anr = false;
> 
> #if 0
> 	printf("oldanr : %s\n", ldb_filter_from_tree (0, req->op.search.tree));
> #endif
> 
>-	ret = anr_replace_subtrees(ac, req->op.search.tree, "anr", &anr_tree);
>-	if (ret != LDB_SUCCESS) {
>+	/* First make a copy, so we don't overwrite caller memory */
>+
>+	anr_tree = ldb_parse_tree_copy_shallow(ac, req->op.search.tree);
>+
>+	if (anr_tree == NULL) {
> 		return ldb_operr(ldb);
> 	}
> 
>-	if (!ac->found_anr) {
>-		talloc_free(ac);
>-		return ldb_next_request(module, req);
>+	/* Now expand 'anr' out */
>+	ret = anr_replace_subtrees(ac, anr_tree, attr, &anr_tree);
>+	if (ret != LDB_SUCCESS) {
>+		return ldb_operr(ldb);
> 	}
> 
> 	ret = ldb_build_search_req_ex(&down_req,
>-- 
>2.25.1
>
>
>From b024e73fdeec1ce3c495e866c04b793d2e5c5f82 Mon Sep 17 00:00:00 2001
>From: Andrew Bartlett <abartlet@samba.org>
>Date: Thu, 18 Nov 2021 16:09:47 +1300
>Subject: [PATCH 7/7] CVE-2021-3670 ldap_server: Clearly log LDAP queries and
> timeouts
>
>This puts all the detail on one line so it can be searched
>by IP address and connecting SID.
>
>This relies on the anr handling as otherwise this log
>becomes the expanded query, not the original one.
>
>RN: Provide clear logs of the LDAP search and who made it, including
>a warning (at log level 3) for queries that are 1/4 of the hard timeout.
>
>BUG: https://bugzilla.samba.org/show_bug.cgi?id=14694
>
>Signed-off-by: Andrew Bartlett <abartlet@samba.org>
>Reviewed-by: Douglas Bagnall <douglas.bagnall@catalyst.net.nz>
>
>Autobuild-User(master): Douglas Bagnall <dbagnall@samba.org>
>Autobuild-Date(master): Thu Nov 25 02:30:42 UTC 2021 on sn-devel-184
>
>(cherry picked from commit 3507e96b3dcf0c0b8eff7b2c08ffccaf0812a393)
>---
> source4/ldap_server/ldap_backend.c | 121 +++++++++++++++++++++++------
> 1 file changed, 99 insertions(+), 22 deletions(-)
>
>diff --git a/source4/ldap_server/ldap_backend.c b/source4/ldap_server/ldap_backend.c
>index 78d0de951c5..e37b87f62ee 100644
>--- a/source4/ldap_server/ldap_backend.c
>+++ b/source4/ldap_server/ldap_backend.c
>@@ -729,6 +729,15 @@ static NTSTATUS ldapsrv_SearchRequest(struct ldapsrv_call *call)
> 	unsigned int i;
> 	int extended_type = 1;
> 
>+	/*
>+	 * Warn for searches that are longer than 1/4 of the
>+	 * search_timeout, being 30sec by default
>+	 */
>+	struct timeval start_time = timeval_current();
>+	struct timeval warning_time
>+		= timeval_add(&start_time,
>+			      call->conn->limits.search_timeout / 4,
>+			      0);
> 
> 	local_ctx = talloc_new(call);
> 	NT_STATUS_HAVE_NO_MEMORY(local_ctx);
>@@ -736,29 +745,27 @@ static NTSTATUS ldapsrv_SearchRequest(struct ldapsrv_call *call)
> 	basedn = ldb_dn_new(local_ctx, samdb, req->basedn);
> 	NT_STATUS_HAVE_NO_MEMORY(basedn);
> 
>-	DEBUG(10, ("SearchRequest: basedn: [%s]\n", req->basedn));
>-	DEBUG(10, ("SearchRequest: filter: [%s]\n", ldb_filter_from_tree(call, req->tree)));
>-
> 	switch (req->scope) {
>-		case LDAP_SEARCH_SCOPE_BASE:
>-			scope_str = "BASE";
>-			scope = LDB_SCOPE_BASE;
>-			break;
>-		case LDAP_SEARCH_SCOPE_SINGLE:
>-			scope_str = "ONE";
>-			scope = LDB_SCOPE_ONELEVEL;
>-			break;
>-		case LDAP_SEARCH_SCOPE_SUB:
>-			scope_str = "SUB";
>-			scope = LDB_SCOPE_SUBTREE;
>-			break;
>-	        default:
>-			result = LDAP_PROTOCOL_ERROR;
>-			map_ldb_error(local_ctx, LDB_ERR_PROTOCOL_ERROR, NULL,
>-				&errstr);
>-			errstr = talloc_asprintf(local_ctx,
>-				"%s. Invalid scope", errstr);
>-			goto reply;
>+	case LDAP_SEARCH_SCOPE_BASE:
>+		scope_str = "BASE";
>+		scope = LDB_SCOPE_BASE;
>+		break;
>+	case LDAP_SEARCH_SCOPE_SINGLE:
>+		scope_str = "ONE";
>+		scope = LDB_SCOPE_ONELEVEL;
>+		break;
>+	case LDAP_SEARCH_SCOPE_SUB:
>+		scope_str = "SUB";
>+		scope = LDB_SCOPE_SUBTREE;
>+		break;
>+	default:
>+		result = LDAP_PROTOCOL_ERROR;
>+		map_ldb_error(local_ctx, LDB_ERR_PROTOCOL_ERROR, NULL,
>+			      &errstr);
>+		scope_str = "<Invalid scope>";
>+		errstr = talloc_asprintf(local_ctx,
>+					 "%s. Invalid scope", errstr);
>+		goto reply;
> 	}
> 	DEBUG(10,("SearchRequest: scope: [%s]\n", scope_str));
> 
>@@ -911,6 +918,76 @@ static NTSTATUS ldapsrv_SearchRequest(struct ldapsrv_call *call)
> 	}
> 
> reply:
>+
>+	/*
>+	 * This looks like duplicated code - because it is - but
>+	 * otherwise the work in the parameters will be done
>+	 * regardless, this way the functions only execuate when the
>+	 * log level is set.
>+	 *
>+	 * The basedn is re-obtained as a string to escape it
>+	 */
>+	if ((req->timelimit == 0 || call->conn->limits.search_timeout < req->timelimit)
>+	    && ldb_ret == LDB_ERR_TIME_LIMIT_EXCEEDED) {
>+		struct dom_sid_buf sid_buf;
>+		DBG_WARNING("MaxQueryDuration(%d) timeout exceeded "
>+			    "in SearchRequest by %s from %s filter: [%s] "
>+			    "basedn: [%s] "
>+			    "scope: [%s]\n",
>+			    call->conn->limits.search_timeout,
>+			    dom_sid_str_buf(&call->conn->session_info->security_token->sids[0],
>+					    &sid_buf),
>+			    tsocket_address_string(call->conn->connection->remote_address,
>+						   call),
>+			    ldb_filter_from_tree(call, req->tree),
>+			    ldb_dn_get_extended_linearized(call, basedn, 1),
>+			    scope_str);
>+		for (i=0; i < req->num_attributes; i++) {
>+			DBG_WARNING("MaxQueryDuration timeout exceeded attrs: [%s]\n",
>+				    req->attributes[i]);
>+		}
>+
>+	} else if (timeval_expired(&warning_time)) {
>+		struct dom_sid_buf sid_buf;
>+		DBG_NOTICE("Long LDAP Query: Duration was %.2fs, "
>+			   "MaxQueryDuration(%d)/4 == %d "
>+			   "in SearchRequest by %s from %s filter: [%s] "
>+			   "basedn: [%s] "
>+			   "scope: [%s] "
>+			   "result: %s\n",
>+			   timeval_elapsed(&start_time),
>+			   call->conn->limits.search_timeout,
>+			   call->conn->limits.search_timeout / 4,
>+			   dom_sid_str_buf(&call->conn->session_info->security_token->sids[0],
>+					   &sid_buf),
>+			   tsocket_address_string(call->conn->connection->remote_address,
>+						  call),
>+			   ldb_filter_from_tree(call, req->tree),
>+			   ldb_dn_get_extended_linearized(call, basedn, 1),
>+			   scope_str,
>+			   ldb_strerror(ldb_ret));
>+		for (i=0; i < req->num_attributes; i++) {
>+			DBG_NOTICE("Long LDAP Query attrs: [%s]\n",
>+				   req->attributes[i]);
>+		}
>+	} else {
>+		struct dom_sid_buf sid_buf;
>+		DBG_INFO("LDAP Query: Duration was %.2fs, "
>+			 "SearchRequest by %s from %s filter: [%s] "
>+			 "basedn: [%s] "
>+			 "scope: [%s] "
>+			 "result: %s\n",
>+			 timeval_elapsed(&start_time),
>+			 dom_sid_str_buf(&call->conn->session_info->security_token->sids[0],
>+					 &sid_buf),
>+			 tsocket_address_string(call->conn->connection->remote_address,
>+						call),
>+			 ldb_filter_from_tree(call, req->tree),
>+			 ldb_dn_get_extended_linearized(call, basedn, 1),
>+			 scope_str,
>+			 ldb_strerror(ldb_ret));
>+	}
>+
> 	DLIST_REMOVE(call->conn->pending_calls, call);
> 	call->notification.busy = false;
> 
>-- 
>2.25.1
>

Flags:

abartlet: review+

Actions: View

Attachments on bug 14694: 17032 | 17034 | 17038 | 17430