Issue 6328 - vlv control may not be logged (#6354)

VLV control is logged only after succesfully sending the VLV response control
which means that VLV is not visible if the search fail which make troubleshooting harder.
This fix, logs the VLV (with None as vlv result) everytime a VLV is used

This fix also improve lmdb debug log about VLVs

Issue: #6328

Reviewed by: @tbordaz, @droideck (Thanks!)

dirsrvtests/tests/suites/vlv/regression_test.py

@@ -11,7 +11,8 @@
 import glob
 import ldap
 from shutil import copyfile, rmtree
-from contextlib import contextmanager
+from datetime import datetime
+from contextlib import contextmanager, suppress
 from lib389.tasks import *
 from lib389.utils import *
 from lib389.topologies import topology_m2, topology_st
@@ -21,6 +22,7 @@
 from lib389.index import *
 from lib389.mappingTree import *
 from lib389.backend import *
+from lib389.dirsrv_log import DirsrvAccessLog
 from lib389.idm.user import UserAccounts, UserAccount
 from lib389.idm.organization import Organization
 from ldap.controls.vlv import VLVRequestControl
@@ -47,6 +49,8 @@
 # and the NNNN value) is:
 VLV_SEARCH_OFFSET = STARTING_UID_INDEX - 2
 
+DEMO_PW = 'secret12'
+
 # A VLV Index with invalid vlvSrch:
 # ( Using objectClass: extensibleobject instead of objectClass: vlvSrch )
 BAD_DSE_DATA = """dn: cn=vlvSrch,cn=userRoot,cn=ldbm database,cn=plugins,cn=config
@@ -179,90 +183,132 @@ def cleanup(inst):
     remove_entries(inst, "cn=config", "(objectclass=vlvSearch)")
     remove_entries(inst, DEFAULT_SUFFIX, "(cn=testuser*)")
 
+class BackendHandler:
+    def __init__(self, inst, bedict, scope=ldap.SCOPE_ONELEVEL):
+        self.inst = inst
+        self.bedict = bedict
+        self.bes = Backends(inst)
+        self.scope = scope
+        self.data = {}
+
+    def find_backend(self, bename):
+        for be in self.bes.list():
+            if be.get_attr_val_utf8_l('cn') == bename:
+                return be
+        return None
+
+    def cleanup(self):
+        benames =  list(self.bedict.keys())
+        benames.reverse()
+        for bename in benames:
+            be = self.find_backend(bename)
+            if be:
+                be.delete()
+
+    def setup(self):
+        # Create backends, add vlv index and populate the backends.
+        for bename,suffix in self.bedict.items():
+            be = self.bes.create(properties={
+                'cn': bename,
+                'nsslapd-suffix': suffix,
+            })
+            # Add suffix entry
+            Organization(self.inst, dn=suffix).create(properties={ 'o': bename, })
+            # Configure vlv
+            vlv_search, vlv_index = create_vlv_search_and_index(
+                self.inst, basedn=suffix,
+                bename=bename, scope=self.scope,
+                prefix=f'vlv_1lvl_{bename}')
+            # Reindex
+            reindex_task = Tasks(self.inst)
+            assert reindex_task.reindex(
+                suffix=suffix,
+                attrname=vlv_index.rdn,
+                args={TASK_WAIT: True},
+                vlv=True
+            ) == 0
+            # Add ou=People entry
+            OrganizationalUnits(self.inst, suffix).create(properties={'ou': 'People'})
+            # Add another ou that will be deleted before the export
+            # so that import will change the vlv search basedn entryid
+            ou2 = OrganizationalUnits(self.inst, suffix).create(properties={'ou': 'dummy ou'})
+            # Add a demo user so that vlv_check is happy
+            dn = f'uid=demo_user,ou=people,{suffix}'
+            UserAccount(self.inst, dn=dn).create( properties= {
+                    'uid': 'demo_user',
+                    'cn': 'Demo user',
+                    'sn': 'Demo user',
+                    'uidNumber': '99998',
+                    'gidNumber': '99998',
+                    'homeDirectory': '/var/empty',
+                    'loginShell': '/bin/false',
+                    'userpassword': DEMO_PW })
+            # Add regular user
+            add_users(self.inst, 10, suffix=suffix)
+            # Removing ou2
+            ou2.delete()
+            # And export
+            tasks = Tasks(self.inst)
+            ldif = f'{self.inst.get_ldif_dir()}/db-{bename}.ldif'
+            assert tasks.exportLDIF(suffix=suffix,
+                                    output_file=ldif,
+                                    args={TASK_WAIT: True}) == 0
+            # Add the various parameters in topology_st.belist
+            self.data[bename] = { 'be': be,
+                                 'suffix': suffix,
+                                 'ldif': ldif,
+                                 'vlv_search' : vlv_search,
+                                 'vlv_index' : vlv_index,
+                                 'dn' : dn}
+
 
 @pytest.fixture
 def vlv_setup_with_two_backend(topology_st, request):
     inst = topology_st.standalone
-    belist = []
+    beh = BackendHandler(inst, { 'be1': 'o=be1', 'be2': 'o=be2' })
 
     def fin():
         # Cleanup function
         if not DEBUGGING and inst.exists() and inst.status():
-            for be in Backends(inst).list():
-                if be.get_attr_val_utf8_l('cn') in [ 'be1', 'be2' ]:
-                    be.delete()
+            beh.cleanup()
 
     request.addfinalizer(fin)
 
-    def setup_vlv_and_backend(inst, bename):
-        # Create a backend, add vlv index and populate the backend.
-        bes = Backends(inst)
-        suffix = f'o={bename}'
-        be = bes.create(properties={
-            'cn': bename,
-            'nsslapd-suffix': suffix,
-        })
-        # Add suffix entry
-        Organization(inst, dn=suffix).create(properties={ 'o': bename, })
-        # Configure vlv
-        vlv_search, vlv_index = create_vlv_search_and_index(
-            inst, basedn=suffix,
-            bename=bename, scope=ldap.SCOPE_ONELEVEL,
-            prefix=f'vlv_1lvl_{bename}')
-        # Add ou=People entry
-        OrganizationalUnits(inst, suffix).create(properties={'ou': 'People'})
-        # Add another ou that will be deleted before the export
-        # so that import will change the vlv search basedn entryid
-        ou2 = OrganizationalUnits(inst, suffix).create(properties={'ou': 'dummy ou'})
-        # Add a demo user so that vlv_check is happy
-        dn = f'uid=demo_user,ou=people,{suffix}'
-        UserAccount(inst, dn=dn).create( properties= {
-                'uid': 'demo_user',
-                'cn': 'Demo user',
-                'sn': 'Demo user',
-                'uidNumber': '99998',
-                'gidNumber': '99998',
-                'homeDirectory': '/var/empty',
-                'loginShell': '/bin/false', })
-        # Add regular user
-        add_users(inst, 10, suffix=suffix)
-        # Removing ou2
-        ou2.delete()
-        # And export
-        tasks = Tasks(inst)
-        ldif = f'{inst.get_ldif_dir()}/db-{bename}.ldif'
-        assert tasks.exportLDIF(suffix=suffix,
-                                output_file=ldif,
-                                args={TASK_WAIT: True}) == 0
-        # Add the various parameters in topology_st.belist
-        belist.append( { 'be': be,
-                         'suffix': suffix,
-                         'ldif': ldif,
-                         'vlv_search' : vlv_search,
-                         'vlv_index' : vlv_index, })
-
     # Make sure that our backend are not already present.
-    # and gran userRoot be while doing that
-    be0 = None
-    for be in Backends(inst).list():
-        bename = be.get_attr_val_utf8_l('cn')
-        if bename in [ 'be1', 'be2' ]:
-            be.delete()
-        if bename == 'userroot':
-            be0 = be
+    beh.cleanup()
 
     # Add userRoot backend to the backend list
+    be0 = beh.find_backend('userroot')
     be0ldif = f'{inst.get_ldif_dir()}/db-userroot.ldif'
     assert Tasks(inst).exportLDIF(suffix=DEFAULT_SUFFIX,
                                   output_file=be0ldif,
                                   args={TASK_WAIT: True}) == 0
-    belist.append( { 'be': be0,
+    beh.data['userroot'] = { 'be': be0,
                      'suffix': DEFAULT_SUFFIX,
-                     'ldif': be0ldif, })
+                     'ldif': be0ldif, }
     # Then add two new backends
-    setup_vlv_and_backend(inst, "be1")
-    setup_vlv_and_backend(inst, "be2")
-    topology_st.belist = belist
+    beh.setup()
+    topology_st.beh = beh
+    topology_st.belist = list(beh.data.values())
+    return topology_st
+
+
+@pytest.fixture
+def vlv_setup_nested_backends(topology_st, request):
+    inst = topology_st.standalone
+    beh = BackendHandler(inst, { 'be1': 'o=be1', 'be2': 'o=be2,o=be1' }, scope=ldap.SCOPE_SUBTREE)
+
+    def fin():
+        # Cleanup function
+        if not DEBUGGING and inst.exists() and inst.status():
+            beh.cleanup()
+
+    request.addfinalizer(fin)
+
+    # Make sure that our backend are not already present.
+    beh.cleanup()
+    beh.setup()
+    topology_st.beh = beh
     return topology_st
 
 
@@ -939,6 +985,108 @@ def test_vlv_by_keyword(freeipa):
         assert f'cn={idx},ou=certificateRepository,ou=ca,o=ipaca' in dns
 
 
+def get_timestamp_attr():
+    current_datetime = datetime.now()
+    return f'tsattr-{current_datetime.timestamp()}'.replace(".", "-")
+
+
+def perform_vlv_search(conn, alog, basedn, vlvcrit=True, ssscrit=True, scope=ldap.SCOPE_SUBTREE, sss='cn', filter='(uid=*)'):
+    timestamp = get_timestamp_attr()
+    vlv_control = VLVRequestControl(criticality=vlvcrit,
+        before_count=1,
+        after_count=1,
+        offset=4,
+        content_count=0,
+        greater_than_or_equal=None,
+        context_id=None)
+
+    sss_control = SSSRequestControl(criticality=ssscrit, ordering_rules=[sss])
+    log.info(f'perform_vlv_search: basedn={basedn} ={vlvcrit} ssscrit={ssscrit} sss={sss} filter={filter} timestamp={timestamp}')
+
+    with suppress(ldap.LDAPError):
+        result = conn.search_ext_s(
+            base=basedn,
+            scope=scope,
+            filterstr=filter,
+            attrlist=[timestamp],
+            serverctrls=[vlv_control, sss_control]
+        )
+    line =  alog.match(f'.*SRCH.*{timestamp}.*')
+    log.info(f'perform_vlv_search: line={line}')
+    match = re.match(r'.*conn=(\d+) op=(\d+).*', line[0])
+    conn,op = match.group(1,2)
+    log.info(f'perform_vlv_search: conn={conn} op={op} ')
+    lines = ''.join(alog.match(f'.*conn={conn} op={op} .*', after_pattern=f'.*{timestamp}.*'))
+    log.info(f'perform_vlv_search: lines={lines}')
+    return lines
+
+
+def test_vlv_logs(vlv_setup_nested_backends):
+    """Test than VLV abd SORT lines are properply written
+
+    :id: a1d9ad9e-7cbb-11ef-82e3-083a88554478
+    :setup: Standalone instance with two backens and one level scoped vlv
+    :steps:
+        1. Check that standard search returns 16 valid certificate
+        2. Check that vlv search returns 16 valid certificate
+
+    :expectedresults:
+        1. Should Success.
+        2. Should Success.
+    """
+    inst = vlv_setup_nested_backends.standalone
+    beh = vlv_setup_nested_backends.beh
+    tasks = Tasks(inst)
+    conn = open_new_ldapi_conn(inst.serverid)
+    conn_demo = open_new_ldapi_conn(inst.serverid)
+    alog = DirsrvAccessLog(inst)
+    dn1 = beh.data['be1']['dn']
+    dn2 = beh.data['be2']['dn']
+    suffix1 = beh.data['be1']['suffix']
+    suffix2 = beh.data['be2']['suffix']
+    conn_demo.bind_s(dn2, DEMO_PW)
+
+    VLV_FEATURE_DN = 'oid=2.16.840.1.113730.3.4.9,cn=features,cn=config'
+    VLV_DEFAULT_ACI = b'(targetattr != "aci")(version 3.0; acl "VLV Request Control"; ' + \
+                      b'allow( read , search, compare, proxy ) userdn = "ldap:///all";)'
+    VLV_DENY_ACI = b'(targetattr != "aci")(version 3.0; acl "VLV Request Control"; ' + \
+                      f'deny( read , search, compare, proxy ) userdn = "ldap:///{dn2}";)'.encode('utf8')
+
+    # Set VLV feature ACI
+    mod = (ldap.MOD_REPLACE, 'aci', [ VLV_DEFAULT_ACI, VLV_DENY_ACI ])
+    conn.modify_s(VLV_FEATURE_DN, [mod,])
+
+    # Invalid ACL
+    res = perform_vlv_search(conn_demo, alog, suffix2)
+    assert 'SORT' in res
+    assert 'VLV' in res
+    assert 'err=50 ' in res
+
+    # Sucessful VLV
+    res = perform_vlv_search(conn, alog, suffix2)
+    assert 'SORT' in res
+    assert 'VLV' in res
+    assert 'err=0 ' in res
+
+    # Multiple backends SSS and VLV are critical
+    res = perform_vlv_search(conn, alog, suffix1)
+    assert 'SORT' in res
+    assert 'VLV' in res
+    assert 'err=76 ' in res
+
+    # Multiple backends SSS is critical VLV is not critical
+    res = perform_vlv_search(conn, alog, suffix1, vlvcrit=False)
+    assert 'SORT' in res
+    assert 'VLV' in res
+    assert 'err=12 ' in res
+
+    # Multiple backends SSS and VLV are not critical
+    res = perform_vlv_search(conn, alog, suffix1, vlvcrit=False, ssscrit=False)
+    assert 'SORT' in res
+    assert 'VLV' in res
+    assert 'err=0 ' in res
+
+
 if __name__ == "__main__":
     # Run isolated
     # -s for DEBUG mode

ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c

@@ -185,6 +185,7 @@ static flagsdesc_t mdb_loglvl_desc[] = {
     { "TXN", DBGMDB_LEVEL_TXN },
     { "IMPORT", DBGMDB_LEVEL_IMPORT },
     { "BULKOP", DBGMDB_LEVEL_BULKOP },
+    { "VLV", DBGMDB_LEVEL_VLV },
     { "DBGMDB", DBGMDB_LEVEL_OTHER },
     { 0 }
 };

ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h

@@ -10,12 +10,13 @@
 void dbmdb_format_dbslist_info(char *info, dbmdb_dbi_t *dbi);
 
 #define DBGMDB_LEVEL_MDBAPI 1
-#define DBGMDB_LEVEL_TXN 2
+#define DBGMDB_LEVEL_TXN    2
 #define DBGMDB_LEVEL_IMPORT 4
 #define DBGMDB_LEVEL_BULKOP 8
-#define DBGMDB_LEVEL_OTHER 0x20
-#define DBGMDB_LEVEL_REPL 0x1000
-#define DBGMDB_LEVEL_FORCE 0x10000
+#define DBGMDB_LEVEL_VLV    0x10
+#define DBGMDB_LEVEL_OTHER  0x20
+#define DBGMDB_LEVEL_REPL   0x1000
+#define DBGMDB_LEVEL_FORCE  0x10000
 
 #define DBGMDB_LEVEL_PRINTABLE 0xfff
 
@@ -26,7 +27,8 @@ void dbgval2str(char *buff, size_t bufsiz, MDB_val *val);
 void dbmdb_dbg_set_dbi_slots(dbmdb_dbi_t *slots);
 
 /* #define DBMDB_DEBUG 1 */
-#define DBGMDB_LEVEL_DEFAULT DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_TXN+DBGMDB_LEVEL_IMPORT+DBGMDB_LEVEL_BULKOP+DBGMDB_LEVEL_OTHER
+#define DBGMDB_LEVEL_DEFAULT DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_TXN+DBGMDB_LEVEL_IMPORT+ \
+                             DBGMDB_LEVEL_BULKOP+DBGMDB_LEVEL_OTHER+DBGMDB_LEVEL_VLV
 
 /* Define the wrapper associated with each log level */
 #ifdef DBMDB_DEBUG
@@ -52,6 +54,8 @@ void dbmdb_dbg_set_dbi_slots(dbmdb_dbi_t *slots);
 #define TXN_LOG(msg,txn) dbg_log(__FILE__,__LINE__,__FUNCTION__,DBGMDB_LEVEL_TXN, msg, (ulong)(txn))
 #define pthread_gettid() syscall(__NR_gettid)
 
+#define DBG_LOG(...) dbg_log(__FILE__,__LINE__,__FUNCTION__, __VA_ARGS__)
+
 
 int dbg_mdb_cursor_open(const char *file, int lineno, const char *funcname, MDB_txn *txn, MDB_dbi dbi, MDB_cursor **cursor);
 int dbg_mdb_cursor_renew(const char *file, int lineno, const char *funcname, MDB_txn *txn, MDB_cursor *cursor);
@@ -98,4 +102,6 @@ void dbmdb_log_dbi_set_fn(const char *file, int lineno, const char *funcname, co
 #define TXN_LOG(msg,txn)
 #define pthread_gettid() 0
 
+#define DBG_LOG(...)
+
 #endif /* DBMDB_DEBUG */