PR#50249: Issue 49029 - [RFE] improve internal operations logging - 389-ds-base

389-ds-base

#50249 Issue 49029 - [RFE] improve internal operations logging

Closed 3 years ago by spichugi. Opened 5 years ago by bsmejkal.

bsmejkal/389-ds-base ds49029 into master

Issue 49029 - [RFE] improve internal operations logging

Barbora Smejkalová • 5 years ago

e6e1800

dirsrvtests/tests/suites/ds_logs/ds_logs_test.py

file modified

+445 -1

		`@@ -11,14 +11,17 @@`
		`import pytest`
		`from lib389.tasks import *`
		`from lib389.utils import *`
		`+ from lib389.plugins import *`
		`from lib389.topologies import topology_st`
		`-`
		`from lib389.idm.user import UserAccounts`
		`+ from lib389.idm.group import Groups`
		`+ from lib389.idm.organizationalunit import OrganizationalUnits`

		`logging.getLogger(__name__).setLevel(logging.DEBUG)`
		`log = logging.getLogger(__name__)`

		`PLUGIN_TIMESTAMP = 'nsslapd-logging-hr-timestamps-enabled'`
		`+ PLUGIN_LOGGING = 'nsslapd-plugin-logging'`
		`USER1_DN = 'uid=user1,' + DEFAULT_SUFFIX`


		`@@ -36,12 +39,99 @@`
		`'homeDirectory' : '/home/testuser%d' % uid`
		`})`

		`+`
		`def search_users(topology_st):`
		`users = UserAccounts(topology_st, DEFAULT_SUFFIX)`
		`entries = users.list()`
		`# We just assert we got some data ...`
		`assert len(entries) > 0`

		`+`
		`+ def delete_obj(obj):`
		`+ if obj.exists():`
		`+ obj.delete()`
		`+`
		`+`
		`+ def add_group_and_perform_user_operations(topology_st):`
		`+ topo = topology_st.standalone`
		`+`
		`+ # Add the automember group`
		`+ groups = Groups(topo, DEFAULT_SUFFIX)`
		`+ group = groups.create(properties={'cn': 'group'})`
		`+`
		`+ ous = OrganizationalUnits(topo, DEFAULT_SUFFIX)`
		`+ branch1 = ous.create(properties={'ou': 'branch1'})`
		`+`
		`+ # Add the automember config entry`
		`+ am_configs = AutoMembershipDefinitions(topo)`
		`+ am_config = am_configs.create(properties={'cn': 'config',`
		`+ 'autoMemberScope': branch1.dn,`
		`+ 'autoMemberFilter': 'objectclass=top',`
		`+ 'autoMemberDefaultGroup': group.dn,`
		`+ 'autoMemberGroupingAttr': 'member:dn'})`
		`+`
		`+ # Add a user that should get added to the group`
		`+ users = UserAccounts(topo, DEFAULT_SUFFIX, rdn='ou={}'.format(branch1.rdn))`
		`+ test_user = users.create_test_user(uid=777)`
		`+`
		`+ # Check if created user is group member`
		`+ assert test_user.dn in group.list_members()`
		`+`
		`+ log.info('Renaming user')`
		`+ test_user.rename('uid=new_test_user_777', newsuperior=SUFFIX)`
		`+`
		`+ log.info('Delete the user')`
		`+ delete_obj(test_user)`
		`+`
		`+ log.info('Delete automember entry, org. unit and group for the next test')`
		`+ delete_obj(am_config)`
		`+ delete_obj(branch1)`
		`+ delete_obj(group)`
		`+`
		`+`
		`+ @pytest.fixture(scope="module")`
		`+ def enable_plugins(topology_st):`
		`+ topo = topology_st.standalone`
		`+`
		`+ log.info("Enable automember plugin")`
		`+ plugin = AutoMembershipPlugin(topo)`
		`+ plugin.enable()`
		`+`
		`+ log.info('Enable Referential Integrity plugin')`
		`+ plugin = ReferentialIntegrityPlugin(topo)`
		`+ plugin.enable()`
		`+`
		`+ log.info('Set nsslapd-plugin-logging to on')`
		`+ topo.config.set(PLUGIN_LOGGING, 'ON')`
		`+`
		`+ log.info('Restart the server')`
		`+ topo.restart()`
		`+`
		`+`
		`+ @pytest.fixture(scope="module")`
		`+ def add_user_log_level_260(topology_st, enable_plugins):`
		`+ log.info('Configure access log level to 260 (4 + 256)')`
		`+ access_log_level = '260'`
		`+ topology_st.standalone.config.set(LOG_ACCESS_LEVEL, access_log_level)`
		`+ add_group_and_perform_user_operations(topology_st)`
		`+`
		`+`
		`+ @pytest.fixture(scope="module")`
		`+ def add_user_log_level_516(topology_st, enable_plugins):`
		`+ log.info('Configure access log level to 516 (4 + 512)')`
		`+ access_log_level = '516'`
		`+ topology_st.standalone.config.set(LOG_ACCESS_LEVEL, access_log_level)`
		`+ add_group_and_perform_user_operations(topology_st)`
		`+`
		`+`
		`+ @pytest.fixture(scope="module")`
		`+ def add_user_log_level_131076(topology_st, enable_plugins):`
		`+ log.info('Configure access log level to 131076 (4 + 131072)')`
		`+ access_log_level = '131076'`
		`+ topology_st.standalone.config.set(LOG_ACCESS_LEVEL, access_log_level)`
		`+ add_group_and_perform_user_operations(topology_st)`
		`+`
		`+`
		`@pytest.mark.bz1273549`
		`def test_check_default(topology_st):`
		`"""Check the default value of nsslapd-logging-hr-timestamps-enabled,`
		`@@ -67,6 +157,7 @@`
		`assert (default == "on")`
		`log.debug(default)`

		`+`
		`@pytest.mark.bz1273549`
		`def test_plugin_set_invalid(topology_st):`
		`"""Try to set some invalid values for nsslapd-logging-hr-timestamps-enabled`
		`@@ -87,6 +178,7 @@`
		`with pytest.raises(ldap.OPERATIONS_ERROR):`
		`result = topology_st.standalone.config.set(PLUGIN_TIMESTAMP, 'JUNK')`

		`+`
		`@pytest.mark.bz1273549`
		`def test_log_plugin_on(topology_st):`
		`"""Check access logs for millisecond, when`
		`@@ -122,6 +214,7 @@`
		`assert len(access_log_lines) > 0`
		`assert topology_st.standalone.ds_access_log.match('^\[.+\d{9}.+\].+')`

		`+`
		`@pytest.mark.bz1273549`
		`def test_log_plugin_off(topology_st):`
		`"""Milliseconds should be absent from access logs when`
		`@@ -171,6 +264,357 @@`
		`assert not topology_st.standalone.ds_access_log.match('^\[.+\d{9}.+\].+')`


		`+ @pytest.mark.bz1358706`
		`+ @pytest.mark.ds49029`
		`+ def test_internal_log_server_level_0(topology_st):`
		`+ """Tests server-initiated internal operations`
		`+ :id: 798d06fe-92e8-4648-af66-21349c20638e`
		`+ :setup: Standalone instance`
		`+ :steps:`
		`+ 1. Set nsslapd-plugin-logging to on`
		`+ 2. Configure access log level to only 0`
		`+ 3. Check the access logs.`
		`+ :expectedresults:`
		`+ 1. Operation should be successful`
		`+ 2. Operation should be successful`
		`+ 3. Access log should not contain internal operations log formats`
		`+ """`
		`+`
		`+ topo = topology_st.standalone`
		`+`
		`+ log.info('Delete the previous access logs')`
		`+ topo.deleteAccessLogs()`
		`+`
		`+ log.info('Set nsslapd-plugin-logging to on')`
		`+ topo.config.set(PLUGIN_LOGGING, 'ON')`
		`+`
		`+ log.info('Configure access log level to 0')`
		`+ access_log_level = '0'`
		`+ topo.config.set(LOG_ACCESS_LEVEL, access_log_level)`
		`+`
		`+ log.info('Restart the server to flush the logs')`
		`+ topo.restart()`
		`+`
		`+ # These comments contain lines we are trying to find without regex`
		`+ log.info("Check if access log does not contain internal log of MOD operation")`
		`+ # (Internal) op=2(2)(1) SRCH base="cn=config`
		`+ assert not topo.ds_access_log.match(r'.\(Internal\) op=2\(2\)\(1\) SRCH base="cn=config.')`
		`+ # (Internal) op=2(2)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert not topo.ds_access_log.match(r'.\(Internal\) op=2\(2\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+`
		`+ log.info("Check if the other internal operations are not present")`
		`+ # conn=Internal(0) op=0`
		`+ assert not topo.ds_access_log.match(r'.conn=Internal\(0\) op=0.')`
		`+`
		`+`
		`+ @pytest.mark.bz1358706`
		`+ @pytest.mark.ds49029`
		`+ def test_internal_log_server_level_4(topology_st):`
		`+ """Tests server-initiated internal operations`
		`+ :id: a3500e47-d941-4575-b399-e3f4b49bc4b6`
		`+ :setup: Standalone instance`
		`+ :steps:`
		`+ 1. Set nsslapd-plugin-logging to on`
		`+ 2. Configure access log level to only 4`
		`+ 3. Check the access logs, it should contain info about MOD operation of cn=config and other`
		`+ internal operations should have the conn field set to Internal`
		`+ and all values inside parenthesis set to 0.`
		`+ :expectedresults:`
		`+ 1. Operation should be successful`
		`+ 2. Operation should be successful`
		`+ 3. Access log should contain correct internal log formats with cn=config modification:`
		`+ "(Internal) op=2(1)(1)"`
		`+ "conn=Internal(0)"`
		`+ """`
		`+`
		`+ topo = topology_st.standalone`
		`+`
		`+ log.info('Delete the previous access logs for the next test')`
		`+ topo.deleteAccessLogs()`
		`+`
		`+ log.info('Set nsslapd-plugin-logging to on')`
		`+ topo.config.set(PLUGIN_LOGGING, 'ON')`
		`+`
		`+ log.info('Configure access log level to 4')`
		`+ access_log_level = '4'`
		`+ topo.config.set(LOG_ACCESS_LEVEL, access_log_level)`
		`+`
		`+ log.info('Restart the server to flush the logs')`
		`+ topo.restart()`
		`+`
		`+ # These comments contain lines we are trying to find without regex`
		`+ log.info("Check if access log contains internal MOD operation in correct format")`
		`+ # (Internal) op=2(2)(1) SRCH base="cn=config`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=2\(2\)\(1\) SRCH base="cn=config.')`
		`+ # (Internal) op=2(2)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=2\(2\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+`
		`+ log.info("Check if the other internal operations have the correct format")`
		`+ # conn=Internal(0) op=0`
		`+ assert topo.ds_access_log.match(r'.conn=Internal\(0\) op=0.')`
		`+`
		`+ log.info('Delete the previous access logs for the next test')`
		`+ topo.deleteAccessLogs()`
		`+`
		`+`
		`+ @pytest.mark.bz1358706`
		`+ @pytest.mark.ds49029`
		`+ def test_internal_log_level_260(topology_st, add_user_log_level_260):`
		`+ """Tests client initiated operations when automember plugin is enabled`
		`+ :id: e68a303e-c037-42b2-a5a0-fbea27c338a9`
		`+ :setup: Standalone instance with internal operation`
		`+ logging on and nsslapd-plugin-logging to on`
		`+ :steps:`
		`+ 1. Configure access log level to 260 (4 + 256)`
		`+ 2. Set nsslapd-plugin-logging to on`
		`+ 3. Enable Referential Integrity and automember plugins`
		`+ 4. Restart the server`
		`+ 5. Add a test group`
		`+ 6. Add a test user and add it as member of the test group`
		`+ 7. Rename the test user`
		`+ 8. Delete the test user`
		`+ 9. Check the access logs for nested internal operation logs`
		`+ :expectedresults:`
		`+ 1. Operation should be successful`
		`+ 2. Operation should be successful`
		`+ 3. Operation should be successful`
		`+ 4. Operation should be successful`
		`+ 5. Operation should be successful`
		`+ 6. Operation should be successful`
		`+ 7. Operation should be successful`
		`+ 8. Operation should be successful`
		`+ 9. Access log should contain internal info about operations of the user`
		`+ """`
		`+`
		`+ topo = topology_st.standalone`
		`+`
		`+ log.info('Restart the server to flush the logs')`
		`+ topo.restart()`
		`+`
		`+ # These comments contain lines we are trying to find without regex`
		`+ log.info("Check the access logs for ADD operation of the user")`
		`+ # op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(1) MOD dn="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(1\) MOD dn="cn=group,ou=Groups,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(2) SRCH base="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=10\(1\)\(2\) SRCH base="cn=group,'`
		`+ r'ou=Groups,dc=example,dc=com".*')`
		`+ # (Internal) op=10(1)(2) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(2\) RESULT err=0 tag=48 nentries=1')`
		`+ # (Internal) op=10(1)(1) RESULT err=0 tag=48`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(1\) RESULT err=0 tag=48.')`
		`+ # op=10 RESULT err=0 tag=105`
		`+ assert topo.ds_access_log.match(r'.op=10 RESULT err=0 tag=105.')`
		`+`
		`+ log.info("Check the access logs for MOD operation of the user")`
		`+ # op=12 MODRDN dn="uid=test_user_777,ou=branch1,dc=example,dc=com" '`
		`+ # 'newrdn="uid=new_test_user_777" newsuperior="dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*op=12 MODRDN dn="uid=test_user_777,ou=branch1,dc=example,dc=com" '`
		`+ 'newrdn="uid=new_test_user_777" newsuperior="dc=example,dc=com".*')`
		`+ # (Internal) op=12(1)(1) SRCH base="uid=test_user_777, ou=branch1,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=12\(1\)\(1\) SRCH base="uid=test_user_777,'`
		`+ 'ou=branch1,dc=example,dc=com".*')`
		`+ # (Internal) op=12(1)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=12\(1\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+ # op=12 RESULT err=0 tag=109`
		`+ assert topo.ds_access_log.match(r'.op=12 RESULT err=0 tag=109.')`
		`+`
		`+ log.info("Check the access logs for DEL operation of the user")`
		`+ # op=15 DEL dn="uid=new_test_user_777,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.op=15 DEL dn="uid=new_test_user_777,dc=example,dc=com".')`
		`+ # (Internal) op=15(1)(1) SRCH base="uid=new_test_user_777, dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=15\(1\)\(1\) SRCH base="uid=new_test_user_777,'`
		`+ 'dc=example,dc=com".*')`
		`+ # (Internal) op=15(1)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=15\(1\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+ # op=15 RESULT err=0 tag=107`
		`+ assert topo.ds_access_log.match(r'.op=15 RESULT err=0 tag=107.')`
		`+`
		`+ log.info("Check if the other internal operations have the correct format")`
		`+ # conn=Internal(0) op=0`
		`+ assert topo.ds_access_log.match(r'.conn=Internal\(0\) op=0.')`
		`+`
		`+ log.info('Delete the previous access logs for the next test')`
		`+ topo.deleteAccessLogs()`
		`+`
		`+`
		`+ @pytest.mark.bz1358706`
		`+ @pytest.mark.ds49029`
		`+ def test_internal_log_level_131076(topology_st, add_user_log_level_131076):`
		`+ """Tests client-initiated operations while referential integrity plugin is enabled`
		`+ :id: 44836ac9-dabd-4a8c-abd5-ecd7c2509739`
		`+ :setup: Standalone instance`
		`+ Configure access log level to - 131072 + 4`
		`+ Set nsslapd-plugin-logging to on`
		`+ :steps:`
		`+ 1. Configure access log level to 131076`
		`+ 2. Set nsslapd-plugin-logging to on`
		`+ 3. Enable Referential Integrity and automember plugins`
		`+ 4. Restart the server`
		`+ 5. Add a test group`
		`+ 6. Add a test user and add it as member of the test group`
		`+ 7. Rename the test user`
		`+ 8. Delete the test user`
		`+ 9. Check the access logs for nested internal operation logs`
		`+ :expectedresults:`
		`+ 1. Operation should be successful`
		`+ 2. Operation should be successful`
		`+ 3. Operation should be successful`
		`+ 4. Operation should be successful`
		`+ 5. Operation should be successful`
		`+ 6. Operation should be successful`
		`+ 7. Operation should be successful`
		`+ 8. Operation should be successful`
		`+ 9. Access log should contain internal info about operations of the user`
		`+ """`
		`+`
		`+ topo = topology_st.standalone`
		`+`
		`+ log.info('Restart the server to flush the logs')`
		`+ topo.restart()`
		`+`
		`+ path = topo.ds_access_log._get_log_path()`
		`+ with open(path) as f:`
		`+ print(f.read())`
		`+`
		`+ # These comments contain lines we are trying to find without regex`
		`+ log.info("Check the access logs for ADD operation of the user")`
		`+ # op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com"`
		`+ assert not topo.ds_access_log.match(r'.op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(1) MOD dn="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(1\) MOD dn="cn=group,ou=Groups,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(2) SRCH base="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(2\) SRCH base="cn=group,ou=Groups,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(2) RESULT err=0 tag=48 nentries=1*')`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(2\) RESULT err=0 tag=48 nentries=1')`
		`+ # (Internal) op=10(1)(1) RESULT err=0 tag=48`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(1\) RESULT err=0 tag=48.')`
		`+ # op=10 RESULT err=0 tag=105`
		`+ assert not topo.ds_access_log.match(r'.op=10 RESULT err=0 tag=105.')`
		`+`
		`+ log.info("Check the access logs for MOD operation of the user")`
		`+ # op=12 MODRDN dn="uid=test_user_777,ou=branch1,dc=example,dc=com" '`
		`+ # 'newrdn="uid=new_test_user_777" newsuperior="dc=example,dc=com"`
		`+ assert not topo.ds_access_log.match(r'.*op=12 MODRDN dn="uid=test_user_777,ou=branch1,dc=example,dc=com" '`
		`+ 'newrdn="uid=new_test_user_777" newsuperior="dc=example,dc=com".*')`
		`+ # (Internal) op=12(1)(1) SRCH base="uid=test_user_777, ou=branch1,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=12\(1\)\(1\) SRCH base="uid=test_user_777,'`
		`+ 'ou=branch1,dc=example,dc=com".*')`
		`+ # (Internal) op=12(1)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=12\(1\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+ # op=12 RESULT err=0 tag=109`
		`+ assert not topo.ds_access_log.match(r'.op=12 RESULT err=0 tag=109.')`
		`+`
		`+ log.info("Check the access logs for DEL operation of the user")`
		`+ # op=15 DEL dn="uid=new_test_user_777,dc=example,dc=com"`
		`+ assert not topo.ds_access_log.match(r'.op=15 DEL dn="uid=new_test_user_777,dc=example,dc=com".')`
		`+ # (Internal) op=15(1)(1) SRCH base="uid=new_test_user_777, dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=15\(1\)\(1\) SRCH base="uid=new_test_user_777,'`
		`+ 'dc=example,dc=com".*')`
		`+ # (Internal) op=15(1)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=15\(1\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+ # op=15 RESULT err=0 tag=107`
		`+ assert not topo.ds_access_log.match(r'.op=15 RESULT err=0 tag=107.')`
		`+`
		`+ log.info("Check if the other internal operations have the correct format")`
		`+ # conn=Internal(0) op=0`
		`+ assert topo.ds_access_log.match(r'.conn=Internal\(0\) op=0.')`
		`+`
		`+ log.info('Delete the previous access logs for the next test')`
		`+ topo.deleteAccessLogs()`
		`+`
		`+`
		`+ @pytest.mark.bz1358706`
		`+ @pytest.mark.ds49029`
		`+ def test_internal_log_level_516(topology_st, add_user_log_level_516):`
		`+ """Tests client initiated operations when referential integrity plugin is enabled`
		`+ :id: bee1d681-763d-4fa5-aca2-569cf93f8b71`
		`+ :setup: Standalone instance`
		`+ Configure access log level to - 512+4`
		`+ Set nsslapd-plugin-logging to on`
		`+ :steps:`
		`+ 1. Configure access log level to 516`
		`+ 2. Set nsslapd-plugin-logging to on`
		`+ 3. Enable Referential Integrity and automember plugins`
		`+ 4. Restart the server`
		`+ 5. Add a test group`
		`+ 6. Add a test user and add it as member of the test group`
		`+ 7. Rename the test user`
		`+ 8. Delete the test user`
		`+ 9. Check the access logs for nested internal operation logs`
		`+ :expectedresults:`
		`+ 1. Operation should be successful`
		`+ 2. Operation should be successful`
		`+ 3. Operation should be successful`
		`+ 4. Operation should be successful`
		`+ 5. Operation should be successful`
		`+ 6. Operation should be successful`
		`+ 7. Operation should be successful`
		`+ 8. Operation should be successful`
		`+ 9. Access log should contain internal info about operations of the user`
		`+ """`
		`+`
		`+ topo = topology_st.standalone`
		`+`
		`+ log.info('Restart the server to flush the logs')`
		`+ topo.restart()`
		`+`
		`+ # These comments contain lines we are trying to find without regex`
		`+ log.info("Check the access logs for ADD operation of the user")`
		`+ # op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com"`
		`+ assert not topo.ds_access_log.match(r'.op=10 ADD dn="uid=test_user_777,ou=branch1,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(1) MOD dn="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(1\) MOD dn="cn=group,ou=Groups,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(2) SRCH base="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(2\) SRCH base="cn=group,ou=Groups,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(2) ENTRY dn="cn=group,ou=Groups,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(2\) ENTRY dn="cn=group,ou=Groups,dc=example,dc=com".')`
		`+ # (Internal) op=10(1)(2) RESULT err=0 tag=48 nentries=1*')`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(2\) RESULT err=0 tag=48 nentries=1')`
		`+ # (Internal) op=10(1)(1) RESULT err=0 tag=48`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=10\(1\)\(1\) RESULT err=0 tag=48.')`
		`+ # op=10 RESULT err=0 tag=105`
		`+ assert not topo.ds_access_log.match(r'.op=10 RESULT err=0 tag=105.')`
		`+`
		`+ log.info("Check the access logs for MOD operation of the user")`
		`+ # op=12 MODRDN dn="uid=test_user_777,ou=branch1,dc=example,dc=com" '`
		`+ # 'newrdn="uid=new_test_user_777" newsuperior="dc=example,dc=com"`
		`+ assert not topo.ds_access_log.match(r'.*op=12 MODRDN dn="uid=test_user_777,ou=branch1,dc=example,dc=com" '`
		`+ 'newrdn="uid=new_test_user_777" newsuperior="dc=example,dc=com".*')`
		`+ # Internal) op=12(1)(1) SRCH base="uid=test_user_777, ou=branch1,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=12\(1\)\(1\) SRCH base="uid=test_user_777,'`
		`+ 'ou=branch1,dc=example,dc=com".*')`
		`+ # (Internal) op=12(1)(1) ENTRY dn="uid=test_user_777, ou=branch1,dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=12\(1\)\(1\) ENTRY dn="uid=test_user_777,'`
		`+ 'ou=branch1,dc=example,dc=com".*')`
		`+ # (Internal) op=12(1)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=12\(1\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+ # op=12 RESULT err=0 tag=109`
		`+ assert not topo.ds_access_log.match(r'.op=12 RESULT err=0 tag=109.')`
		`+`
		`+ log.info("Check the access logs for DEL operation of the user")`
		`+ # op=15 DEL dn="uid=new_test_user_777,dc=example,dc=com"`
		`+ assert not topo.ds_access_log.match(r'.op=15 DEL dn="uid=new_test_user_777,dc=example,dc=com".')`
		`+ # (Internal) op=15(1)(1) SRCH base="uid=new_test_user_777, dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=15\(1\)\(1\) SRCH base="uid=new_test_user_777,'`
		`+ 'dc=example,dc=com".*')`
		`+ # (Internal) op=15(1)(1) ENTRY dn="uid=new_test_user_777, dc=example,dc=com"`
		`+ assert topo.ds_access_log.match(r'.*\(Internal\) op=15\(1\)\(1\) ENTRY dn="uid=new_test_user_777,'`
		`+ 'dc=example,dc=com".*')`
		`+ # (Internal) op=15(1)(1) RESULT err=0 tag=48 nentries=1`
		`+ assert topo.ds_access_log.match(r'.\(Internal\) op=15\(1\)\(1\) RESULT err=0 tag=48 nentries=1.')`
		`+ # op=15 RESULT err=0 tag=107`
		`+ assert not topo.ds_access_log.match(r'.op=15 RESULT err=0 tag=107.')`
		`+`
		`+ log.info("Check if the other internal operations have the correct format")`
		`+ # conn=Internal(0) op=0`
		`+ assert topo.ds_access_log.match(r'.conn=Internal\(0\) op=0.')`
		`+`
		`+ log.info('Delete the previous access logs for the next test')`
		`+ topo.deleteAccessLogs()`
		`+`
		`+`
		`if __name__ == '__main__':`
		`# Run isolated`
		`# -s for DEBUG mode`

