PR#50629: Ticket 50428 - Log the actual base DN when the search fails with "invalid attribute request" - 389-ds-base

389-ds-base

#50629 Ticket 50428 - Log the actual base DN when the search fails with "invalid attribute request"

Closed 4 years ago by spichugi. Opened 5 years ago by sgouvern.

sgouvern/389-ds-base ticket_50428 into master

Ticket 50428 - Log the actual base DN when the search fails with "invalid attribute request"

Sylvie Gouverneyre • 5 years ago

2f5daa7

dirsrvtests/tests/suites/ds_logs/ds_logs_test.py

file modified

+89 -31

		`@@ -10,6 +10,7 @@`
		`import logging`
		`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.idm.user import UserAccounts`
		`@@ -144,6 +145,22 @@`
		`add_user_log_level(topology_st, access_log_level, request)`


		`+ @pytest.fixture(scope="function")`
		`+ def clean_access_logs(topology_st, request):`
		`+ def _clean_access_logs():`
		`+ topo = topology_st.standalone`
		`+ log.info("Stopping the instance")`
		`+ topo.stop()`
		`+ log.info("Deleting the access logs")`
		`+ topo.deleteAccessLogs()`
		`+ log.info("Starting the instance")`
		`+ topo.start()`
		`+`
		`+ request.addfinalizer(_clean_access_logs)`
		`+`
		`+ return clean_access_logs`
		`+`
		`+`
		`@pytest.mark.bz1273549`
		`def test_check_default(topology_st):`
		`"""Check the default value of nsslapd-logging-hr-timestamps-enabled,`
		`@@ -276,9 +293,10 @@`
		`assert not topology_st.standalone.ds_access_log.match(r'^\[.+\d{9}.+\].+')`


		`+ @pytest.mark.xfail(ds_is_older('1.4.0'), reason="May fail on 1.3.x because of bug 1358706")`
		`@pytest.mark.bz1358706`
		`@pytest.mark.ds49029`
		`- def test_internal_log_server_level_0(topology_st):`
		`+ def test_internal_log_server_level_0(topology_st, clean_access_logs):`
		`"""Tests server-initiated internal operations`
		`:id: 798d06fe-92e8-4648-af66-21349c20638e`
		`:setup: Standalone instance`
		`@@ -295,8 +313,6 @@`
		`topo = topology_st.standalone`
		`default_log_level = topo.config.get_attr_val_utf8(LOG_ACCESS_LEVEL)`

		`- log.info('Delete the previous access logs')`
		`- topo.deleteAccessLogs()`

		`log.info('Set nsslapd-plugin-logging to on')`
		`topo.config.set(PLUGIN_LOGGING, 'ON')`
		`@@ -320,13 +336,12 @@`
		`assert not topo.ds_access_log.match(r'.conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).')`

		`topo.config.set(LOG_ACCESS_LEVEL, default_log_level)`
		`- log.info('Delete the previous access logs for the next test')`
		`- topo.deleteAccessLogs()`


		`+ @pytest.mark.xfail(ds_is_older('1.4.0'), reason="May fail on 1.3.x because of bug 1358706")`
		`@pytest.mark.bz1358706`
		`@pytest.mark.ds49029`
		`- def test_internal_log_server_level_4(topology_st):`
		`+ def test_internal_log_server_level_4(topology_st, clean_access_logs):`
		`"""Tests server-initiated internal operations`
		`:id: a3500e47-d941-4575-b399-e3f4b49bc4b6`
		`:setup: Standalone instance`
		`@@ -347,9 +362,6 @@`
		`topo = topology_st.standalone`
		`default_log_level = topo.config.get_attr_val_utf8(LOG_ACCESS_LEVEL)`

		`- 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')`

		`@@ -360,22 +372,22 @@`
		`log.info('Restart the server to flush the logs')`
		`topo.restart()`

		`- # These comments contain lines we are trying to find without regex (the op numbers are just examples)`
		`- 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=[0-9]+\([0-9]+\)\([0-9]+\) 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=[0-9]+\([0-9]+\)\([0-9]+\) 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-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).')`
		`-`
		`- topo.config.set(LOG_ACCESS_LEVEL, default_log_level)`
		`- log.info('Delete the previous access logs for the next test')`
		`- topo.deleteAccessLogs()`
		`+ try:`
		`+ # These comments contain lines we are trying to find without regex (the op numbers are just examples)`
		`+ 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=[0-9]+\([0-9]+\)\([0-9]+\) 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=[0-9]+\([0-9]+\)\([0-9]+\) 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-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).')`
		`+ finally:`
		`+ topo.config.set(LOG_ACCESS_LEVEL, default_log_level)`


		`+ @pytest.mark.xfail(ds_is_older('1.4.0'), reason="May fail on 1.3.x because of bug 1358706")`
		`@pytest.mark.bz1358706`
		`@pytest.mark.ds49029`
		`def test_internal_log_level_260(topology_st, add_user_log_level_260):`
		`@@ -456,6 +468,7 @@`
		`assert topo.ds_access_log.match(r'.conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).')`


		`+ @pytest.mark.xfail(ds_is_older('1.4.0'), reason="May fail on 1.3.x because of bug 1358706")`
		`@pytest.mark.bz1358706`
		`@pytest.mark.ds49029`
		`def test_internal_log_level_131076(topology_st, add_user_log_level_131076):`
		`@@ -537,6 +550,7 @@`
		`assert topo.ds_access_log.match(r'.conn=Internal\([0-9]+\) op=[0-9]+\([0-9]+\)\([0-9]+\).')`


		`+ @pytest.mark.xfail(ds_is_older('1.4.0'), reason="May fail on 1.3.x because of bug 1358706")`
		`@pytest.mark.bz1358706`
		`@pytest.mark.ds49029`
		`def test_internal_log_level_516(topology_st, add_user_log_level_516):`
		`@@ -630,7 +644,7 @@`
		`@pytest.mark.skipif(ds_is_older('1.4.1.4'), reason="Not implemented")`
		`@pytest.mark.bz1358706`
		`@pytest.mark.ds49232`
		`- def test_access_log_truncated_search_message(topology_st):`
		`+ def test_access_log_truncated_search_message(topology_st, clean_access_logs):`
		`"""Tests that the access log message is properly truncated when the message is too long`

		`:id: 0a9af37d-3311-4a2f-ac0a-9a1c631aaf27`
		`@@ -662,19 +676,14 @@`
		`assert not topo.ds_access_log.match(r'.cn=ending.')`
		`assert not topo.ds_access_log.match(r'.cn500.')`

		`- log.info('Delete the previous access logs for the next test')`
		`- topo.deleteAccessLogs()`
		`+`

		`@pytest.mark.xfail(ds_is_older('1.4.1.6'), reason="May fail because of bug 1732053")`
		`@pytest.mark.bz1732053`
		`@pytest.mark.ds50510`
		`- def test_etime_at_border_of_second(topology_st):`
		`+ def test_etime_at_border_of_second(topology_st, clean_access_logs):`
		`topo = topology_st.standalone`

		`- # be sure to analyze only the following rapid OPs`
		`- topo.stop()`
		`- os.remove(topo.accesslog)`
		`- topo.start()`

		`prog = os.path.join(topo.ds_paths.bin_dir, 'rsearch')`

		`@@ -711,6 +720,55 @@`
		`assert not invalid_etime`


		`+ @pytest.mark.xfail(ds_is_older('1.3.10.1'), reason="May fail because of bug 1662461")`
		`+ @pytest.mark.bz1662461`
		`+ @pytest.mark.ds50428`
		`+ @pytest.mark.ds49969`
		`+ def test_log_base_dn_when_invalid_attr_request(topology_st):`
		`+ """Test that DS correctly logs the base dn when a search with invalid attribute request is performed`
		`+`
		`+ :id: 859de962-c261-4ffb-8705-97bceab1ba2c`
		`+ :setup: Standalone instance`
		`+ :steps:`
		`+ 1. Disable the accesslog-logbuffering config parameter`
		`+ 2. Delete the previous access log`
		`+ 3. Perform a base search on the DEFAULT_SUFFIX, using invalid "" "" attribute request`
		`+ 4. Check the access log file for 'invalid attribute request'`
		`+ 5. Check the access log file for 'SRCH base="\(null\)"'`
		`+ 6. Check the access log file for 'SRCH base="DEFAULT_SUFFIX"'`
		`+ :expectedresults:`
		`+ 1. Operations are visible in the access log in real time`
		`+ 2. Fresh new access log is created`
		`+ 3. The search operation raises a Protocol error`
		`+ 4. The access log should have an 'invalid attribute request' message`
		`+ 5. The access log should not have "\(null\)" as value for the Search base dn`
		`+ 6. The access log should have the value of DEFAULT_SUFFIX as Search base dn`
		`+ """`
		`+`
		`+ entry = DSLdapObject(topology_st.standalone, DEFAULT_SUFFIX)`
		`+`
		`+ log.info('Set accesslog logbuffering to off to get the log in real time')`
		`+ topology_st.standalone.config.set('nsslapd-accesslog-logbuffering', 'off')`
		`+`
		`+ log.info('delete the previous access logs to get a fresh new one')`
		`+ topology_st.standalone.deleteAccessLogs()`
		`+`
		`+ log.info("Search the default suffix, with invalid '\"\" \"\"' attribute request")`
		`+ log.info("A Protocol error exception should be raised, see https://pagure.io/389-ds-base/issue/49969")`
		`+ # A ldap.PROTOCOL_ERROR exception is expected`
		`+ with pytest.raises(ldap.PROTOCOL_ERROR):`
		`+ assert entry.get_attrs_vals_utf8(['', ''])`
		`+`
		`+ # Search for appropriate messages in the access log`
		`+ log.info('Check the access logs for correct messages')`
		`+ # We should find the 'invalid attribute request' information`
		`+ assert topology_st.standalone.ds_access_log.match(r'.invalid attribute request.')`
		`+ # We should not find a "(null)" base dn mention`
		`+ assert not topology_st.standalone.ds_access_log.match(r'.SRCH base="\(null\)".')`
		`+ # We should find the base dn for the search`
		`+ assert topology_st.standalone.ds_access_log.match(r'.SRCH base="{}".'.format(DEFAULT_SUFFIX))`
		`+`
		`+`
		`if __name__ == '__main__':`
		`# Run isolated`
		`# -s for DEBUG mode`

