From 8b89bf22dea16956e4a21174f28ec11f32fc2db4 Mon Sep 17 00:00:00 2001

From: tbordaz <tbordaz@redhat.com>

Date: Mon, 21 Nov 2022 11:41:15 +0100

Subject: [PATCH 1/3] Issue 3729 - (cont) RFE Extend log of operations

 statistics in access log (#5538)

Bug description:

	This is a continuation of the #3729

	The previous fix did not manage internal SRCH, so

	statistics of internal SRCH were not logged

Fix description:

	For internal operation log_op_stat uses

	connid/op_id/op_internal_id/op_nested_count that have been

	computed log_result

	For direct operation log_op_stat uses info from the

	operation itself (o_connid and o_opid)

	log_op_stat relies on operation_type rather than

	o_tag that is not available for internal operation

relates: #3729

Reviewed by: Pierre Rogier

---

 .../tests/suites/ds_logs/ds_logs_test.py      | 90 ++++++++++++++++++-

 ldap/servers/slapd/proto-slap.h               |  2 +-

 ldap/servers/slapd/result.c                   | 74 +++++++++------

 3 files changed, 136 insertions(+), 30 deletions(-)

diff --git a/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py b/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py

index 865a6d0a3..67605438b 100644

--- a/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py

+++ b/dirsrvtests/tests/suites/ds_logs/ds_logs_test.py

@@ -13,7 +13,7 @@ import pytest

 import subprocess

 from lib389._mapped_object import DSLdapObject

 from lib389.topologies import topology_st

-from lib389.plugins import AutoMembershipPlugin, ReferentialIntegrityPlugin, AutoMembershipDefinitions

+from lib389.plugins import AutoMembershipPlugin, ReferentialIntegrityPlugin, AutoMembershipDefinitions, MemberOfPlugin

 from lib389.idm.user import UserAccounts

 from lib389.idm.group import Groups

 from lib389.idm.organizationalunit import OrganizationalUnits

@@ -1254,6 +1254,94 @@ def test_stat_index(topology_st, request):

     request.addfinalizer(fin)

+def test_stat_internal_op(topology_st, request):

+    """Check that statistics can also be collected for internal operations

+

+    :id: 19f393bd-5866-425a-af7a-4dade06d5c77

+    :setup: Standalone Instance

+    :steps:

+        1. Check that nsslapd-statlog-level is 0 (default)

+        2. Enable memberof plugins

+        3. Create a user

+        4. Remove access log (to only detect new records)

+        5. Enable statistic logging nsslapd-statlog-level=1

+        6. Check that on direct SRCH there is no 'Internal' Stat records

+        7. Remove access log (to only detect new records)

+        8. Add group with the user, so memberof triggers internal search

+           and check it exists 'Internal' Stat records

+    :expectedresults:

+        1. Success

+        2. Success

+        3. Success

+        4. Success

+        5. Success

+        6. Success

+        7. Success

+        8. Success

+    """

+

+    inst = topology_st.standalone

+

+    # Step 1

+    log.info("Assert nsslapd-statlog-level is by default 0")

+    assert topology_st.standalone.config.get_attr_val_int("nsslapd-statlog-level") == 0

+

+    # Step 2

+    memberof = MemberOfPlugin(inst)

+    memberof.enable()

+    inst.restart()

+

+    # Step 3 Add setup entries

+    users = UserAccounts(inst, DEFAULT_SUFFIX, rdn=None)

+    user = users.create(properties={'uid': 'test_1',

+                                    'cn': 'test_1',

+                                    'sn': 'test_1',

+                                    'description': 'member',

+                                    'uidNumber': '1000',

+                                    'gidNumber': '2000',

+                                    'homeDirectory': '/home/testuser'})

+    # Step 4 reset accesslog

+    topology_st.standalone.stop()

+    lpath = topology_st.standalone.ds_access_log._get_log_path()

+    os.unlink(lpath)

+    topology_st.standalone.start()

+

+    # Step 5 enable statistics

+    log.info("Set nsslapd-statlog-level: 1 to enable indexing statistics")

+    topology_st.standalone.config.set("nsslapd-statlog-level", "1")

+

+    # Step 6 for direct SRCH only non internal STAT records

+    entries = topology_st.standalone.search_s(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, "uid=test_1")

+    topology_st.standalone.stop()

+    assert topology_st.standalone.ds_access_log.match('.*STAT read index.*')

+    assert topology_st.standalone.ds_access_log.match('.*STAT read index: attribute.*')

+    assert topology_st.standalone.ds_access_log.match('.*STAT read index: duration.*')

+    assert not topology_st.standalone.ds_access_log.match('.*Internal.*STAT.*')

+    topology_st.standalone.start()

+

+    # Step 7 reset accesslog

+    topology_st.standalone.stop()

+    lpath = topology_st.standalone.ds_access_log._get_log_path()

+    os.unlink(lpath)

+    topology_st.standalone.start()

+

+    # Step 8 trigger internal searches and check internal stat records

+    groups = Groups(inst, DEFAULT_SUFFIX, rdn=None)

+    group = groups.create(properties={'cn': 'mygroup',

+                                      'member': 'uid=test_1,%s' % DEFAULT_SUFFIX,

+                                      'description': 'group'})

+    topology_st.standalone.restart()

+    assert topology_st.standalone.ds_access_log.match('.*Internal.*STAT read index.*')

+    assert topology_st.standalone.ds_access_log.match('.*Internal.*STAT read index: attribute.*')

+    assert topology_st.standalone.ds_access_log.match('.*Internal.*STAT read index: duration.*')

+

+    def fin():

+        log.info('Deleting user/group')

+        user.delete()

+        group.delete()

+

+    request.addfinalizer(fin)

+

 if __name__ == '__main__':

     # Run isolated

     # -s for DEBUG mode

diff --git a/ldap/servers/slapd/proto-slap.h b/ldap/servers/slapd/proto-slap.h

index 77832797b..c63ad8e74 100644

--- a/ldap/servers/slapd/proto-slap.h

+++ b/ldap/servers/slapd/proto-slap.h

@@ -515,7 +515,7 @@ long long config_get_pw_minage(void);

 long long config_get_pw_warning(void);

 int config_get_errorlog_level(void);

 int config_get_accesslog_level(void);

-int config_get_statlog_level();

+int config_get_statlog_level(void);

 int config_get_securitylog_level(void);

 int config_get_auditlog_logging_enabled(void);

 int config_get_auditfaillog_logging_enabled(void);

diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c

index c8b363cce..2ba205e04 100644

--- a/ldap/servers/slapd/result.c

+++ b/ldap/servers/slapd/result.c

@@ -33,7 +33,7 @@ static long current_conn_count;

 static PRLock *current_conn_count_mutex;

 static int flush_ber(Slapi_PBlock *pb, Connection *conn, Operation *op, BerElement *ber, int type);

 static char *notes2str(unsigned int notes, char *buf, size_t buflen);

-static void log_op_stat(Slapi_PBlock *pb);

+static void log_op_stat(Slapi_PBlock *pb, uint64_t connid, int32_t op_id, int32_t op_internal_id, int32_t op_nested_count);

 static void log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries);

 static void log_entry(Operation *op, Slapi_Entry *e);

 static void log_referral(Operation *op);

