#51166 Log internal unindexed searches (notes=A)
Closed: wontfix 3 years ago by mreynolds. Opened 3 years ago by mreynolds.

Issue Description

At some point in time we stopped logging internal unindexed searches in the errors log because they were noisy and often false positives, but we have since made it more fine grained with notes=A. For a notes=A case we should log the search details in the errors log. This will help determine the root cause of some of the db lock exhaustion cases we are seeing.


Metadata Update from @mreynolds:
- Issue assigned to mreynolds

3 years ago

Metadata Update from @mreynolds:
- Custom field origin adjusted to None
- Custom field reviewstatus adjusted to None
- Issue priority set to: normal
- Issue set to the milestone: 1.4.2

3 years ago

Commit 16e47bf relates to this ticket

Commit 16e47bf relates to this ticket

c7d81c2..9e1a88c 389-ds-base-1.4.3 -> 389-ds-base-1.4.3

a53c73b..3fdb2ed 389-ds-base-1.4.2 -> 389-ds-base-1.4.2

7cc0f1d..49cbd94 389-ds-base-1.3.10 -> 389-ds-base-1.3.10

Metadata Update from @mreynolds:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

3 years ago

Hi Mark,

I have built a patch on top of 1.3.10.1-5 using https://pagure.io/389-ds-base/c/49cbd94a0

After configuring the RHDS instance to trigger a full DB scan upon a deletion of an entry,
the DEL command does actually kill the server:

# ldapdelete -x -D "cn=Directory Manager" -w<PASSWORD> -h <HOST> -p <PORT> "uid=test2,ou=People,dc=example,dc=com"
ldap_result: Can't contact LDAP server (-1)
#

Running the instance under gdb gives a hint about the issue:

# gdb /usr/sbin/ns-slapd
...
(gdb) set args  -D /etc/dirsrv/slapd-test -i /var/run/dirsrv/slapd-test.pid -w /var/run/dirsrv/slapd-test.startpid -d 0
(gdb) run
Starting program: /usr/sbin/ns-slapd -D /etc/dirsrv/slapd-test -i /var/run/dirsrv/slapd-test.pid -w /var/run/dirsrv/slapd-test.startpid -d 0
...
[New Thread 0x7fffbbe29700 (LWP 31223)]
/usr/sbin/ns-slapd: symbol lookup error: /usr/lib64/dirsrv/plugins/libback-ldbm.so: undefined symbol: get_internal_conn_op
[Thread 0x7fffbbe29700 (LWP 31223) exited]
...
#

The function get_internal_conn_op() is used in the patch but its definition is missing.

It is defined in the 1.4 branch in the file ldap/servers/slapd/util.c

void
get_internal_conn_op (uint64_t *connid, int32_t *op_id, int32_t *op_internal_id, int32_t *op_nested_count) {
    struct slapi_td_log_op_state_t *op_state = slapi_td_get_log_op_state();

    if (op_state != NULL) {
        *connid = op_state->conn_id;
        *op_id = op_state->op_id;
        *op_internal_id = op_state->op_int_id;
        *op_nested_count = op_state->op_nest_count;

    } else {
        *connid = 0;
        *op_id = 0;
        *op_internal_id = 0;
        *op_nested_count = 0;
    }
}

The 1.3.10 branch doesn't seem to have the function definition:

$ find 389-ds-base-1.3.10/ -name *.c | xargs grep get_internal_conn_op
389-ds-base-1.3.10//389-ds-base/ldap/servers/slapd/back-ldbm/ldbm_search.c:            get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count);
$

Would you mind to add the missing part to the patch?

Regards,
Têko.

@tmihinto this missing part comes from https://pagure.io/389-ds-base/issue/49029. It allows to retrieve which client operation (op/conn) triggered the internal operation. #49029 was fixed in several commits that makes the backport a bit more complex.
For a hotfix, an option is to just log the unindexed internal search without the reference to the client operation. The goal is to know which attributes need to be indexed and a simple log will give the information. Knowing which client operation triggered it, is interesting but not crucial for reindexing.

Thanks Thierry!

I would prefer if Engineering can fix the patch so that when CEE folks need to build a hotfix, they don't hit the same issue ;-)

Meanwhile could you please confirm that the following code changes should be enough?

get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count);

            slapi_log_err(SLAPI_LOG_NOTICE, "ldbm_back_search",
                     "Internal unindexed search: source (%s) search base=\"%s\" scope=%d filter=\"%s\",
                     plugin_dn, base_dn, scope, filter_str);
             slapi_ch_free_string(&plugin_dn);

Regards,
Têko.

@mreynolds
Hi Mark,

Please let me know when the new patch is ready.

Thanks,
Têko.

@mreynolds
Hi Mark,
Please let me know when the new patch is ready.
Thanks,
Têko.

Try this one:

diff --git a/ldap/servers/slapd/back-ldbm/ldbm_search.c b/ldap/servers/slapd/back-ldbm/ldbm_search.c
index 212b6cb61..81eef3ac9 100644
--- a/ldap/servers/slapd/back-ldbm/ldbm_search.c
+++ b/ldap/servers/slapd/back-ldbm/ldbm_search.c
@@ -831,10 +831,6 @@ ldbm_back_search(Slapi_PBlock *pb)
         char *plugin_dn;
         char *base_dn;
         int32_t internal_op = operation_is_flag_set(operation, OP_FLAG_INTERNAL);
-        uint64_t connid;
-        int32_t op_id;
-        int32_t op_internal_id;
-        int32_t op_nested_count;

         /*
          * Return error if nsslapd-require-index is set and
@@ -873,10 +869,9 @@ ldbm_back_search(Slapi_PBlock *pb)
                 slapi_pblock_get(pb, SLAPI_PLUGIN, &plugin);
             }
             plugin_dn = plugin_get_dn(plugin);
-            get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count);
             slapi_log_err(SLAPI_LOG_NOTICE, "ldbm_back_search",
-                    "Internal unindexed search: source (%s) search base=\"%s\" scope=%d filter=\"%s\" conn=%" PRIu64 " op=%d (internal op=%d count=%d)\n",
-                    plugin_dn, base_dn, scope, filter_str, connid, op_id, op_internal_id, op_nested_count);
+                    "Internal unindexed search: source (%s) search base=\"%s\" scope=%d filter=\"%s\" conn=%" PRIu64 " op=%d\n",
+                    plugin_dn, base_dn, scope, filter_str, pb_op->o_connid, pb_op->o_opid);
             slapi_ch_free_string(&plugin_dn);
         } else {
             slapi_log_err(SLAPI_LOG_NOTICE, "ldbm_back_search",

@mreynolds
Thank you Mark!
It works now. Just had to figure out that it was cumulative with the previous version ;-)

[03/Jul/2020:19:17:07.121844143 +0200] - NOTICE - ldbm_back_search - Internal unindexed search: source (cn=referential integrity postoperation,cn=plugins,cn=config) search base="dc=example,dc=com" scope=2 filter="(description=uid=test2,ou=People,dc=example,dc=com)" conn=0 op=0

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/4219

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: fixed)

3 years ago

Login to comment on this ticket.

Metadata
Related Pull Requests