Blame SOURCES/0091-Ticket-49540-Indexing-task-is-reported-finished-too-.patch

6f51e1
From b7b71e2da754f950229cbc34d55e34e1314de301 Mon Sep 17 00:00:00 2001
6f51e1
From: Thierry Bordaz <tbordaz@redhat.com>
6f51e1
Date: Fri, 19 Jan 2018 17:50:59 +0100
6f51e1
Subject: [PATCH] Ticket 49540 - Indexing task is reported finished too early
6f51e1
 regarding the backend status
6f51e1
6f51e1
Bug Description:
6f51e1
	If a task complete successfully, its status is updated before the backend
6f51e1
	can receive update.
6f51e1
6f51e1
Fix Description:
6f51e1
	postpone the task status update after backend is reenabled
6f51e1
6f51e1
https://pagure.io/389-ds-base/issue/49540
6f51e1
6f51e1
Reviewed by: Ludwig Krispenz
6f51e1
6f51e1
Platforms tested: F26
6f51e1
6f51e1
Flag Day: no
6f51e1
6f51e1
Doc impact: no
6f51e1
---
6f51e1
 dirsrvtests/tests/tickets/ticket49540_test.py | 135 ++++++++++++++++++++++++++
6f51e1
 ldap/servers/slapd/back-ldbm/ldif2ldbm.c      |  16 +--
6f51e1
 2 files changed, 145 insertions(+), 6 deletions(-)
6f51e1
 create mode 100644 dirsrvtests/tests/tickets/ticket49540_test.py