@@ -2000,65 +2000,82 @@ notes2str(unsigned int notes, char *buf, size_t buflen)

     return (buf);

 }

+#define STAT_LOG_CONN_OP_FMT_INT_INT "conn=Internal(%" PRIu64 ") op=%d(%d)(%d)"

+#define STAT_LOG_CONN_OP_FMT_EXT_INT "conn=%" PRIu64 " (Internal) op=%d(%d)(%d)"

 static void

-log_op_stat(Slapi_PBlock *pb)

+log_op_stat(Slapi_PBlock *pb, uint64_t connid, int32_t op_id, int32_t op_internal_id, int32_t op_nested_count)

 {

-

-    Connection *conn = NULL;

     Operation *op = NULL;

     Op_stat *op_stat;

     struct timespec duration;

     char stat_etime[ETIME_BUFSIZ] = {0};

+    int internal_op;

     if (config_get_statlog_level() == 0) {

         return;

     }

-    slapi_pblock_get(pb, SLAPI_CONNECTION, &conn;;

     slapi_pblock_get(pb, SLAPI_OPERATION, &op);

+    internal_op = operation_is_flag_set(op, OP_FLAG_INTERNAL);

     op_stat = op_stat_get_operation_extension(pb);

-    if (conn == NULL || op == NULL || op_stat == NULL) {

+    if (op == NULL || op_stat == NULL) {

         return;

     }

     /* process the operation */

-    switch (op->o_tag) {

-        case LDAP_REQ_BIND:

-        case LDAP_REQ_UNBIND:

-        case LDAP_REQ_ADD:

-        case LDAP_REQ_DELETE:

-        case LDAP_REQ_MODRDN:

-        case LDAP_REQ_MODIFY:

-        case LDAP_REQ_COMPARE:

+    switch (operation_get_type(op)) {

+        case SLAPI_OPERATION_BIND:

+        case SLAPI_OPERATION_UNBIND:

+        case SLAPI_OPERATION_ADD:

+        case SLAPI_OPERATION_DELETE:

+        case SLAPI_OPERATION_MODRDN:

+        case SLAPI_OPERATION_MODIFY:

+        case SLAPI_OPERATION_COMPARE:

+        case SLAPI_OPERATION_EXTENDED:

             break;

-        case LDAP_REQ_SEARCH:

+        case SLAPI_OPERATION_SEARCH:

             if ((LDAP_STAT_READ_INDEX & config_get_statlog_level()) &&

                 op_stat->search_stat) {

                 struct component_keys_lookup *key_info;

                 for (key_info = op_stat->search_stat->keys_lookup; key_info; key_info = key_info->next) {

-                    slapi_log_stat(LDAP_STAT_READ_INDEX,

-                                   "conn=%" PRIu64 " op=%d STAT read index: attribute=%s key(%s)=%s --> count %d\n",

-                                   op->o_connid, op->o_opid,

-                                   key_info->attribute_type, key_info->index_type, key_info->key,

-                                   key_info->id_lookup_cnt);

+                    if (internal_op) {

+                        slapi_log_stat(LDAP_STAT_READ_INDEX,

+                                       connid == 0 ? STAT_LOG_CONN_OP_FMT_INT_INT "STAT read index: attribute=%s key(%s)=%s --> count %d\n":

+                                                     STAT_LOG_CONN_OP_FMT_EXT_INT "STAT read index: attribute=%s key(%s)=%s --> count %d\n",

+                                       connid, op_id, op_internal_id, op_nested_count,

+                                       key_info->attribute_type, key_info->index_type, key_info->key,

+                                       key_info->id_lookup_cnt);

+                    } else {

+                        slapi_log_stat(LDAP_STAT_READ_INDEX,

+                                       "conn=%" PRIu64 " op=%d STAT read index: attribute=%s key(%s)=%s --> count %d\n",

+                                       connid, op_id,

+                                       key_info->attribute_type, key_info->index_type, key_info->key,

+                                       key_info->id_lookup_cnt);

+                    }

                 }

                 /* total elapsed time */

                 slapi_timespec_diff(&op_stat->search_stat->keys_lookup_end, &op_stat->search_stat->keys_lookup_start, &duration);

                 snprintf(stat_etime, ETIME_BUFSIZ, "%" PRId64 ".%.09" PRId64 "", (int64_t)duration.tv_sec, (int64_t)duration.tv_nsec);

-                slapi_log_stat(LDAP_STAT_READ_INDEX,

-                               "conn=%" PRIu64 " op=%d STAT read index: duration %s\n",

-                               op->o_connid, op->o_opid, stat_etime); 

+                if (internal_op) {

+                    slapi_log_stat(LDAP_STAT_READ_INDEX,

+                                   connid == 0 ? STAT_LOG_CONN_OP_FMT_INT_INT "STAT read index: duration %s\n":

+                                                 STAT_LOG_CONN_OP_FMT_EXT_INT "STAT read index: duration %s\n",

+                                   connid, op_id, op_internal_id, op_nested_count, stat_etime);

+                } else {

+                    slapi_log_stat(LDAP_STAT_READ_INDEX,

+                                   "conn=%" PRIu64 " op=%d STAT read index: duration %s\n",

+                                   op->o_connid, op->o_opid, stat_etime);

+                }

             }

             break;

-        case LDAP_REQ_ABANDON_30:

-        case LDAP_REQ_ABANDON:

+        case SLAPI_OPERATION_ABANDON:

             break;

         default:

             slapi_log_err(SLAPI_LOG_ERR,

-                          "log_op_stat", "Ignoring unknown LDAP request (conn=%" PRIu64 ", tag=0x%lx)\n",

-                          conn->c_connid, op->o_tag);

+                          "log_op_stat", "Ignoring unknown LDAP request (conn=%" PRIu64 ", op_type=0x%lx)\n",

+                          connid, operation_get_type(op));

             break;

     }

 }

@@ -2218,7 +2235,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

             } else {

                 ext_str = "";

             }

-            log_op_stat(pb);

+            log_op_stat(pb, op->o_connid, op->o_opid, 0, 0);

             slapi_log_access(LDAP_DEBUG_STATS,

                              "conn=%" PRIu64 " op=%d RESULT err=%d"

                              " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s\n",

@@ -2233,6 +2250,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries

             }

         } else {

             int optype;

+            log_op_stat(pb, connid, op_id, op_internal_id, op_nested_count);

 #define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s\n"

             slapi_log_access(LDAP_DEBUG_ARGS,

                              connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_MSG_FMT :

-- 

2.38.1