389-ds-base/dirsrvtests/tests/tickets/ticket48266_test.py

import pytest
from lib389.tasks import *
from lib389.utils import *
from lib389.topologies import topology_m2

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

NEW_ACCOUNT = "new_account"
MAX_ACCOUNTS = 20


def pattern_accesslog(file, log_pattern):
    try:
        pattern_accesslog.last_pos += 1
    except AttributeError:
        pattern_accesslog.last_pos = 0

    found = None
    file.seek(pattern_accesslog.last_pos)

    # Use a while true iteration because 'for line in file: hit a
    # python bug that break file.tell()
    while True:
        line = file.readline()
        found = log_pattern.search(line)
        if ((line == '') or (found)):
            break

    pattern_accesslog.last_pos = file.tell()
    if found:
        return line
    else:
        return None


@pytest.fixture(scope="module")
def entries(topology_m2):
    # add dummy entries in the staging DIT
    for cpt in range(MAX_ACCOUNTS):
        name = "%s%d" % (NEW_ACCOUNT, cpt)
        topology_m2.ms["master1"].add_s(Entry(("cn=%s,%s" % (name, SUFFIX), {
            'objectclass': "top person".split(),
            'sn': name,
            'cn': name})))
    mod = [(ldap.MOD_REPLACE, 'nsslapd-errorlog-level', '8192'),
           (ldap.MOD_REPLACE, 'nsslapd-accesslog-level', str(256 + 4))]
    topology_m2.ms["master1"].modify_s(DN_CONFIG, mod)
    topology_m2.ms["master2"].modify_s(DN_CONFIG, mod)


def test_ticket48266_fractional(topology_m2, entries):
    ents = topology_m2.ms["master1"].agreement.list(suffix=SUFFIX)
    assert len(ents) == 1

    mod = [(ldap.MOD_REPLACE, 'nsDS5ReplicatedAttributeList', ['(objectclass=*) $ EXCLUDE telephonenumber']),
           (ldap.MOD_REPLACE, 'nsds5ReplicaStripAttrs', ['modifiersname modifytimestamp'])]
    ents = topology_m2.ms["master1"].agreement.list(suffix=SUFFIX)
    assert len(ents) == 1
    m1_m2_agmt = ents[0].dn
    topology_m2.ms["master1"].modify_s(ents[0].dn, mod)

    ents = topology_m2.ms["master2"].agreement.list(suffix=SUFFIX)
    assert len(ents) == 1
    topology_m2.ms["master2"].modify_s(ents[0].dn, mod)

    topology_m2.ms["master1"].restart(timeout=10)
    topology_m2.ms["master2"].restart(timeout=10)

    topology_m2.ms["master1"].agreement.init(SUFFIX, HOST_MASTER_2, PORT_MASTER_2)
    topology_m2.ms["master1"].waitForReplInit(m1_m2_agmt)


def test_ticket48266_check_repl_desc(topology_m2, entries):
    name = "cn=%s1,%s" % (NEW_ACCOUNT, SUFFIX)
    value = 'check repl. description'
    mod = [(ldap.MOD_REPLACE, 'description', value)]
    topology_m2.ms["master1"].modify_s(name, mod)

    loop = 0
    while loop <= 10:
        ent = topology_m2.ms["master2"].getEntry(name, ldap.SCOPE_BASE, "(objectclass=*)")
        if ent.hasAttr('description') and ent.getValue('description') == value:
            break
        time.sleep(1)
        loop += 1
    assert loop <= 10


