From af92c3ae6de14138150b7e12e54fe02d1c8c1e00 Mon Sep 17 00:00:00 2001 From: Joseph Sutton 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 Reviewed-by: Douglas Bagnall (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 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 Reviewed-by: Douglas Bagnall (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 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 Reviewed-by: Douglas Bagnall (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 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 Reviewed-by: Douglas Bagnall (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 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 Reviewed-by: Douglas Bagnall (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 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 Reviewed-by: Douglas Bagnall (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 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 Reviewed-by: Douglas Bagnall Autobuild-User(master): Douglas Bagnall 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 = ""; + 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