Bug 1181346

Summary: nsslapd-changelogtrim-interval is not applied immediately
Product: Red Hat Enterprise Linux 7 Reporter: Viktor Ashirov <vashirov>
Component: 389-ds-baseAssignee: wibrown <wibrown>
Status: CLOSED WORKSFORME QA Contact: Viktor Ashirov <vashirov>
Severity: low Docs Contact:
Priority: low    
Version: 7.2CC: mreynolds, nhosoi, nkinder, rmeggins, vashirov, wibrown
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-10-31 14:58:01 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
ticket48007_test.py
none
verification lib389 test script none

Description Viktor Ashirov 2015-01-12 23:21:06 UTC 
Description of problem:
When nsslapd-changelogtrim-interval is changed, it doesn't take effect immediately. 

Version-Release number of selected component (if applicable):
389-ds-base-1.3.3.1-11.el7.x86_64


How reproducible:
always

Steps to Reproduce:
[1]  Setup DS using "dc=example,dc=com"
[2]  Create the changelog
[3]  Set the max entries, and changelog trim interval

dn: cn=changelog5,cn=config
changetype: modify
replace: nsslapd-changelogmaxentries
nsslapd-changelogmaxentries: 5
-
replace: nsslapd-changelogtrim-interval
nsslapd-changelogtrim-interval: 15


[4]  Enable replication for "dc=example,dc=com"
[5]  Turn on replication logging

dn: cn=config
changetype: modify
replace: nsslapd-errorlog-level
nsslapd-errorlog-level: 8192

[6]  Add 10 entries to "dc=example,dc=com"

[7]  Sleep for 15 seconds

[8]  Grep the error log for "changes from the changelog"

Actual results:
Next trim starts only after current trim is finished (notice the timestamps)
[13/Jan/2015:00:13:23 +0100] NSMMReplicationPlugin - changelog program - cl5GetOperationCount: found DB object 7f072400df50
[13/Jan/2015:00:18:16 +0100] - Trimmed 5 changes from the changelog


Expected results:
Trimming thread should be notified that config was updated.
Comment 2 Noriko Hosoi 2015-01-19 19:21:18 UTC 
Thank you, Viktor!

This is not a release stopper for 7.1; setting the target to 7.2 per weekly mtg.
Comment 3 Noriko Hosoi 2015-01-28 00:31:46 UTC 
Upstream ticket:
https://fedorahosted.org/389/ticket/48007
Comment 7 Noriko Hosoi 2016-05-10 01:15:55 UTC 
Hi Viktor,

It seems Mark and Willam failed to duplicate the problem.
(See https://fedorahosted.org/389/ticket/48007)

Is it okay to close this bug for now?
Please feel free to reopen it when you run into it.
Probably, you could let us access your test env once you see the bug again?

Thanks!
Comment 8 Viktor Ashirov 2016-05-10 11:51:22 UTC 
With the steps given in description I'm still able to reproduce it.
Comment 9 Noriko Hosoi 2016-05-25 20:52:08 UTC 
William and Viktor, I think you'd better talk on the same page... :)

https://fedorahosted.org/389/ticket/48007#comment:10
> I can reproduce "getting the change log to trim" but in my tests, it appears that the moment I set the new trim time, it's taking effect immediately, and correctly. I think this is actually not an issue, and the difference in log times is a co-incidence.
>
> I would like to close this as "not a bug" if that's okay with you, but I am happy to discuss it more if you like. Do you still want the test case that proves it's not an issue?
Comment 10 Viktor Ashirov 2016-05-31 13:46:53 UTC 
I tried William's test on the affected version, it fails with

        # Now parse the trim_event lines. We should only see 5 seconds between them.
        # This test basically should generate 3 trim events.
        # The first one from the server setup, one from the first add, a third from the last.
>       assert(len(trim_events) >= 3)
E       assert 0 >= 3
E        +  where 0 = len([])


On 389-ds-base-1.3.5.4-1.el7.x86_64:
        # Now parse the trim_event lines. We should only see 5 seconds between them.
        # This test basically should generate 3 trim events.
        # The first one from the server setup, one from the first add, a third from the last.
>       assert(len(trim_events) >= 3)
E       assert 2 >= 3
E        +  where 2 = len(['[31/May/2016:09:31:06.492981568 -0400] Trimmed 17 changes from the changelog\n', '[31/May/2016:09:31:13.797244226 -0400] Trimmed 9 changes from the changelog\n'])

Actually in the logs:
grep trim /var/log/dirsrv/slapd-master_1/errors -i
[31/May/2016:09:31:06.492981568 -0400] Trimmed 17 changes from the changelog
[31/May/2016:09:31:13.797244226 -0400] Trimmed 9 changes from the changelog
[31/May/2016:09:36:13.947764120 -0400] Trimmed 11 changes from the changelog

I don't know why it took 5 minutes to trim last changes.
Comment 11 Viktor Ashirov 2016-05-31 13:47:49 UTC 
Created attachment 1163243 [details]
ticket48007_test.py
Comment 17 mreynolds 2017-10-23 19:45:40 UTC 
I can confirm that 1.3.7 works correctly.  Perhaps the test case is flawed, but I stepped through the code and everything is working after changing the trim interval.  The trimming thread wakes up right after the config change as you would expect, and it does trim entries (if those entries have exceeded the changelog maxage).
Comment 18 mreynolds 2017-10-31 14:57:28 UTC 
Created attachment 1345973 [details]
verification lib389 test script

This is a revised test case that shows the server is working as expected