#51167 Issue 51166 - Log an error when an internal search is fully unindexed
Closed 3 years ago by spichugi. Opened 3 years ago by mreynolds.
mreynolds/389-ds-base issue51166  into  master

@@ -837,13 +837,23 @@ 

          int pr_idx = -1;

          Connection *pb_conn = NULL;

          Operation *pb_op = NULL;

+         struct slapdplugin *plugin = NULL;

+         struct slapi_componentid *cid = NULL;

+         char *filter_str;

+         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

           * this is not an internal operation.

           * We hope the plugins know what they are doing!

           */

-         if (!operation_is_flag_set(operation, OP_FLAG_INTERNAL)) {

+         if (!internal_op) {

  

              PR_Lock(inst->inst_config_mutex);

              ri = inst->require_index;
@@ -856,13 +866,41 @@ 

                  tmp_desc = "Search is not indexed";

              }

          }

+         /*

+          * When an search is fully unindexed we need to log the

+          * details as these kinds of searches can cause issues with bdb db

+          * locks being exhausted.  This will help expose what indexing is

+          * missing.

+          */

+         slapi_pblock_get(pb, SLAPI_OPERATION, &pb_op);

+         slapi_pblock_get(pb, SLAPI_SEARCH_STRFILTER, &filter_str);

+         slapi_pblock_get(pb, SLAPI_TARGET_DN, &base_dn);

+ 

+         if (internal_op) {

+             /* Get the plugin that triggered this internal search */

+             slapi_pblock_get(pb, SLAPI_PLUGIN_IDENTITY, &cid);

+             if (cid) {

+                 plugin = (struct slapdplugin *)cid->sci_plugin;

+             } else {

+                 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);

+             slapi_ch_free_string(&plugin_dn);

+         } else {

+             slapi_log_err(SLAPI_LOG_NOTICE, "ldbm_back_search",

+                     "Unindexed search: search base=\"%s\" scope=%d filter=\"%s\" conn=%" PRIu64 " op=%d\n",

+                     base_dn, scope, filter_str, pb_op->o_connid, pb_op->o_opid);

+         }

  

          opnote = slapi_pblock_get_operation_notes(pb);

          opnote |= SLAPI_OP_NOTE_FULL_UNINDEXED; /* the full filter leads to an unindexed search */

          opnote &= ~SLAPI_OP_NOTE_UNINDEXED;     /* this note is useless because FULL_UNINDEXED includes UNINDEXED */

          slapi_pblock_set_operation_notes(pb, opnote);

          slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx);

-         slapi_pblock_get(pb, SLAPI_OPERATION, &pb_op);

          slapi_pblock_get(pb, SLAPI_CONNECTION, &pb_conn);

          pagedresults_set_unindexed(pb_conn, pb_op, pr_idx);

      }

Bug Description:

Some plugins can trigger very expensive internal searches that can exhaust the bdb db_locks. It is very difficult to track these down.

Fix description:

Log a message to the errors log when an internal search is fully unindexed and provide the search details. This will allow an admin to identify and fix indexing issues.

relates: https://pagure.io/389-ds-base/issue/51166

Ack from me as well. I had a doubt if we need to only log internal search that are done under txn. Finally I think it is a good idea to log all of them.

Ack from me as well. I had a doubt if we need to only log internal search that are done under txn. Finally I think it is a good idea to log all of them.

Well non-internal operations are logged in the access log. So the information is retrievable, but it's not nicely gathered into a single log line. Yeah I think it makes sense, I'm just worried it might overload the errors log with these messages. But let's add it and see who complains :-) I'll revise the patch...

Here is what the logging looks like now for unindexed and internal unindexed:

[19/Jun/2020:16:19:10.914405524 -0400] - NOTICE - ldbm_back_search - Unindexed search: search base="dc=example,dc=com" scope=2 filter="(member=uid=user0069,ou=product development,dc=example,dc=com)" conn=1 op=1

[19/Jun/2020:16:19:42.469911436 -0400] - 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="(member=uid=user0068,ou=product development,dc=example,dc=com)" conn=3 op=1 (internal op=1 count=1)

rebased onto d90b03685173c65690e4c3f9365a219f737f3185

3 years ago

Forgot to say, please review this revision :-)

Sorry about the delay, the update looks good to me, ack. Thanks!

rebased onto 16e47bf

3 years ago

Pull-Request has been merged by mreynolds

3 years ago

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 pull request has been cloned to Github as issue and is available here:
- https://github.com/389ds/389-ds-base/issues/4220

If you want to continue to work on the PR, please navigate to the github issue,
download the patch from the attachments and file a new pull request.

Thank you for understanding. We apologize for all inconvenience.

Pull-Request has been closed by spichugi

3 years ago
Metadata