bsmejkal commented 5 years ago

Description:
Added test cases and fixtures to check correct internal log values of user operations (add, rename, delete) in access log when different access log level is set.

https://pagure.io/389-ds-base/issue/49029

Reviewed by: spichugi (Thanks!)

mreynolds commented 5 years ago

LGTM but every time I say that @firstyear and @spichugi have concerns. So lets see what they have to say...

firstyear commented on line 21 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

How does "member attr" change between 1.3.7 given that member and memberof are reverse directions for membership?

firstyear commented on line 42 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

instead of this helper function, you can use "obj.ensure_removed()" which does the state check and delete for you.

firstyear commented on line 47 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

Is there a valid case where the user wouldn't exist and you try to rename them? This seems like a potential flaw in the test architecture if you "best effort" rename. Either you rename or don't I think.

firstyear commented on line 75 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

This certainly will fail with the MEMBER_ATTR definition you have above on older versions. It's always been "member". ....

As a helper you can just use "group.list_members()" instead, and it will "do the right thing" for you.

firstyear commented on line 96 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

Why do you call a disable before the enable? Just call enable()....

firstyear commented on line 195 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

You probably don't want this timeout in restart, because highly-loaded CI servers will probably take longer than 10 seconds ....

firstyear commented on line 198 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

Please provided a commented example of the "line you are matching", so that we can see what the regex is intending to find.