src/lib389/lib389/__init__.py

file modified

+5 -1

		`@@ -3123,7 +3123,11 @@`
		`self.stop()`
		`for log in glob.glob(logtype + "*"):`
		`if os.path.isfile(log):`
		`- os.remove(log)`
		`+ try:`
		`+ os.remove(log)`
		`+ except:`
		`+ self.log.info("deleteLog: fail to remove %s", log)`
		`+ pass`
		`if restart:`
		`self.start()`

sgouvern commented 5 years ago

Bug Description:
When a search fails because it requests more than one empty attribute,
the search base DN is always logged as "(null)".

Fix Description:
The search base DN for the failed search request is logged.
This commit include the automated test to verify the correct behavior.

Fixes https://pagure.io/389-ds-base/issue/50428
Relates: https://pagure.io/389-ds-base/issue/49969

Author: Sylvie Gouverneyre

Reviewed by: Viktor Ashirov, Simon Pichugin, Thierry Bordaz

spichugi commented on line 35 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

We're trying to avoid using pure DSLdapObject because it is more explicit and optimal to use the exact objects that represent the entity.
Here, you can set -

from lib389.idm.domain import Domain
entry = Domain(topology_st.standalone, DEFAULT_SUFFIX)

Edited 5 years ago by spichugi

spichugi commented on line 34 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