6f51e1
6f51e1
diff --git a/dirsrvtests/tests/tickets/ticket49540_test.py b/dirsrvtests/tests/tickets/ticket49540_test.py
6f51e1
new file mode 100644
6f51e1
index 000000000..1fbfde2c5
6f51e1
--- /dev/null
6f51e1
+++ b/dirsrvtests/tests/tickets/ticket49540_test.py
6f51e1
@@ -0,0 +1,135 @@
6f51e1
+import logging
6f51e1
+import pytest
6f51e1
+import os
6f51e1
+import ldap
6f51e1
+import time
6f51e1
+import re
6f51e1
+from lib389._constants import *
6f51e1
+from lib389.tasks import *
6f51e1
+from lib389.topologies import topology_st as topo
6f51e1
+from lib389.idm.user import UserAccount, UserAccounts, TEST_USER_PROPERTIES
6f51e1
+from lib389 import Entry
6f51e1
+
6f51e1
+
6f51e1
+
6f51e1
+DEBUGGING = os.getenv("DEBUGGING", default=False)
6f51e1
+if DEBUGGING:
6f51e1
+    logging.getLogger(__name__).setLevel(logging.DEBUG)
6f51e1
+else:
6f51e1
+    logging.getLogger(__name__).setLevel(logging.INFO)
6f51e1
+log = logging.getLogger(__name__)
6f51e1
+
6f51e1
+HOMEDIRECTORY_INDEX = 'cn=homeDirectory,cn=index,cn=userRoot,cn=ldbm database,cn=plugins,cn=config'
6f51e1
+HOMEDIRECTORY_CN = "homedirectory"
6f51e1
+MATCHINGRULE = 'nsMatchingRule'
6f51e1
+USER_CN = 'user_'
6f51e1
+
6f51e1
+def create_index_entry(topo):
6f51e1
+    log.info("\n\nindex homeDirectory")
6f51e1
+    try:
6f51e1
+        ent = topo.getEntry(HOMEDIRECTORY_INDEX, ldap.SCOPE_BASE)
6f51e1
+    except ldap.NO_SUCH_OBJECT:
6f51e1
+        topo.add_s(Entry((HOMEDIRECTORY_INDEX, {
6f51e1
+            'objectclass': "top nsIndex".split(),
6f51e1
+            'cn': HOMEDIRECTORY_CN,
6f51e1
+            'nsSystemIndex': 'false',
6f51e1
+            MATCHINGRULE: ['caseIgnoreIA5Match', 'caseExactIA5Match' ],
6f51e1
+            'nsIndexType': ['eq', 'sub', 'pres']})))
6f51e1
+
6f51e1
+
6f51e1
+def provision_users(topo):
6f51e1
+    test_users = []
6f51e1
+    homeValue = b'x' * (32 * 1024)  # just to slow down indexing
6f51e1
+    for i in range(100):
6f51e1
+        CN = '%s%d' % (USER_CN, i)
6f51e1
+        users = UserAccounts(topo, SUFFIX)
6f51e1
+        user_props = TEST_USER_PROPERTIES.copy()
6f51e1
+        user_props.update({'uid': CN, 'cn': CN, 'sn': '_%s' % CN, HOMEDIRECTORY_CN: homeValue})
6f51e1
+        testuser = users.create(properties=user_props)
6f51e1
+        test_users.append(testuser)
6f51e1
+    return test_users
6f51e1
+
6f51e1
+def start_start_status(server):
6f51e1
+    args = {TASK_WAIT: False}
6f51e1
+    indexTask = Tasks(server)
6f51e1
+    indexTask.reindex(suffix=SUFFIX, attrname='homeDirectory', args=args)
6f51e1
+    return indexTask
6f51e1
+
6f51e1
+def check_task_status(server, indexTask, test_entry):
6f51e1
+    finish_pattern = re.compile(".*Finished indexing.*")
6f51e1
+    mod = [(ldap.MOD_REPLACE, 'sn', b'foo')]
6f51e1
+    for i in range(10):
6f51e1
+        log.info("check_task_status =========> %d th loop" % i)
6f51e1
+        try:
6f51e1
+            ent = server.getEntry(indexTask.dn, ldap.SCOPE_BASE)
6f51e1
+            if ent.hasAttr('nsTaskStatus'):
6f51e1
+                value = str(ent.getValue('nsTaskStatus'))
6f51e1
+                finish = finish_pattern.search(value)
6f51e1
+                log.info("%s ---> %s" % (indexTask.dn, value))
6f51e1
+            else:
6f51e1
+                finish = None
6f51e1
+                log.info("%s ---> NO STATUS" % (indexTask.dn))
6f51e1
+
6f51e1
+            if not finish:
6f51e1
+                # This is not yet finished try an update
6f51e1
+                try:
6f51e1
+                    server.modify_s(test_entry, mod)
6f51e1
+
6f51e1
+                    # weird, may be indexing just complete
6f51e1
+                    ent = server.getEntry(indexTask.dn, ldap.SCOPE_BASE, ['nsTaskStatus'])
6f51e1
+                    assert (ent.hasAttr('nsTaskStatus') and regex.search(ent.getValue('nsTaskStatus')))
6f51e1
+                    log.info("Okay, it just finished so the MOD was successful")
6f51e1
+                except ldap.UNWILLING_TO_PERFORM:
6f51e1
+                    log.info("=========> Great it was expected in the middle of index")
6f51e1
+            else:
6f51e1
+                # The update should be successful
6f51e1
+                server.modify_s(test_entry, mod)
6f51e1
+
6f51e1
+        except ldap.NO_SUCH_OBJECT:
6f51e1
+            log.info("%s: no found" % (indexTask.dn))
6f51e1
+
6f51e1
+        time.sleep(1)
6f51e1
+
6f51e1
+def test_ticket49540(topo):
6f51e1
+    """Specify a test case purpose or name here
6f51e1
+
6f51e1
+    :id: 1df16d5a-1b92-46b7-8435-876b87545748
6f51e1
+    :setup: Standalone Instance
6f51e1
+    :steps:
6f51e1
+        1. Create homeDirectory index (especially with substring)
6f51e1
+        2. Creates 100 users with large homeDirectory value => long to index
6f51e1
+        3. Start an indexing task WITHOUT waiting for its completion
6f51e1
+        4. Monitor that until task.status = 'Finish', any update -> UNWILLING to perform
6f51e1
+    :expectedresults:
6f51e1
+        1. Index configuration succeeds
6f51e1
+        2. users entry are successfully created
6f51e1
+        3. Indexing task is started
6f51e1
+        4. If the task.status does not contain 'Finished indexing', any update should return UNWILLING_TO_PERFORM
6f51e1
+           When it contains 'Finished indexing', updates should be successful
6f51e1
+    """
6f51e1
+
6f51e1
+    server = topo.standalone
6f51e1
+    create_index_entry(server)
6f51e1
+    test_users = provision_users(server)
6f51e1
+
6f51e1
+    indexTask = start_start_status(server)
6f51e1
+    check_task_status(server, indexTask, test_users[0].dn)
6f51e1
+
6f51e1
+    # If you need any test suite initialization,
6f51e1
+    # please, write additional fixture for that (including finalizer).
6f51e1
+    # Topology for suites are predefined in lib389/topologies.py.
6f51e1
+
6f51e1
+    # If you need host, port or any other data about instance,
6f51e1
+    # Please, use the instance object attributes for that (for example, topo.ms["master1"].serverid)
6f51e1
+
6f51e1
+    if DEBUGGING:
6f51e1
+        # Add debugging steps(if any)...
6f51e1
+        pass
6f51e1
+
6f51e1
+
6f51e1
+if __name__ == '__main__':
6f51e1
+    # Run isolated
6f51e1
+    # -s for DEBUG mode
6f51e1
+    CURRENT_FILE = os.path.realpath(__file__)
6f51e1
+    pytest.main(["-s", CURRENT_FILE])
6f51e1
+
6f51e1
diff --git a/ldap/servers/slapd/back-ldbm/ldif2ldbm.c b/ldap/servers/slapd/back-ldbm/ldif2ldbm.c
6f51e1
index 6d897edc7..6527a477c 100644
6f51e1
--- a/ldap/servers/slapd/back-ldbm/ldif2ldbm.c
6f51e1
+++ b/ldap/servers/slapd/back-ldbm/ldif2ldbm.c
6f51e1
@@ -2533,12 +2533,7 @@ ldbm_back_ldbm2index(Slapi_PBlock *pb)
6f51e1
         vlvIndex_go_online(pvlv[vlvidx], be);