firstyear commented 5 years ago

For the most part, pretty clean and nice use of the api I think. Some improvements, but pretty good, thanks.

bsmejkal commented 5 years ago

@firstyear Thanks! I will correct the test with suggested changes.

Also questions:
1. So basically there is no need to distinguish member and memberOf between versions as these terms mean reverse directions for membership and I should keep the definition just to MEMBER_ATTR = 'memberOf'?
I found this function with versions in tests/suites/plugins/acceptance_test.py so I thought there was a change in that attribute.
2. What would be the sufficient timeout for restart? 60? Because 120 seems a bit too much although not impossible.

Edited 5 years ago by bsmejkal

firstyear commented 5 years ago

Hey there.

In this case, you are using the "group has a member which is user.dn". The reverse is "the user is a memberOf a group". So in this case, MEMBER_ATTR is "member".

If that's in acceptance_test.py, that may be a bug :|

Don't list the timeout at all. The function has a default value (which I think is 120). I'm not sure of your python experience, but python supports default args where if you provide no value, the default is used. :)

bsmejkal commented 5 years ago

@firstyear
Thanks :)
Also I looked at the obj.ensure_removed() but what would be the correct way to use it? Because if I call it like “test_user.ensure_removed('uid','new_test_user_777')” then I get error “TypeError: 'NoneType' object is not callable”.
I thought it’s on the same level as obj.ensure_present() which works fine.

