diff --git a/dirsrvtests/tests/suites/session_tracking/session_test.py b/dirsrvtests/tests/suites/session_tracking/session_test.py new file mode 100644 index 0000000000..10d700ad7e --- /dev/null +++ b/dirsrvtests/tests/suites/session_tracking/session_test.py @@ -0,0 +1,1164 @@ +# --- BEGIN COPYRIGHT BLOCK --- +# Copyright (C) 2024 RED Hat, Inc. +# All rights reserved. +# +# License: GPL (version 3 or any later version). +# See LICENSE for details. +# --- END COPYRIGHT BLOCK ---- + +import pytest, os, re, time +import pdb +from lib389.tasks import * +from lib389.utils import * +from lib389 import Entry +from ldap import SCOPE_SUBTREE, ALREADY_EXISTS +from ldap.controls import SimplePagedResultsControl +from ldap.controls.sessiontrack import SessionTrackingControl, SESSION_TRACKING_CONTROL_OID +from ldap.extop import ExtendedRequest + +from lib389._constants import DEFAULT_SUFFIX, PW_DM, PLUGIN_MEMBER_OF +from lib389.topologies import topology_st +from lib389.plugins import MemberOfPlugin + +from lib389.schema import Schema +from lib389.idm.user import UserAccount, UserAccounts +from lib389.idm.account import Accounts +from lib389.idm.account import Anonymous + +SESSION_SOURCE_IP = '10.0.0.10' +SESSION_SOURCE_NAME = 'host.example.com' +SESSION_TRACKING_FORMAT_OID = SESSION_TRACKING_CONTROL_OID + ".1234" + +pytestmark = pytest.mark.tier0 + +def test_short_session_tracking_srch(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during a search + + :id: c9efc1cc-03c7-42b7-801c-440f7a11ee13 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Do a search with a short session tracking string + 2. Restart the instance to flush the log + 3. Check the exact same string is present in the access log + :expectedresults: + 1. Search should succeed + 2. success + 3. Log should contain one log with that session + """ + + + SESSION_TRACKING_IDENTIFIER = "SRCH short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + topology_st.standalone.search_ext_s(DEFAULT_SUFFIX, + ldap.SCOPE_SUBTREE, + '(uid=*)', + serverctrls=[st_ctrl]) + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=101.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + pass + + request.addfinalizer(fin) + +def test_short_session_tracking_add(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during a add + + :id: 04afd3de-365e-485f-9e00-913d913af931 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry with a short session tracking + 2. Restart the instance to flush the log + 3. Check the exact same string is present in the access log + :expectedresults: + 1. Add should succeed + 2. success + 3. Log should contain one log with that session + """ + + + SESSION_TRACKING_IDENTIFIER = "ADD short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_add," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_add'), + ('cn', b'test_add'), + ('userPassword', b'test_add'), + ], + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_short_session_tracking_del(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during a del + + :id: a1391fbc-2107-4474-aaaf-088c393767a6 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. Delete the test entry with a short session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the DEL + :expectedresults: + 1. Add should succeed + 2. DEL should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the DEL + """ + + + SESSION_TRACKING_IDENTIFIER = "DEL short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_del," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_del'), + ('cn', b'test_del'), + ('userPassword', b'test_del'), + ]) + topology_st.standalone.delete_ext_s(TEST_DN, + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=107.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_short_session_tracking_mod(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during a MOD + + :id: 00c91efc-071d-4187-8185-6cca27b5bf63 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. Modify the test entry with a short session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the MOD + :expectedresults: + 1. Add should succeed + 2. Mod should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the MOD + """ + + + SESSION_TRACKING_IDENTIFIER = "MOD short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_mod," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_del'), + ('cn', b'test_del'), + ('userPassword', b'test_del'), + ]) + topology_st.standalone.modify_ext_s(TEST_DN, + [(ldap.MOD_REPLACE, 'sn', b'new_sn')], + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=103.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_short_session_tracking_compare(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during a compare + + :id: 6f2090fd-a960-48e5-b7f1-04ddef4a85af + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. compare an attribute with a short session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the COMPARE + :expectedresults: + 1. Add should succeed + 2. Compare should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the COMPARE + """ + + + SESSION_TRACKING_IDENTIFIER = "COMPARE short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_compare," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_compare'), + ('cn', b'test_compare'), + ('userPassword', b'test_compare'), + ]) + topology_st.standalone.compare_ext_s(TEST_DN, 'sn', b'test_compare', serverctrls=[st_ctrl]) + topology_st.standalone.compare_ext_s(TEST_DN, 'sn', b'test_fail_compare', serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*err=6 tag=111.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*err=5 tag=111.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_short_session_tracking_abandon(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during an abandon + + :id: 58f54ada-e05c-411b-a1c6-8b19fd99843c + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add 10 test entries + 2. Launch Page Search with a window of 3 + 3. Abandon the Page Search with a short session tracking + 4. Restart the instance to flush the log + 5. Check the exact same string is not present in the access log for the ADD + 6. Check the exact same string is present in the access log for the ABANDON + :expectedresults: + 1. Add should succeed + 2. success + 3. success + 4. success + 5. Log should not contain log with that session for the ADDs + 6. Log should contain one log with that session for the abandon + """ + + SESSION_TRACKING_IDENTIFIER = "ABANDON short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + # provision more entries than the page search will fetch + entries = [] + for i in range(10): + TEST_DN = "cn=test_abandon_%d,%s" % (i, DEFAULT_SUFFIX) + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_abandon'), + ('cn', b'test_abandon_%d' % i), + ('userPassword', b'test_abandon'), + ]) + entries.append(TEST_DN) + + # run a page search (with the session) using a small window. So we can abandon it. + req_ctrl = SimplePagedResultsControl(True, size=3, cookie='') + msgid = topology_st.standalone.search_ext(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, r'(objectclass=*)', ['cn'], serverctrls=[req_ctrl]) + time.sleep(1) + topology_st.standalone.abandon_ext(msgid, serverctrls=[st_ctrl]) + + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*ABANDON.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + for ent in entries: + try: + topology_st.standalone.delete_s(ent) + except: + pass + + request.addfinalizer(fin) + +def test_short_session_tracking_extop(topology_st, request): + """Verify that a short session_tracking string + is added (not truncate) during an extended operation + + :id: 65c2d014-d798-46f3-8168-b6f56b43d069 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. run whoami extop + 2. Check the exact same string is present in the access log for the EXTOP + :expectedresults: + 1. success + 2. Log should contain one log with that session for the EXTOP + """ + SESSION_TRACKING_IDENTIFIER = "Extop short" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + extop = ExtendedRequest(requestName = '1.3.6.1.4.1.4203.1.11.3', requestValue=None) + (oid_response, res) = topology_st.standalone.extop_s(extop, serverctrls=[st_ctrl]) + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=120.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_srch(topology_st, request): + """Verify that a exact max length session_tracking string + is added (not truncate) during a search + + :id: 2c8c86f9-4896-4ccc-a727-6a4033f6f44a + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Do a search with a exact max length session tracking string + 2. Restart the instance to flush the log + 3. Check the exact same string is present in the access log (without '.') + :expectedresults: + 1. Search should succeed + 2. success + 3. Log should contain one log with that session + """ + + + SESSION_TRACKING_IDENTIFIER = "SRCH long ---->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + topology_st.standalone.search_ext_s(DEFAULT_SUFFIX, + ldap.SCOPE_SUBTREE, + '(uid=*)', + serverctrls=[st_ctrl]) + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=101.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_add(topology_st, request): + """Verify that a exact max length of session_tracking string + is added (not truncate) during a add + + :id: 41c0b4f3-5e75-404b-98af-98cc98b742c7 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry with a exact max lenght (15) session tracking + 2. Restart the instance to flush the log + 3. Check the exact same string is present in the access log + :expectedresults: + 1. Add should succeed + 2. success + 3. Log should contain one log with that session + """ + + + SESSION_TRACKING_IDENTIFIER = "ADD long ----->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_add," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_add'), + ('cn', b'test_add'), + ('userPassword', b'test_add'), + ], + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_del(topology_st, request): + """Verify that a exact max lgth session_tracking string + is added (not truncate) during a del + + :id: b8dca6c9-7cd4-4950-bcb5-7e9e6bb9202f + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. Delete the test entry with a exact max length (15) session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the DEL + :expectedresults: + 1. Add should succeed + 2. DEL should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the DEL + """ + + + SESSION_TRACKING_IDENTIFIER = "DEL long ----->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_del," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_del'), + ('cn', b'test_del'), + ('userPassword', b'test_del'), + ]) + topology_st.standalone.delete_ext_s(TEST_DN, + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=107.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_mod(topology_st, request): + """Verify that an exact max length session_tracking string + is added (not truncate) during a MOD + + :id: 3bd1205f-a035-48a7-94c2-f8774e24ae91 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. Modify the test entry with an exact max length (15) session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the MOD + :expectedresults: + 1. Add should succeed + 2. Mod should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the MOD + """ + + + SESSION_TRACKING_IDENTIFIER = "MOD long ----->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_mod," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_del'), + ('cn', b'test_del'), + ('userPassword', b'test_del'), + ]) + topology_st.standalone.modify_ext_s(TEST_DN, + [(ldap.MOD_REPLACE, 'sn', b'new_sn')], + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=103.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_compare(topology_st, request): + """Verify that an exact max length session_tracking string + is added (not truncate) during a compare + + :id: a6c8ad60-7edb-4ee4-b0e3-06727870687c + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. compare an attribute with an exact max length session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the COMPARE + :expectedresults: + 1. Add should succeed + 2. Compare should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the COMPARE + """ + + + SESSION_TRACKING_IDENTIFIER = "COMPARE long ->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_compare," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_compare'), + ('cn', b'test_compare'), + ('userPassword', b'test_compare'), + ]) + topology_st.standalone.compare_ext_s(TEST_DN, 'sn', b'test_compare', serverctrls=[st_ctrl]) + topology_st.standalone.compare_ext_s(TEST_DN, 'sn', b'test_fail_compare', serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*err=6 tag=111.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*err=5 tag=111.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_abandon(topology_st, request): + """Verify that an exact max length session_tracking string + is added (not truncate) during an abandon + + :id: 708554b9-8403-411c-90b5-d9ecc2d3830f + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add 10 test entries + 2. Launch Page Search with a window of 3 + 3. Abandon the Page Search with an exact max length session tracking + 4. Restart the instance to flush the log + 5. Check the exact same string is not present in the access log for the ADD + 6. Check the exact same string is present in the access log for the ABANDON + :expectedresults: + 1. Add should succeed + 2. success + 3. success + 4. success + 5. Log should not contain log with that session for the ADDs + 6. Log should contain one log with that session for the abandon + """ + + SESSION_TRACKING_IDENTIFIER = "ABANDON long ->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + # provision more entries than the page search will fetch + entries = [] + for i in range(10): + TEST_DN = "cn=test_abandon_%d,%s" % (i, DEFAULT_SUFFIX) + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_abandon'), + ('cn', b'test_abandon_%d' % i), + ('userPassword', b'test_abandon'), + ]) + entries.append(TEST_DN) + + # run a page search (with the session) using a small window. So we can abandon it. + req_ctrl = SimplePagedResultsControl(True, size=3, cookie='') + msgid = topology_st.standalone.search_ext(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, r'(objectclass=*)', ['cn'], serverctrls=[req_ctrl]) + time.sleep(1) + topology_st.standalone.abandon_ext(msgid, serverctrls=[st_ctrl]) + + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*ABANDON.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + for ent in entries: + try: + topology_st.standalone.delete_s(ent) + except: + pass + + request.addfinalizer(fin) + +def test_exact_max_lgth_session_tracking_extop(topology_st, request): + """Verify that an exact max length session_tracking string + is added (not truncate) during an extended operation + + :id: 078d33c4-9124-4766-966e-2e3eebdf0e18 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. run whoami extop + 2. Check the exact same string (max length 15) + is present in the access log for the EXTOP + :expectedresults: + 1. success + 2. Log should contain one log with that session for the EXTOP + """ + SESSION_TRACKING_IDENTIFIER = "Extop long --->" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + extop = ExtendedRequest(requestName = '1.3.6.1.4.1.4203.1.11.3', requestValue=None) + (oid_response, res) = topology_st.standalone.extop_s(extop, serverctrls=[st_ctrl]) + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=120.* sid="%s".*' % SESSION_TRACKING_IDENTIFIER) + assert len(access_log_lines) == 1 + + def fin(): + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_srch(topology_st, request): + """Verify that a long session_tracking string + is added (truncate) during a search + + :id: 56118d13-c0b1-401f-aaa4-6dc233156e36 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Do a search with a long session tracking string + 2. Restart the instance to flush the log + 3. Check the exact same string is present in the access log (with '.') + :expectedresults: + 1. Search should succeed + 2. success + 3. Log should contain one log with that session + """ + + + SESSION_TRACKING_IDENTIFIER_MAX = "SRCH long ---->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + topology_st.standalone.search_ext_s(DEFAULT_SUFFIX, + ldap.SCOPE_SUBTREE, + '(uid=*)', + serverctrls=[st_ctrl]) + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=101.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_add(topology_st, request): + """Verify that a long session_tracking string + is added (truncate) during a add + + :id: ac97bc6b-f2c5-41e2-9ab6-df05afb2757c + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry with a long session tracking + 2. Restart the instance to flush the log + 3. Check the exact same string is present in the access log (with '.') + :expectedresults: + 1. Add should succeed + 2. success + 3. Log should contain one log with that session + """ + + + SESSION_TRACKING_IDENTIFIER_MAX = "ADD long ----->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_add," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_add'), + ('cn', b'test_add'), + ('userPassword', b'test_add'), + ], + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_del(topology_st, request): + """Verify that a long session_tracking string + is added (truncate) during a del + + :id: 283152b8-ba6b-4153-b2de-17070911bf18 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. Delete the test entry with a long session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the DEL (with '.') + :expectedresults: + 1. Add should succeed + 2. DEL should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the DEL + """ + + + SESSION_TRACKING_IDENTIFIER_MAX = "DEL long ----->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_del," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_del'), + ('cn', b'test_del'), + ('userPassword', b'test_del'), + ]) + topology_st.standalone.delete_ext_s(TEST_DN, + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=107.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_mod(topology_st, request): + """Verify that a long session_tracking string + is added (truncate) during a MOD + + :id: 6bfcca4b-40b4-4288-9b77-cfa0d4f15c14 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. Modify the test entry with an long session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the MOD (with '.') + :expectedresults: + 1. Add should succeed + 2. Mod should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the MOD + """ + + + SESSION_TRACKING_IDENTIFIER_MAX = "MOD long ----->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_mod," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_del'), + ('cn', b'test_del'), + ('userPassword', b'test_del'), + ]) + topology_st.standalone.modify_ext_s(TEST_DN, + [(ldap.MOD_REPLACE, 'sn', b'new_sn')], + serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=103.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_compare(topology_st, request): + """Verify that a long session_tracking string + is added (truncate) during a compare + + :id: 840ad60b-d2c5-4375-a50d-1553701d3c22 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add a test entry + 2. compare an attribute with an exact max length session tracking + 3. Restart the instance to flush the log + 4. Check the exact same string is not present in the access log for the ADD + 5. Check the exact same string is present in the access log for the COMPARE (with '.') + :expectedresults: + 1. Add should succeed + 2. Compare should succeed + 3. success + 4. Log should not contain a log with that session for the ADD + 5. Log should contain one log with that session for the COMPARE + """ + + + SESSION_TRACKING_IDENTIFIER_MAX = "COMPARE long ->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + TEST_DN = "cn=test_compare," + DEFAULT_SUFFIX + try: + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_compare'), + ('cn', b'test_compare'), + ('userPassword', b'test_compare'), + ]) + topology_st.standalone.compare_ext_s(TEST_DN, 'sn', b'test_compare', serverctrls=[st_ctrl]) + topology_st.standalone.compare_ext_s(TEST_DN, 'sn', b'test_fail_compare', serverctrls=[st_ctrl]) + except ldap.LDAPError as e: + log.fatal('Failed to add user1 entry, error: ' + e.message['desc']) + assert False + + topology_st.standalone.restart(timeout=10) + + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*err=6 tag=111.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*err=5 tag=111.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + try: + topology_st.standalone.delete_s(TEST_DN) + except: + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_abandon(topology_st, request): + """Verify that long session_tracking string + is added (truncate) during an abandon + + :id: bded1fbb-b123-42c5-8d28-9fcf9f19af94 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. Add 10 test entries + 2. Launch Page Search with a window of 3 + 3. Abandon the Page Search with long session tracking + 4. Restart the instance to flush the log + 5. Check the exact same string is not present in the access log for the ADD + 6. Check the exact same string is present in the access log for the ABANDON (with '.') + :expectedresults: + 1. Add should succeed + 2. success + 3. success + 4. success + 5. Log should not contain log with that session for the ADDs + 6. Log should contain one log with that session for the abandon + """ + + SESSION_TRACKING_IDENTIFIER_MAX = "ABANDON long ->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + # provision more entries than the page search will fetch + entries = [] + for i in range(10): + TEST_DN = "cn=test_abandon_%d,%s" % (i, DEFAULT_SUFFIX) + ent = topology_st.standalone.add_ext_s(TEST_DN, + [ + ('objectClass', b'person'), + ('sn', b'test_abandon'), + ('cn', b'test_abandon_%d' % i), + ('userPassword', b'test_abandon'), + ]) + entries.append(TEST_DN) + + # run a page search (with the session) using a small window. So we can abandon it. + req_ctrl = SimplePagedResultsControl(True, size=3, cookie='') + msgid = topology_st.standalone.search_ext(DEFAULT_SUFFIX, ldap.SCOPE_SUBTREE, r'(objectclass=*)', ['cn'], serverctrls=[req_ctrl]) + time.sleep(1) + topology_st.standalone.abandon_ext(msgid, serverctrls=[st_ctrl]) + + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=105.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 0 + + access_log_lines = topology_st.standalone.ds_access_log.match('.*ABANDON.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + for ent in entries: + try: + topology_st.standalone.delete_s(ent) + except: + pass + + request.addfinalizer(fin) + +def test_long_session_tracking_extop(topology_st, request): + """Verify that long session_tracking string + is added (truncate) during an extended operation + + :id: a7aa65d2-eed8-4bdd-9786-2379997ff0b7 + :customerscenario: False + :setup: Standalone instance, default backend + :steps: + 1. run whoami extop + 2. Check the truncated long session string + is present in the access log for the EXTOP + :expectedresults: + 1. success + 2. Log should contain one log with that session for the EXTOP + """ + SESSION_TRACKING_IDENTIFIER_MAX = "Extop long --->" + SESSION_TRACKING_IDENTIFIER = SESSION_TRACKING_IDENTIFIER_MAX + "xxxxxxxx" + st_ctrl = SessionTrackingControl( + SESSION_SOURCE_IP, + SESSION_SOURCE_NAME, + SESSION_TRACKING_FORMAT_OID, + SESSION_TRACKING_IDENTIFIER + ) + + extop = ExtendedRequest(requestName = '1.3.6.1.4.1.4203.1.11.3', requestValue=None) + (oid_response, res) = topology_st.standalone.extop_s(extop, serverctrls=[st_ctrl]) + + topology_st.standalone.restart(timeout=10) + access_log_lines = topology_st.standalone.ds_access_log.match('.*tag=120.* sid="%s...".*' % SESSION_TRACKING_IDENTIFIER_MAX) + assert len(access_log_lines) == 1 + + def fin(): + pass + + request.addfinalizer(fin) + +if __name__ == "__main__": + CURRENT_FILE = os.path.realpath(__file__) + pytest.main("-s -v %s" % CURRENT_FILE) diff --git a/ldap/servers/slapd/abandon.c b/ldap/servers/slapd/abandon.c index 2dd1ee3205..6818bb11b5 100644 --- a/ldap/servers/slapd/abandon.c +++ b/ldap/servers/slapd/abandon.c @@ -38,6 +38,13 @@ do_abandon(Slapi_PBlock *pb) Connection *pb_conn = NULL; Operation *pb_op = NULL; Operation *o; + char *sessionTrackingId; + /* Should fit + * - ~10chars for ' sid=\"..\"' + * - 15+3 for the truncated sessionID + * Need to sync with SESSION_ID_STR_SZ + */ + char session_str[30] = {0}; /* Keep a copy of some data because o may vanish once conn is unlocked */ struct { struct timespec hr_time_end; @@ -87,6 +94,25 @@ do_abandon(Slapi_PBlock *pb) slapi_log_err(SLAPI_LOG_ARGS, "do_abandon", "id %d\n", id); + slapi_pblock_get(pb, SLAPI_SESSION_TRACKING, &sessionTrackingId); + + /* prepare session_str to be logged */ + if (sessionTrackingId) { + if (sizeof(session_str) < (strlen(sessionTrackingId) + 10 + 1)) { + /* The session tracking string is too large to fit in 'session_str' + * Likely SESSION_ID_STR_SZ was changed without increasing the size of session_str. + * Just ignore the session string. + */ + session_str[0] = '\0'; + slapi_log_err(SLAPI_LOG_ERR, "do_abandon", "Too large session tracking string (%ld) - It is ignored\n", + strlen(sessionTrackingId)); + } else { + snprintf(session_str, sizeof(session_str), " sid=\"%s\"", sessionTrackingId); + } + } else { + session_str[0] = '\0'; + } + /* * find the operation being abandoned and set the o_abandon * flag. We don't allow the operation to abandon itself. @@ -143,21 +169,22 @@ do_abandon(Slapi_PBlock *pb) pthread_mutex_unlock(&(pb_conn->c_mutex)); if (0 == pagedresults_free_one_msgid(pb_conn, id, pageresult_lock_get_addr(pb_conn))) { slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 - " op=%d ABANDON targetop=Simple Paged Results msgid=%d\n", - pb_conn->c_connid, pb_op->o_opid, id); + " op=%d ABANDON targetop=Simple Paged Results msgid=%d%s\n", + pb_conn->c_connid, pb_op->o_opid, id, session_str); } else if (NULL == o) { slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 " op=%d ABANDON" - " targetop=NOTFOUND msgid=%d\n", - pb_conn->c_connid, pb_op->o_opid, id); + " targetop=NOTFOUND msgid=%d%s\n", + pb_conn->c_connid, pb_op->o_opid, id, session_str); } else if (suppressed_by_plugin) { slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 " op=%d ABANDON" - " targetop=SUPPRESSED-BY-PLUGIN msgid=%d\n", - pb_conn->c_connid, pb_op->o_opid, id); + " targetop=SUPPRESSED-BY-PLUGIN msgid=%d%s\n", + pb_conn->c_connid, pb_op->o_opid, id, session_str); } else { slapi_log_access(LDAP_DEBUG_STATS, "conn=%" PRIu64 " op=%d ABANDON" - " targetop=%d msgid=%d nentries=%d etime=%" PRId64 ".%010" PRId64 "\n", + " targetop=%d msgid=%d nentries=%d etime=%" PRId64 ".%010" PRId64 "%s\n", pb_conn->c_connid, pb_op->o_opid, o_copy.opid, id, - o_copy.nentries, (int64_t)o_copy.hr_time_end.tv_sec, (int64_t)o_copy.hr_time_end.tv_nsec); + o_copy.nentries, (int64_t)o_copy.hr_time_end.tv_sec, (int64_t)o_copy.hr_time_end.tv_nsec, + session_str); } /* * Wake up the persistent searches, so they diff --git a/ldap/servers/slapd/control.c b/ldap/servers/slapd/control.c index dd5c2f9ab9..2ada033762 100644 --- a/ldap/servers/slapd/control.c +++ b/ldap/servers/slapd/control.c @@ -91,6 +91,10 @@ init_controls(void) /* LDAP_CONTROL_PAGEDRESULTS is shared by request and response */ slapi_register_supported_control(LDAP_CONTROL_PAGEDRESULTS, SLAPI_OPERATION_SEARCH); + + /* LDAP_CONTROL_X_SESSION_TRACKING only supported by request */ + slapi_register_supported_control(LDAP_CONTROL_X_SESSION_TRACKING, + SLAPI_OPERATION_BIND | SLAPI_OPERATION_UNBIND | SLAPI_OPERATION_ABANDON | SLAPI_OPERATION_EXTENDED | SLAPI_OPERATION_SEARCH | SLAPI_OPERATION_COMPARE | SLAPI_OPERATION_ADD | SLAPI_OPERATION_DELETE | SLAPI_OPERATION_MODIFY | SLAPI_OPERATION_MODDN); } @@ -162,6 +166,124 @@ slapi_get_supported_controls_copy(char ***ctrloidsp, unsigned long **ctrlopsp) return (0); } +/* Parse the Session Tracking control + * see https://datatracker.ietf.org/doc/html/draft-wahl-ldap-session-03 + * LDAPString ::= OCTET STRING -- UTF-8 encoded + * LDAPOID ::= OCTET STRING -- Constrained to numericoid + * + * SessionIdentifierControlValue ::= SEQUENCE { + * sessionSourceIp LDAPString, + * sessionSourceName LDAPString, + * formatOID LDAPOID, + * sessionTrackingIdentifier LDAPString + * } + * + * design https://www.port389.org/docs/389ds/design/session-identifier-in-logs.html + * + * It extracts the 15 first chars from sessionTrackingIdentifier (escaped) + * and return them in session_tracking_id (allocated buffer) + * The caller is responsible of the free of session_tracking_id + */ +static int +parse_sessiontracking_ctrl(struct berval *session_tracking_spec, char **session_tracking_id) +{ + BerElement *ber = NULL; + ber_tag_t ber_rc; + struct berval sessionSourceIp = {0}; + struct berval sessionSourceName = {0}; + struct berval formatOID = {0}; + struct berval sessionTrackingIdentifier = {0}; +#define SESSION_ID_STR_SZ 15 +#define NB_DOTS 3 + char buf_sid_orig[SESSION_ID_STR_SZ + 2] = {0}; + int32_t sid_orig_sz; /* size of the original sid that we retain */ + const char *buf_sid_escaped; + int32_t sid_escaped_sz; /* size of the escaped sid that we retain */ + char buf[BUFSIZ]; + char *sid; + int rc = LDAP_SUCCESS; + + if (!BV_HAS_DATA(session_tracking_spec)) { + return LDAP_PROTOCOL_ERROR; + } + ber = ber_init(session_tracking_spec); + if ((ber == NULL) || (session_tracking_id == NULL)) { + return LDAP_OPERATIONS_ERROR; + } + + *session_tracking_id = NULL; + + /* Get the sessionSourceIp but discard it as we are not using it */ + ber_rc = ber_scanf(ber, "{o", &sessionSourceIp); + if ((ber_rc == LBER_ERROR) || (sessionSourceIp.bv_len > 128)) { + rc = LDAP_PROTOCOL_ERROR; + goto free_and_return; + } + slapi_ch_free_string(&sessionSourceIp.bv_val); /* discard the value anyway */ + + /* Get sessionSourceName but discard it as we are not using it */ + ber_rc = ber_scanf(ber, "o", &sessionSourceName); + if ((ber_rc == LBER_ERROR) || (sessionSourceName.bv_len > 65536)) { + rc = LDAP_PROTOCOL_ERROR; + goto free_and_return; + } + slapi_ch_free_string(&sessionSourceIp.bv_val); /* discard the value anyway */ + + /* Get formatOID but discard it as we are not using it */ + ber_rc = ber_scanf(ber, "o", &formatOID); + if ((ber_rc == LBER_ERROR) || (formatOID.bv_len > 1024) || (formatOID.bv_len == 0)) { + rc = LDAP_PROTOCOL_ERROR; + goto free_and_return; + } + slapi_ch_free_string(&formatOID.bv_val); /* discard the value anyway */ + + /* Get sessionTrackingIdentifier and truncate it if needed */ + ber_rc = ber_scanf(ber, "o}", &sessionTrackingIdentifier); + if ((ber_rc == LBER_ERROR) || (sessionTrackingIdentifier.bv_len > 65536)) { + rc = LDAP_PROTOCOL_ERROR; + goto free_and_return; + } + + /* Make sure the interesting part of the provided SID is escaped */ + if (sessionTrackingIdentifier.bv_len > SESSION_ID_STR_SZ) { + sid_orig_sz = SESSION_ID_STR_SZ + 1; + } else { + sid_orig_sz = sessionTrackingIdentifier.bv_len; + memcpy(buf_sid_orig, sessionTrackingIdentifier.bv_val, sessionTrackingIdentifier.bv_len); + } + memcpy(buf_sid_orig, sessionTrackingIdentifier.bv_val, sid_orig_sz); + buf_sid_escaped = escape_string(buf_sid_orig, buf); + + /* Allocate the buffer that contains the heading portion + * of the escaped SID + */ + sid_escaped_sz = strlen(buf_sid_escaped); + if (sid_escaped_sz > SESSION_ID_STR_SZ) { + /* Take only a portion of it plus some '.' */ + sid_escaped_sz = SESSION_ID_STR_SZ + NB_DOTS; + } + sid = (char *) slapi_ch_calloc(1, sid_escaped_sz + 1); + + /* Lets copy the escaped SID into the buffer */ + if (sid_escaped_sz > SESSION_ID_STR_SZ) { + memcpy(sid, buf_sid_escaped, SESSION_ID_STR_SZ); + memset(sid + SESSION_ID_STR_SZ, '.', NB_DOTS); /* ending the string with "..." */ + } else { + memcpy(sid, buf_sid_escaped, sid_escaped_sz); + } + + *session_tracking_id = sid; + return rc; + +free_and_return: + slapi_ch_free_string(&sessionSourceIp.bv_val); + slapi_ch_free_string(&sessionSourceName.bv_val); + slapi_ch_free_string(&formatOID.bv_val); + slapi_ch_free_string(&sessionTrackingIdentifier.bv_val); + + return rc; +} + /* * RFC 4511 section 4.1.11. Controls says that the UnbindRequest * MUST ignore the criticality field of controls @@ -346,9 +468,16 @@ get_ldapmessage_controls_ext( slapi_pblock_set(pb, SLAPI_REQCONTROLS, NULL); slapi_pblock_set(pb, SLAPI_MANAGEDSAIT, &ctrl_not_found); slapi_pblock_set(pb, SLAPI_PWPOLICY, &ctrl_not_found); + slapi_pblock_set(pb, SLAPI_SESSION_TRACKING, NULL); slapi_log_err(SLAPI_LOG_CONNS, "get_ldapmessage_controls_ext", "Warning: conn=%" PRIu64 " op=%d contains an empty list of controls\n", pb_conn ? pb_conn->c_connid : -1, pb_op ? pb_op->o_opid : -1); } else { + struct berval *session_tracking_spec = NULL; + int iscritical = 0; + char *session_tracking_id = NULL; + char *old_sid; + int parse_rc = 0; + /* len, ber_len_t is uint, not int, cannot be != -1, may be better to remove this check. */ if ((tag != LBER_END_OF_SEQORSET) && (len != -1)) { goto free_and_return; @@ -358,6 +487,31 @@ get_ldapmessage_controls_ext( managedsait = slapi_control_present(ctrls, LDAP_CONTROL_MANAGEDSAIT, NULL, NULL); slapi_pblock_set(pb, SLAPI_MANAGEDSAIT, &managedsait); + if (slapi_control_present(ctrls, + LDAP_CONTROL_X_SESSION_TRACKING, &session_tracking_spec, &iscritical)) { + Operation *pb_op = NULL; + slapi_pblock_get(pb, SLAPI_OPERATION, &pb_op); + + if (iscritical) { + /* It must not be critical */ + slapi_log_err(SLAPI_LOG_ERR, "get_ldapmessage_controls_ext", "conn=%" PRIu64 " op=%d Does not support critical SessionTracking control\n", + pb_conn ? pb_conn->c_connid : -1, pb_op ? pb_op->o_opid : -1); + rc = LDAP_UNAVAILABLE_CRITICAL_EXTENSION; + goto free_and_return; + } + parse_rc = parse_sessiontracking_ctrl(session_tracking_spec, &session_tracking_id); + if (parse_rc != LDAP_SUCCESS) { + slapi_log_err(SLAPI_LOG_WARNING, "get_ldapmessage_controls_ext", "Warning: conn=%" PRIu64 " op=%d failed to parse SessionTracking control (%d)\n", + pb_conn ? pb_conn->c_connid : -1, pb_op ? pb_op->o_opid : -1, parse_rc); + slapi_ch_free_string(&session_tracking_id); + } else { + /* now replace the sid (if any) in the pblock */ + slapi_pblock_get(pb, SLAPI_SESSION_TRACKING, &old_sid); + slapi_ch_free_string(&old_sid); + slapi_pblock_set(pb, SLAPI_SESSION_TRACKING, session_tracking_id); + } + } + slapi_pblock_set(pb, SLAPI_SESSION_TRACKING, session_tracking_id); pwpolicy_ctrl = slapi_control_present(ctrls, LDAP_X_CONTROL_PWPOLICY_REQUEST, NULL, NULL); slapi_pblock_set(pb, SLAPI_PWPOLICY, &pwpolicy_ctrl); diff --git a/ldap/servers/slapd/pblock.c b/ldap/servers/slapd/pblock.c index 2357698373..0aedd70a6a 100644 --- a/ldap/servers/slapd/pblock.c +++ b/ldap/servers/slapd/pblock.c @@ -218,6 +218,7 @@ pblock_done(Slapi_PBlock *pb) if (pb->pb_intop != NULL) { delete_passwdPolicy(&pb->pb_intop->pwdpolicy); slapi_ch_free((void **)&(pb->pb_intop->pb_result_text)); + slapi_ch_free_string(&pb->pb_intop->pb_session_tracking_id); } slapi_ch_free((void **)&(pb->pb_intop)); if (pb->pb_intplugin != NULL) { @@ -1552,6 +1553,13 @@ slapi_pblock_get(Slapi_PBlock *pblock, int arg, void *value) (*(int *)value) = 0; } break; + case SLAPI_SESSION_TRACKING: + if (pblock->pb_intop != NULL) { + (*(char **)value) = pblock->pb_intop->pb_session_tracking_id; + } else { + (*(char **)value) = 0; + } + break; case SLAPI_PWPOLICY: if (pblock->pb_intop != NULL) { (*(int *)value) = pblock->pb_intop->pb_pwpolicy_ctrl; @@ -3484,6 +3492,10 @@ slapi_pblock_set(Slapi_PBlock *pblock, int arg, void *value) _pblock_assert_pb_intop(pblock); pblock->pb_intop->pb_managedsait = *((int *)value); break; + case SLAPI_SESSION_TRACKING: + _pblock_assert_pb_intop(pblock); + pblock->pb_intop->pb_session_tracking_id = (char *)value; + break; case SLAPI_PWPOLICY: _pblock_assert_pb_intop(pblock); pblock->pb_intop->pb_pwpolicy_ctrl = *((int *)value); diff --git a/ldap/servers/slapd/pblock_v3.h b/ldap/servers/slapd/pblock_v3.h index ef15ee457f..1b4996c48e 100644 --- a/ldap/servers/slapd/pblock_v3.h +++ b/ldap/servers/slapd/pblock_v3.h @@ -161,6 +161,9 @@ typedef struct _slapi_pblock_intop /* For password policy control */ int pb_pwpolicy_ctrl; + /* For Session Tracking control */ + char *pb_session_tracking_id; + int pb_paged_results_index; /* stash SLAPI_PAGED_RESULTS_INDEX */ int pb_paged_results_cookie; /* stash SLAPI_PAGED_RESULTS_COOKIE */ int32_t pb_usn_tombstone_incremented; /* stash SLAPI_PAGED_RESULTS_COOKIE */ diff --git a/ldap/servers/slapd/result.c b/ldap/servers/slapd/result.c index 97af5a2b83..7fb8517fb9 100644 --- a/ldap/servers/slapd/result.c +++ b/ldap/servers/slapd/result.c @@ -2153,10 +2153,35 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries int32_t op_internal_id; int32_t op_nested_count; struct timespec o_hr_time_end; + char *sessionTrackingId; + /* Should fit + * - ~10chars for ' sid=\"..\"' + * - 15+3 for the truncated sessionID + * Need to sync with SESSION_ID_STR_SZ + */ + char session_str[30] = {0}; get_internal_conn_op(&connid, &op_id, &op_internal_id, &op_nested_count); slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_INDEX, &pr_idx); slapi_pblock_get(pb, SLAPI_PAGED_RESULTS_COOKIE, &pr_cookie); + slapi_pblock_get(pb, SLAPI_SESSION_TRACKING, &sessionTrackingId); + + /* prepare session_str to be logged */ + if (sessionTrackingId) { + if (sizeof(session_str) < (strlen(sessionTrackingId) + 10 + 1)) { + /* The session tracking string is too large to fit in 'session_str' + * Likely SESSION_ID_STR_SZ was changed without increasing the size of session_str. + * Just ignore the session string. + */ + session_str[0] = '\0'; + slapi_log_err(SLAPI_LOG_ERR, "log_result", "Too large session tracking string (%ld) - It is ignored\n", + strlen(sessionTrackingId)); + } else { + snprintf(session_str, sizeof(session_str), " sid=\"%s\"", sessionTrackingId); + } + } else { + session_str[0] = '\0'; + } internal_op = operation_is_flag_set(op, OP_FLAG_INTERNAL); /* total elapsed time */ @@ -2202,16 +2227,16 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries if (!internal_op) { 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" + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" ", SASL bind in progress\n", op->o_connid, op->o_opid, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str); + notes_str, csn_str, session_str); } else { -#define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s, SASL bind in progress\n" +#define LOG_SASLMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s, SASL bind in progress\n" slapi_log_access(LDAP_DEBUG_ARGS, connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_SASLMSG_FMT : LOG_CONN_OP_FMT_EXT_INT LOG_SASLMSG_FMT, @@ -2221,7 +2246,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries op_nested_count, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str); + notes_str, csn_str, session_str); } } else if (op->o_tag == LDAP_REQ_BIND && err == LDAP_SUCCESS) { char *dn = NULL; @@ -2234,15 +2259,15 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries if (!internal_op) { 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" + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" " dn=\"%s\"\n", op->o_connid, op->o_opid, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str, dn ? dn : ""); + notes_str, csn_str, session_str, dn ? dn : ""); } else { -#define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s dn=\"%s\"\n" +#define LOG_BINDMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s dn=\"%s\"\n" slapi_log_access(LDAP_DEBUG_ARGS, connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_BINDMSG_FMT : LOG_CONN_OP_FMT_EXT_INT LOG_BINDMSG_FMT, @@ -2252,7 +2277,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries op_nested_count, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str, dn ? dn : ""); + notes_str, csn_str, session_str, dn ? dn : ""); } slapi_ch_free((void **)&dn); } else { @@ -2260,15 +2285,15 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries if (!internal_op) { 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" + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s" " pr_idx=%d pr_cookie=%d\n", op->o_connid, op->o_opid, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str, pr_idx, pr_cookie); + notes_str, csn_str, session_str, pr_idx, pr_cookie); } else { -#define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s pr_idx=%d pr_cookie=%d \n" +#define LOG_PRMSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s pr_idx=%d pr_cookie=%d \n" slapi_log_access(LDAP_DEBUG_ARGS, connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_PRMSG_FMT : LOG_CONN_OP_FMT_EXT_INT LOG_PRMSG_FMT, @@ -2278,7 +2303,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries op_nested_count, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str, pr_idx, pr_cookie); + notes_str, csn_str, session_str, pr_idx, pr_cookie); } } else if (!internal_op) { char *pbtxt = NULL; @@ -2292,12 +2317,12 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries 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", + " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s%s\n", op->o_connid, op->o_opid, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str, ext_str); + notes_str, csn_str, ext_str, session_str); if (pbtxt) { /* if !pbtxt ==> ext_str == "". Don't free ext_str. */ slapi_ch_free_string(&ext_str); @@ -2305,7 +2330,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" +#define LOG_MSG_FMT " tag=%" BERTAG_T " nentries=%d wtime=%s optime=%s etime=%s%s%s%s\n" slapi_log_access(LDAP_DEBUG_ARGS, connid == 0 ? LOG_CONN_OP_FMT_INT_INT LOG_MSG_FMT : LOG_CONN_OP_FMT_EXT_INT LOG_MSG_FMT, @@ -2315,7 +2340,7 @@ log_result(Slapi_PBlock *pb, Operation *op, int err, ber_tag_t tag, int nentries op_nested_count, err, tag, nentries, wtime, optime, etime, - notes_str, csn_str); + notes_str, csn_str, session_str); /* * If this is an unindexed search we should log it in the error log if * we didn't log it in the access log. diff --git a/ldap/servers/slapd/slapi-plugin.h b/ldap/servers/slapd/slapi-plugin.h index a0e7b3779f..63f1bbcbc5 100644 --- a/ldap/servers/slapd/slapi-plugin.h +++ b/ldap/servers/slapd/slapi-plugin.h @@ -7285,6 +7285,7 @@ typedef struct slapi_plugindesc /* controls we know about */ #define SLAPI_MANAGEDSAIT 1000 #define SLAPI_PWPOLICY 1001 +#define SLAPI_SESSION_TRACKING 1002 /* arguments that are common to all operation */ #define SLAPI_TARGET_SDN 47 /* target sdn of the operation */