From 3629f947d504afc8406048d690cc031c9c906b67 Mon Sep 17 00:00:00 2001 From: Mark Reynolds Date: Mon, 12 Dec 2022 16:06:29 -0500 Subject: [PATCH] Bump version to 2.2.4-2 Resolves: Bug 1132524 - [RFE] Compression of log file --- ...RFE-Extend-log-of-operations-statist.patch | 294 ++++++++++++++++++ ...ate-create-template-regression-due-t.patch | 34 -- ...Issue-5544-Increase-default-task-TTL.patch | 30 ++ 389-ds-base.spec | 17 +- 4 files changed, 340 insertions(+), 35 deletions(-) create mode 100644 0001-Issue-3729-cont-RFE-Extend-log-of-operations-statist.patch delete mode 100644 0001-Issue-5254-dscreate-create-template-regression-due-t.patch create mode 100644 0002-Issue-5544-Increase-default-task-TTL.patch diff --git a/0001-Issue-3729-cont-RFE-Extend-log-of-operations-statist.patch b/0001-Issue-3729-cont-RFE-Extend-log-of-operations-statist.patch new file mode 100644 index 0000000..623dc9c --- /dev/null +++ b/0001-Issue-3729-cont-RFE-Extend-log-of-operations-statist.patch @@ -0,0 +1,294 @@ +From 8b89bf22dea16956e4a21174f28ec11f32fc2db4 Mon Sep 17 00:00:00 2001 +From: tbordaz +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 + diff --git a/0001-Issue-5254-dscreate-create-template-regression-due-t.patch b/0001-Issue-5254-dscreate-create-template-regression-due-t.patch deleted file mode 100644 index a96f344..0000000 --- a/0001-Issue-5254-dscreate-create-template-regression-due-t.patch +++ /dev/null @@ -1,34 +0,0 @@ -From 88c1e83e02a59f4811f06757daced6c821fa54d9 Mon Sep 17 00:00:00 2001 -From: progier389 -Date: Mon, 11 Apr 2022 16:15:07 +0200 -Subject: [PATCH] Issue 5254 - dscreate create-template regression due to - 5a3bdc336 (#5255) - -dscreate create-template regression due to 829ea4113..5a3bdc336 - (default value for template_file parameter was unwillingly changed to 'None' (instead of None)) - -Issue: 5254 https://github.com/389ds/389-ds-base/issues/5254 - -Reviewed by: - -(cherry picked from commit 45af34013f8bdd34f939d36b16776413e13c0a51) ---- - src/lib389/cli/dscreate | 2 +- - 1 file changed, 1 insertion(+), 1 deletion(-) - -diff --git a/src/lib389/cli/dscreate b/src/lib389/cli/dscreate -index 0b41166cc..aa3878ff9 100755 ---- a/src/lib389/cli/dscreate -+++ b/src/lib389/cli/dscreate -@@ -51,7 +51,7 @@ interactive_parser.set_defaults(func=cli_instance.instance_create_interactive) - template_parser = subparsers.add_parser('create-template', help="Display an example inf answer file, or provide a file name to write it to disk.") - template_parser.add_argument('--advanced', action='store_true', default=False, - help="Add advanced options to the template - changing the advanced options may make your instance install fail") --template_parser.add_argument('template_file', nargs="?", default='None', help="Write example template to this file") -+template_parser.add_argument('template_file', nargs="?", default=None, help="Write example template to this file") - template_parser.set_defaults(func=cli_instance.instance_example) - - subtree_parser = subparsers.add_parser('ds-root', help="Prepare a root directory in which non root user can create, run and administer instances.") --- -2.37.3 - diff --git a/0002-Issue-5544-Increase-default-task-TTL.patch b/0002-Issue-5544-Increase-default-task-TTL.patch new file mode 100644 index 0000000..9d1497c --- /dev/null +++ b/0002-Issue-5544-Increase-default-task-TTL.patch @@ -0,0 +1,30 @@ +From 3bc889b6564b70c5113f74e8add1a47b38fce04b Mon Sep 17 00:00:00 2001 +From: Mark Reynolds +Date: Mon, 28 Nov 2022 09:47:09 -0500 +Subject: [PATCH 2/3] Issue 5544 - Increase default task TTL + +Description: Increase the Time To Live of tasks from 1 hour to 12 hours + +relates: https://github.com/389ds/389-ds-base/issues/5544 + +Reviewed by: progier(Thanks!) +--- + ldap/servers/slapd/task.c | 2 +- + 1 file changed, 1 insertion(+), 1 deletion(-) + +diff --git a/ldap/servers/slapd/task.c b/ldap/servers/slapd/task.c +index c0e3dd7c4..1dc4f6b28 100644 +--- a/ldap/servers/slapd/task.c ++++ b/ldap/servers/slapd/task.c +@@ -48,7 +48,7 @@ static uint64_t shutting_down = 0; + #define TASK_DATE_NAME "nsTaskCreated" + #define TASK_WARNING_NAME "nsTaskWarning" + +-#define DEFAULT_TTL "3600" /* seconds */ ++#define DEFAULT_TTL "43200" /* 12 hours in seconds */ + #define TASK_SYSCONFIG_FILE_ATTR "sysconfigfile" /* sysconfig reload task file attr */ + #define TASK_SYSCONFIG_LOGCHANGES_ATTR "logchanges" + #define TASK_TOMBSTONE_FIXUP "fixup tombstones task" +-- +2.38.1 + diff --git a/389-ds-base.spec b/389-ds-base.spec index 09a2773..faeddd4 100644 --- a/389-ds-base.spec +++ b/389-ds-base.spec @@ -47,7 +47,7 @@ ExcludeArch: i686 Summary: 389 Directory Server (base) Name: 389-ds-base Version: 2.2.4 -Release: 1%{?dist} +Release: 2%{?dist} License: GPLv3+ and (ASL 2.0 or MIT) URL: https://www.port389.org Conflicts: selinux-policy-base < 3.9.8 @@ -269,6 +269,9 @@ Source2: %{name}-devel.README %if %{bundle_jemalloc} Source3: https://github.com/jemalloc/%{jemalloc_name}/releases/download/%{jemalloc_ver}/%{jemalloc_name}-%{jemalloc_ver}.tar.bz2 %endif +Patch01: 0001-Issue-3729-cont-RFE-Extend-log-of-operations-statist.patch +Patch02: 0002-Issue-5544-Increase-default-task-TTL.patch + %description 389 Directory Server is an LDAPv3 compliant server. The base package includes @@ -719,6 +722,18 @@ exit 0 %endif %changelog +* Mon Dec 12 2022 Mark Reynolds - 2.2.4-2 +- Bump version to 2.2.4-2 +- Resolves: Bug 1859271 - RFE - Extend log of operations statistics in access log +- Resolves: Bug 2093981 - RFE - Create Security Audit Log +- Resolves: Bug 2109891 - Migrate 389 to pcre2 +- Resolves: Bug 2112361 - Supplier should do periodic update to avoid slow replication when a new direct update happen +- Resolves: Bug 2112998 - performance search rate: checking if an entry is a referral is expensive +- Resolves: Bug 2114039 - Current pbkdf2 hardcoded parameters are no longer secure +- Resolves: Bug 2124660 - Retro changelog trimming uses maxage incorrectly +- Resolves: Bug 2132697 - RFE - run as non-root +- Resolves: Bug 2142636 - pam mutex lock causing high etimes, affecting red hat internal sso + * Fri Nov 11 2022 Mark Reynolds - 2.2.4-1 - Bump version to 2.2.4-1 - Resolves: Bug 1132524 - [RFE] Compression of log files