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 _______________________________________________ 389-users mailing list -- 389-users(a)lists.fedoraproject.org To unsubscribe send an email to 389-users-leave(a)lists.fedoraproject.org Fedora Code of Conduct: https://docs.fedoraproject.org/en-US/project/code-of-conduct/ List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines List Archives: https://lists.fedoraproject.org/archives/list/389-users@lists.fedoraproje... Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

On 13-07-2022 13:01, Kees Bakker wrote: > Hi, > > [...] > 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. Unless, ... cur_time is the relative time since start of the server (not sure if this is true, but the code in eq_call_all_rel() seems to suggest it) ts.ts_s_last_trim is 0 at startup Shouldn't we compare "first_time" with the current (non-relative) time?

**** EXTERNAL E-MAIL **** On 7/13/22 3:18 PM, Kees Bakker wrote: > On 13-07-2022 13:39, Kees Bakker wrote: >> On 13-07-2022 13:01, Kees Bakker wrote: >>> Hi, >>> >>> [...] >>> 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. >> >> Unless, ... >> cur_time is the relative time since start of the server (not sure if this is true, >> but the code in eq_call_all_rel() seems to suggest it) >> ts.ts_s_last_trim is 0 at startup >> >> Shouldn't we compare "first_time" with the current (non-relative) time? > > First an answer to Pierre's question > I had nsslapd-changelogmaxage set to 480d. (The reason for that is that I just want to trim > the small subset.) > > I changed maxage back to the default 2d. Now I see the this message, quickly after restart. > > Jul 13 14:33:13 iparep4.example.com ns-slapd[141407]: [13/Jul/2022:14:33:13.806790126 +0200] - DEBUG - DSRetroclPlugin - cltrim: ldrc=0, first_time=1615990532, cur_time=12006600 > > I'm now convinced that the logic is (still) flawed. There is still a mix of UTC time and relative time. > >         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)) { <<<< wrong condition >             /* Is the first entry too old? */ >             time_t first_time; >             time_t now_maxage = slapi_current_utc_time(); /* real time for trimming candidates */ > Hi Kees, The mix of monotonic/real time was already an issue (https://github.com/389ds/389-ds-base/issues/4869) that was fixed in you version 1.4.3.28-6. I think 'first_time' is coming from the first registered record in the retroCL.  I wonder if it could be because of an old retroCL DB containing an old value, not matching current monotonic time. Could you dump the first record of the retroCL (dbscan) ? regards thierry

On 7/13/22 5:08 PM, Kees Bakker wrote: > On 13-07-2022 16:31, Thierry Bordaz wrote: >> On 7/13/22 3:18 PM, Kees Bakker wrote: >>> On 13-07-2022 13:39, Kees Bakker wrote: >>>> On 13-07-2022 13:01, Kees Bakker wrote: >>>>> Hi, >>>>> >>>>> [...] >>>>> 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)) { >>>>> I agree with you, the use of ts_c_max_age is wrong. The trimming mechanism should run periodically, whatever the maxage of the records. Here we should check an interval of time, (each hour or 10 min...). Would you please open a ticket for that ?