# will use this CSN as a starting point on error log
# after this is one 'Skipped' then the first csn _get_first_not_replicated_csn
# should no longer be Skipped in the error log
def _get_last_not_replicated_csn(topology_m2):
    name = "cn=%s5,%s" % (NEW_ACCOUNT, SUFFIX)

    # read the first CSN that will not be replicated
    mod = [(ldap.MOD_REPLACE, 'telephonenumber', str(123456))]
    topology_m2.ms["master1"].modify_s(name, mod)
    msgid = topology_m2.ms["master1"].search_ext(name, ldap.SCOPE_SUBTREE, 'objectclass=*', ['nscpentrywsi'])
    rtype, rdata, rmsgid = topology_m2.ms["master1"].result2(msgid)
    attrs = None
    for dn, raw_attrs in rdata:
        topology_m2.ms["master1"].log.info("dn: %s" % dn)
        if 'nscpentrywsi' in raw_attrs:
            attrs = raw_attrs['nscpentrywsi']
    assert attrs
    for attr in attrs:
        if attr.lower().startswith('telephonenumber'):
            break
    assert attr

    # now retrieve the CSN of the operation we are looking for
    csn = None
    topology_m2.ms["master1"].stop(timeout=10)
    file_obj = open(topology_m2.ms["master1"].accesslog, "r")

    # First the conn/op of the operation
    regex = re.compile("MOD dn=\"%s\"" % name)
    found_op = pattern_accesslog(file_obj, regex)
    assert found_op
    if found_op:
        conn_op_pattern = '.* (conn=[0-9]* op=[0-9]*) .*'
        conn_op_re = re.compile(conn_op_pattern)
        conn_op_match = conn_op_re.match(found_op)
        conn_op = conn_op_match.group(1)

        # now the related CSN
        regex = re.compile("%s RESULT" % conn_op)
        found_result = pattern_accesslog(file_obj, regex)
        csn_pattern = '.* csn=(.*)'
        csn_re = re.compile(csn_pattern)
        csn_match = csn_re.match(found_result)
        csn = csn_match.group(1)

    topology_m2.ms["master1"].start(timeout=10)
    return csn


def _get_first_not_replicated_csn(topology_m2):
    name = "cn=%s2,%s" % (NEW_ACCOUNT, SUFFIX)

    # read the first CSN that will not be replicated
    mod = [(ldap.MOD_REPLACE, 'telephonenumber', str(123456))]
    topology_m2.ms["master1"].modify_s(name, mod)
    msgid = topology_m2.ms["master1"].search_ext(name, ldap.SCOPE_SUBTREE, 'objectclass=*', ['nscpentrywsi'])
    rtype, rdata, rmsgid = topology_m2.ms["master1"].result2(msgid)
    attrs = None
    for dn, raw_attrs in rdata:
        topology_m2.ms["master1"].log.info("dn: %s" % dn)
        if 'nscpentrywsi' in raw_attrs:
            attrs = raw_attrs['nscpentrywsi']
    assert attrs
    for attr in attrs:
        if attr.lower().startswith('telephonenumber'):
            break
    assert attr

    # now retrieve the CSN of the operation we are looking for
    csn = None
    topology_m2.ms["master1"].stop(timeout=10)
    file_obj = open(topology_m2.ms["master1"].accesslog, "r")

    # First the conn/op of the operation
    regex = re.compile("MOD dn=\"%s\"" % name)
    found_op = pattern_accesslog(file_obj, regex)
    assert found_op
    if found_op:
        conn_op_pattern = '.* (conn=[0-9]* op=[0-9]*) .*'
        conn_op_re = re.compile(conn_op_pattern)
        conn_op_match = conn_op_re.match(found_op)
        conn_op = conn_op_match.group(1)

        # now the related CSN
        regex = re.compile("%s RESULT" % conn_op)
        found_result = pattern_accesslog(file_obj, regex)
        csn_pattern = '.* csn=(.*)'
        csn_re = re.compile(csn_pattern)
        csn_match = csn_re.match(found_result)
        csn = csn_match.group(1)

    topology_m2.ms["master1"].start(timeout=10)
    return csn


def _count_full_session(topology_m2):
    #
    # compute the number of 'No more updates'
    #
    file_obj = open(topology_m2.ms["master1"].errlog, "r")
    # pattern to find
    pattern = ".*No more updates to send.*"
    regex = re.compile(pattern)
    no_more_updates = 0

    # check initiation number of 'No more updates
    while True:
        line = file_obj.readline()
        found = regex.search(line)
        if (found):
            no_more_updates = no_more_updates + 1
        if (line == ''):
            break
    file_obj.close()

    return no_more_updates