I think it makes sense to clean the accesslog because you are looking for a basic thing to appear - (r'.*SRCH base="{}".*'.format(DEFAULT_SUFFIX). And it's very possible that previous tests could affect it.
It can be done like this - topo.deleteAccessLogs()

spichugi commented 5 years ago

Could you also, please, fix the previous test's finalization?
If I run the whole test suite, your test case fails because of the previous test function (test_etime_at_border_of_second). It has stopped the instance and then it didn't resume.
You can put it to try: finally: block, I think.

Otherwise, it's a very nice and smooth test case! Thanks!

Edited 5 years ago by spichugi

spichugi commented 5 years ago

Also, we refer the upstream issue in commit messages.

So please, replace the Bugzilla link with this
https://pagure.io/389-ds-base/issue/50428

vashirov commented 5 years ago

We're trying to avoid using pure DSLdapObject because it is more explicit and optimal to use the exact objects that represent the entity.

Since when we're trying to avoid to use it? Entry was frowned upon, but not DSLdapObject.
Morover, Domain is DSLdapObject. The point of the test case is to do a search on any entry, not domain specifically, but with a list of empty attributes. So any class that inherits
DSLdapObject would do including DSLdapObject itself.

tbordaz commented on line 40 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

A minor point.
You may comment that this protocol error is a consequence of https://pagure.io/389-ds-base/issue/49969.
A search request containing more than one empty attribute fails with protocol error.

sgouvern commented 5 years ago

Thanks for your comments, working on it.

spichugi commented 5 years ago

Since when we're trying to avoid to use it? Entry was frowned upon, but not DSLdapObject.
Morover, Domain is DSLdapObject. The point of the test case is to do a search on any entry, not domain specifically, but with a list of empty attributes. So any class that inherits
DSLdapObject would do including DSLdapObject itself.

I agree. Please, note that I mentioned pure DSLdapObject. She has decided to search a Domain - we have an object for that and I gave the example. :)