firstyear commented 5 years ago

@bsmejkal The ensure_removed works on an instance of something. An example could be:

users = UserAccounts(standalone, DEFAULT_SUFFIX)
user = users.get('firstyear')
user.ensure_removed()

It doesn't need any arguments. The idea is you could have a pattern like:

user = UserAccount(standalone, <dn of user>)
user.ensure_removed()

So you don't know if the user existed, but you can blind create the object that "could" be there, then ensure it's removed. The initialisation of the DSLdapObject does not checks on ldap so it's safe to do this :)

bsmejkal commented 5 years ago

@firstyear
I tried what you suggested on rhel8
(389-ds-base-1.4.0.20-7.module+el8+2809+aaa18b6a.x86_64) but if I try this:

users = UserAccounts(topology_st.standalone, DEFAULT_SUFFIX)
user = users.create_test_user(uid=777)
user.ensure_removed()

or this pattern:

user = UserAccount(standalone, <dn of user>)
user.ensure_removed()

I will still get error to provide those two arguments:

TypeError: ensure_removed() missing 2 required positional arguments: 'attr' and 'value'

So I tried:

user.ensure_removed('dn', user.dn)

then it passes, but user dn still won’t get removed (I checked) and the next test will fail, because that entry already exists.

firstyear commented 5 years ago

