[389-users] Retro Changelog trimming not working

Hi,

Retro Changelog Trimming continues to give me headaches. In short, trimming does not work.
The number of entries keep piling up. One server now has a 4Gb database (480 days of changelogs).
Another server has about 2Gb (218 days).

We were using rpm packages

389-ds-base-1.4.3.23-10.module_el8.5+946+51aba098.x86_64
389-ds-base-libs-1.4.3.23-10.module_el8.5+946+51aba098.x86_64

This version has a known problem [1], so I know that trimming does not work.

This week I upgraded one system to 1.4.2.28-6.module_el8.6.0+1102+fe5d910f
I'm a bit puzzled, trimming still doesn't work. With enabled debug I see this message
about every five minutes. (Also a few debug lines after restart.)

Jul 13 10:01:52 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:01:52.304836309 +0200] - DEBUG - plugin_print_lists -   Retro Changelog Plugin (precedence: 25)
Jul 13 10:01:54 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:01:54.286755784 +0200] - DEBUG - plugin_print_lists -   Retrocl postoperation plugin (precedence: 25)
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.211710079 +0200] - DEBUG - plugin_dependency_startall - Starting object plugin Retro Changelog Plugin
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.566700485 +0200] - DEBUG - DSRetroclPlugin - cn=changelog already existed
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.604862146 +0200] - DEBUG - retrocl - Got changenumbers 15888 and 2578430
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.661391716 +0200] - DEBUG - DSRetroclPlugin - retrocl_start - nsslapd-attribute:
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.694197373 +0200] - DEBUG - DSRetroclPlugin - retrocl_start - nsuniqueid:targetUniqueId
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.719301803 +0200] - DEBUG - DSRetroclPlugin - retrocl_start - Attributes:
Jul 13 10:02:12 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:12.744411445 +0200] - DEBUG - DSRetroclPlugin -  - nsuniqueid [targetUniqueId]
Jul 13 10:02:16 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:02:16.294477996 +0200] - DEBUG - DSRetroclPlugin - retrocl_housekeeping - changelog does not need to be trimmed
Jul 13 10:03:14 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:03:14.217129558 +0200] - DEBUG - DSRetroclPlugin - retrocl_housekeeping - changelog does not need to be trimmed
Jul 13 10:08:13 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:08:13.902950611 +0200] - DEBUG - DSRetroclPlugin - retrocl_housekeeping - changelog does not need to be trimmed
Jul 13 10:13:13 iparep4.example.com ns-slapd[140367]: [13/Jul/2022:10:13:13.193109483 +0200] - DEBUG - DSRetroclPlugin - retrocl_housekeeping - changelog does not need to be trimmed

[root@iparep4 ~]# ldapsearch -H ldaps://$HOSTNAME -D "cn=Directory Manager" -y p -LLL -o ldif-wrap=no -b 'changenumber=15888,cn=changelog' changeNumber changeTime
dn: changenumber=15888,cn=changelog
changeNumber: 15888
changeTime: 20210317141532Z

This is strange because on the other server with 1.4.3.23 I get these messages:

Jul 12 11:17:19 rotte.example.com ns-slapd[2398871]: [12/Jul/2022:11:17:19.710733008 +0200] - DEBUG - DSRetroclPlugin - cltrim: ldrc=0, first_time=1638871758, cur_time=11908500
Jul 12 11:17:19 rotte.example.com ns-slapd[2398871]: [12/Jul/2022:11:17:19.711707843 +0200] - DEBUG - DSRetroclPlugin - retrocl_housekeeping - changelog does not need to be trimmed
Jul 12 11:22:19 rotte.example.com ns-slapd[2398871]: [12/Jul/2022:11:22:19.910817088 +0200] - DEBUG - DSRetroclPlugin - cltrim: ldrc=0, first_time=1638871758, cur_time=11908800
Jul 12 11:22:19 rotte.example.com ns-slapd[2398871]: [12/Jul/2022:11:22:19.911893609 +0200] - DEBUG - DSRetroclPlugin - retrocl_housekeeping - changelog does not need to be trimmed

[root@rotte ~]# ldapsearch -H ldaps://$HOSTNAME -D "cn=Directory Manager" -y p -LLL -o ldif-wrap=no -b 'changenumber=1,cn=changelog' changeNumber changeTime
dn: changenumber=1,cn=changelog
changeNumber: 1
changeTime: 20211207100918Z

In other words, with 1.4.3.28 I don't get to see the message with first_time and cur_time. I'm
quite puzzled how that can happen. The code is like this (stripped a bit):

    if (!ts.ts_s_trimming) {
        int must_trim = 0;
        /* See if we need to trim */
        /* Has enough time elapsed since our last check? */
        if (cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)) {
            /* Is the first entry too old? */
            time_t first_time;
...
            slapi_log_err(SLAPI_LOG_PLUGIN, RETROCL_PLUGIN_NAME,
                          "cltrim: ldrc=%d, first_time=%ld, cur_time=%ld\n",
                          ldrc, first_time, cur_time);
            if (LDAP_SUCCESS == ldrc && first_time > (time_t)0L &&
                first_time + ts.ts_c_max_age < now_maxage)
            {
                must_trim = 1;
            }
        }
        if (must_trim) {
...
        } else {
            slapi_log_err(SLAPI_LOG_PLUGIN, RETROCL_PLUGIN_NAME,
                          "retrocl_housekeeping - changelog does not need to be trimmed\n");
        }
    }

Puzzled, because I don't understand why "cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)"
is FALSE.

[1] https://github.com/389ds/389-ds-base/issues/4869
--
Kees