def test_ticket48266_count_csn_evaluation(topology_m2, entries):
    ents = topology_m2.ms["master1"].agreement.list(suffix=SUFFIX)
    assert len(ents) == 1
    first_csn = _get_first_not_replicated_csn(topology_m2)
    name = "cn=%s3,%s" % (NEW_ACCOUNT, SUFFIX)
    NB_SESSION = 102

    no_more_update_cnt = _count_full_session(topology_m2)
    topology_m2.ms["master1"].agreement.pause(ents[0].dn)
    # now do a set of updates that will NOT be replicated
    for telNumber in range(NB_SESSION):
        mod = [(ldap.MOD_REPLACE, 'telephonenumber', str(telNumber))]
        topology_m2.ms["master1"].modify_s(name, mod)

    topology_m2.ms["master1"].agreement.resume(ents[0].dn)

    # let's wait all replication session complete
    MAX_LOOP = 10
    cnt = 0
    current_no_more_update = _count_full_session(topology_m2)
    while (current_no_more_update == no_more_update_cnt):
        cnt = cnt + 1
        if (cnt > MAX_LOOP):
            break
        time.sleep(5)
        current_no_more_update = _count_full_session(topology_m2)

    log.info('after %d MODs we have completed %d replication sessions' % (
    NB_SESSION, (current_no_more_update - no_more_update_cnt)))
    no_more_update_cnt = current_no_more_update

    # At this point, with the fix a dummy update was made BUT may be not sent it
    # make sure it was sent so that the consumer CSN will be updated
    last_csn = _get_last_not_replicated_csn(topology_m2)

    # let's wait all replication session complete
    MAX_LOOP = 10
    cnt = 0
    current_no_more_update = _count_full_session(topology_m2)
    while (current_no_more_update == no_more_update_cnt):
        cnt = cnt + 1
        if (cnt > MAX_LOOP):
            break
        time.sleep(5)
        current_no_more_update = _count_full_session(topology_m2)

    log.info('This MODs %s triggered the send of the dummy update completed %d replication sessions' % (
    last_csn, (current_no_more_update - no_more_update_cnt)))
    no_more_update_cnt = current_no_more_update

    # so we should no longer see the first_csn in the log
    # Let's create a new csn (last_csn) and check there is no longer first_csn
    topology_m2.ms["master1"].agreement.pause(ents[0].dn)
    last_csn = _get_last_not_replicated_csn(topology_m2)
    topology_m2.ms["master1"].agreement.resume(ents[0].dn)

    # let's wait for the session to complete
    MAX_LOOP = 10
    cnt = 0
    while (current_no_more_update == no_more_update_cnt):
        cnt = cnt + 1
        if (cnt > MAX_LOOP):
            break
        time.sleep(5)
        current_no_more_update = _count_full_session(topology_m2)

    log.info('This MODs %s  completed in %d replication sessions, should be sent without evaluating %s' % (
    last_csn, (current_no_more_update - no_more_update_cnt), first_csn))
    no_more_update_cnt = current_no_more_update

    # Now determine how many times we have skipped 'csn'
    # no need to stop the server to check the error log
    file_obj = open(topology_m2.ms["master1"].errlog, "r")

    # find where the last_csn operation was processed
    pattern = ".*ruv_add_csn_inprogress: successfully inserted csn %s.*" % last_csn
    regex = re.compile(pattern)
    cnt = 0

    while True:
        line = file_obj.readline()
        found = regex.search(line)
        if ((line == '') or (found)):
            break
    if (found):
        log.info('last operation was found at %d' % file_obj.tell())
        log.info(line)
    log.info('Now check the we can not find the first csn %s in the log' % first_csn)

    pattern = ".*Skipping update operation.*CSN %s.*" % first_csn
    regex = re.compile(pattern)
    found = False
    while True:
        line = file_obj.readline()
        found = regex.search(line)
        if ((line == '') or (found)):
            break
    if (found):
        log.info('Unexpected found %s' % line)
    assert not found


if __name__ == '__main__':
    # Run isolated
    # -s for DEBUG mode

    CURRENT_FILE = os.path.realpath(__file__)
    pytest.main("-s %s" % CURRENT_FILE)