Ahhhhhh, it turns out i'm the problem, and I misread the api. ensure_removed makes sure an attr:value is missing, not that the entry is deleted. Opps! This is my mistake for telling you the wrong thing.

The api for "ensure deleted" doesn't exist today, so ignore this comment and do the "if user.exists(): user.delete()" in that case. So sorry for this.

rebased onto 49d66d11467e5227a640cc7e53feae31cbab4ed5

5 years ago

bsmejkal commented 5 years ago

@firstyear
No problem :)
I made the suggested changes, could you please take a look? Thanks!

rebased onto e6e1800

5 years ago

firstyear commented 5 years ago

Thanks @bsmejkal This looks much better. Great work!

Pull-Request has been merged by firstyear

5 years ago

spichugi commented 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/3308

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

Assignee

None

Tags

No Tags

Changes Summary 1

+445 -1

file changed

dirsrvtests/tests/suites/ds_logs/ds_logs_test.py

389-ds-base

Source Code

#50249 Issue 49029 - [RFE] improve internal operations logging Closed 3 years ago by spichugi. Opened 5 years ago by bsmejkal. bsmejkal/389-ds-base ds49029 into master

Metadata

Changes Summary 1

#50249 Issue 49029 - [RFE] improve internal operations logging

Closed 3 years ago by spichugi. Opened 5 years ago by bsmejkal.

bsmejkal/389-ds-base ds49029 into master