6f51e1
     }
6f51e1
 
6f51e1
-    if (task) {
6f51e1
-        slapi_task_log_status(task, "%s: Finished indexing.",
6f51e1
-                              inst->inst_name);
6f51e1
-        slapi_task_log_notice(task, "%s: Finished indexing.",
6f51e1
-                              inst->inst_name);
6f51e1
-    }
6f51e1
+    /* if it was a task, its status will be updated later after backend is ready for update */
6f51e1
     slapi_log_err(SLAPI_LOG_INFO, "ldbm_back_ldbm2index", "%s: Finished indexing.\n",
6f51e1
               inst->inst_name);
6f51e1
     return_value = 0; /* success */
6f51e1
@@ -2562,6 +2557,15 @@ err_min:
6f51e1
     dblayer_release_id2entry( be, db ); /* nope */
6f51e1
     instance_set_not_busy(inst);
6f51e1
 
6f51e1
+    if (return_value == 0) {
6f51e1
+        if (task) {
6f51e1
+            slapi_task_log_status(task, "%s: Finished indexing.",
6f51e1
+                    inst->inst_name);
6f51e1
+            slapi_task_log_notice(task, "%s: Finished indexing.",
6f51e1
+                    inst->inst_name);
6f51e1
+        }
6f51e1
+    }
6f51e1
+
6f51e1
     if (run_from_cmdline) {
6f51e1
         if (0 != dblayer_flush(li)) {
6f51e1
             slapi_log_err(SLAPI_LOG_ERR,
6f51e1
-- 
6f51e1
2.13.6
6f51e1