Retro Changelog trimming not working

[Kees Bakker]

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

[Pierre Rogier]

Hi Kees,

Could you provide the retrochangelog plugin entry from the dse.ldif ?
( First thing to check is that nsslapd-changelogmaxage is present and that
there is not a typo in its value.)

Regards
   Pierre

On Wed, Jul 13, 2022 at 1:04 PM Kees Bakker <keesb(a)ghs.com&gt; wrote:

>  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/[e-mail]...
>  Do not reply to spam on the list, report it:
>  https://pagure.io/fedora-infrastructure
>  

-- 
--

389 Directory Server Development Team

[Kees Bakker]

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?
-- 
Kees

[Kees Bakker]

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 */


-- 
Kees

[Thierry Bordaz]

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

>  -- 
>  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/[e-mail]...
>  Do not reply to spam on the list, report it: https://pagure.io/fedora-infrastructure

[Kees Bakker]

On 13-07-2022 16:31, Thierry Bordaz wrote:
>  **** 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
>  
Hi Thierry,

Here is an example of an old changelog entry.

[root@iparep4 ~]# ldapsearch -H ldaps://$HOSTNAME -D "cn=Directory Manager" -y p
-LLL -o ldif-wrap=no -b 'changenumber=20000,cn=changelog'
dn: changenumber=20000,cn=changelog
objectClass: top
objectClass: changelogentry
objectClass: extensibleObject
targetuniqueid: 23f6980a-87f611eb-872490e8-ab7c8ee8
changeNumber: 20000
targetDn: idnsName=110,idnsname=30.16.172.in-addr.arpa.,cn=dns,dc=example,dc=com
changeTime: 20210318152832Z
changeType: delete

Yes, I know about issue 4869. That's why I am now trying 1.4.3.28

But I want you to take another look at this line

    if (cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)) {

This code has the effect of using "maxage"  to determine when to do the trim
run!!!.
This is wrong.

And a few lines further

                 if (LDAP_SUCCESS == ldrc && first_time > (time_t)0L
&&
                     first_time + ts.ts_c_max_age < now_maxage)
                 {
                     must_trim = 1;
                 }

Here "maxage" is used the way it should be used, as a maximum age for the
changelog
entries. This is good.

If I set maxage to 480 then I have to wait until 480 days after restarting the server
before it finally
decides to look at first_time.

Maybe now is also a good time to explain why I set a much higher maxage value.
When trimming finally kicks in (since I now have maxage 2d) then entries are being
deleted
at an extreemly slow pace, roughly one per second. But the worse part is, the server
becomes
unresponsive after a few minutes. All connected LDAP clients hang, without getting a
timeout.
And because plugin debug messages are enabled, I can see that it stopped deleting
entries.
-- Kees

[Thierry Bordaz]

On 7/13/22 5:08 PM, Kees Bakker wrote:
>  On 13-07-2022 16:31, Thierry Bordaz wrote:
> > **** 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)) {
> >>>> 
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 ?

thanks
thierry

> >>>>                 /* 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
> >
>  Hi Thierry,
>
>  Here is an example of an old changelog entry.
>
>  [root@iparep4 ~]# ldapsearch -H ldaps://$HOSTNAME -D "cn=Directory 
>  Manager" -y p -LLL -o ldif-wrap=no -b 'changenumber=20000,cn=changelog'
>  dn: changenumber=20000,cn=changelog
>  objectClass: top
>  objectClass: changelogentry
>  objectClass: extensibleObject
>  targetuniqueid: 23f6980a-87f611eb-872490e8-ab7c8ee8
>  changeNumber: 20000
>  targetDn: 
>  idnsName=110,idnsname=30.16.172.in-addr.arpa.,cn=dns,dc=example,dc=com
>  changeTime: 20210318152832Z
>  changeType: delete
>
>  Yes, I know about issue 4869. That's why I am now trying 1.4.3.28
>
>  But I want you to take another look at this line
>
>      if (cur_time - ts.ts_s_last_trim >= (ts.ts_c_max_age)) {
>
>  This code has the effect of using "maxage"  to determine when to do 
>  the trim run!!!.
>  This is wrong.
>
>  And a few lines further
>
>                  if (LDAP_SUCCESS == ldrc && first_time > (time_t)0L
> &&
>                      first_time + ts.ts_c_max_age < now_maxage)
>                  {
>                      must_trim = 1;
>                  }
>
>  Here "maxage" is used the way it should be used, as a maximum age for 
>  the changelog
>  entries. This is good.
>
>  If I set maxage to 480 then I have to wait until 480 days after 
>  restarting the server before it finally
>  decides to look at first_time.
>
>  Maybe now is also a good time to explain why I set a much higher 
>  maxage value.
>  When trimming finally kicks in (since I now have maxage 2d) then 
>  entries are being deleted
>  at an extreemly slow pace, roughly one per second. But the worse part 
>  is, the server becomes
>  unresponsive after a few minutes. All connected LDAP clients hang, 
>  without getting a timeout.
>  And because plugin debug messages are enabled, I can see that it 
>  stopped deleting entries.
>  -- Kees

[Kees Bakker]

On 13-07-2022 18:49, Thierry Bordaz wrote:
>  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 ?
>  
Done.
https://github.com/389ds/389-ds-base/issues/5368
-- 
Kees