Edited 5 years ago by spichugi

rebased onto efa244d87585f5dbf4d8f9cd992d5dcb99fc2cc3

5 years ago

sgouvern commented 5 years ago

Changes are done, could you please review.

spichugi commented on line 27 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

There is a second block of code:

# be sure to analyze only the following rapid OPs
topo.stop()
os.remove(topo.accesslog)
topo.start()

It also has the 'stop()' part which can affect the next test case execution in case os.remove(topo.accesslog) fails.

As an option, you can write a small fixture here (scope="function"). And ensure the instance is in the right state.

spichugi commented on line 58 of dirsrvtests/tests/suites/ds_logs/ds_logs_test.py 5 years ago

Could you please comment why have you decided not to use Domain object as I suggested?..

sgouvern commented 5 years ago

I agree that it's more explicit to use the exact object of an entity, and that it should preferably be used. Precisely in this case, I preferred not to use Domain object because the objective of the test is to check the logs registered after a search with invalid attributes, whatever the nature of the object searched is. I chose to use a domain for convenience, but I feel in this specific case it could be misleading to insist on the nature of the object as being a domain, because it could make lose sight on the generic scope of the test.

sgouvern commented 5 years ago

I didn't noticed the possible impact of a failure of os.remove(topo.accesslog) in the previous test_etime_at_border_of_second test. I'm going to rework on this test to securise its impact, as you suggest.
Thanks for pointing that !

rebased onto 790edfd17a42dd5987659351595dcf38900577c2

5 years ago

sgouvern commented 5 years ago

Changes done. Could you please review, thanks.

tbordaz commented 5 years ago

It looks good to me. Let's wait for @spichugi and @vashirov final point.

spichugi commented 5 years ago

LGTM! Thanks!

sgouvern commented 5 years ago

Thank you all for your reviews !

rebased onto 8365205ac20f49c61fb8ea8aa4a57dc36c794120

5 years ago

sgouvern commented 5 years ago

With Viktor's review, and after falling in failures when running the test suite, it appeared that the whole suite needs be improved to be more robust.
Commit Description:
The search base DN for the failed search request is logged.
This commit include the automated test to verify the correct behavior.
It includes as well changes to make the whole test suite more robust:
.adding the clean_access_logs fixture to make sure the state left by a test doesn't affect the others
.using this fixture in relevant tests
.adding the xfail mark for relevant tests
.fixing test_internal_log_server_level_4 for it to restore the default log level config before ending in case of failure, to avoid to affect the next test cases
.Handling a possible failure in removing a log file in lib389 deleteLog function

Could you please review (again !) these changes ? Thanks for your patience !

rebased onto e89c717540a39a57e422b1c6d9005a2059b7b889

5 years ago

rebased onto bd3b6f536a9b82bf207aed893b2bed194c431818

5 years ago

rebased onto cbcf26265642400a92e55f263f31f38ba4b7d1dc

5 years ago

vashirov commented on line 2 of src/lib389/lib389/__init__.py 5 years ago

This shouldn't be uncommented.

vashirov commented on line 13 of src/lib389/lib389/__init__.py 5 years ago

I get an error here:

ImportError while loading conftest '/mnt/tests/rhds/tests/upstream/ds/dirsrvtests/conftest.py'.
dirsrvtests/conftest.py:8: in <module>
    from lib389.paths import Paths
E     File "/mnt/tests/rhds/tests/upstream/ds/src/lib389/lib389/__init__.py", line 3126
E       try:
E          ^
E   TabError: inconsistent use of tabs and spaces in indentation

rebased onto 49177819df514fd4bdbebb8dbe66a709fe9f9804

5 years ago

rebased onto 2f5daa7

5 years ago

sgouvern commented 5 years ago

I fixed the comment and indentation problem.
Could you please review.

vashirov commented 5 years ago

Thank you, Sylvie! Everything works now. Ack.