From 08012009e44f3b29473a4ea4546d70e4d118a4e7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Kuzn=C3=ADk?= Date: Mon, 9 Feb 2026 11:17:24 +0000 Subject: [PATCH 1/2] ITS#10293 Keep controls around for a little longer so we can log the cookie --- servers/slapd/syncrepl.c | 13 ++----------- 1 file changed, 2 insertions(+), 11 deletions(-) diff --git a/servers/slapd/syncrepl.c b/servers/slapd/syncrepl.c index 7b870c4ac9..aed438582e 100644 --- a/servers/slapd/syncrepl.c +++ b/servers/slapd/syncrepl.c @@ -1465,7 +1465,6 @@ do_syncrep2( Debug( LDAP_DEBUG_ANY, "do_syncrep2: %s " "got search entry with multiple " "Sync State control (%s)\n", si->si_ridtxt, bdn.bv_val ); - ldap_controls_free( rctrls ); rc = -1; goto entry_done; } @@ -1476,8 +1475,6 @@ do_syncrep2( "got search entry without " "Sync State control (%s)\n", si->si_ridtxt, bdn.bv_val ); rc = -1; - if ( rctrls ) - ldap_controls_free( rctrls ); goto entry_done; } ber_init2( ber, &rctrlp->ldctl_value, LBER_USE_DER ); @@ -1486,7 +1483,6 @@ do_syncrep2( bdn.bv_val[bdn.bv_len] = '\0'; Debug( LDAP_DEBUG_ANY, "do_syncrep2: %s malformed message (%s)\n", si->si_ridtxt, bdn.bv_val ); - ldap_controls_free( rctrls ); rc = -1; goto entry_done; } @@ -1498,7 +1494,6 @@ do_syncrep2( "got empty or invalid syncUUID with LDAP_SYNC_%s (%s)\n", si->si_ridtxt, syncrepl_state2str( syncstate ), bdn.bv_val ); - ldap_controls_free( rctrls ); rc = -1; goto entry_done; } @@ -1528,7 +1523,6 @@ do_syncrep2( ldap_pvt_thread_mutex_unlock( &si->si_cookieState->cs_mutex ); if ( i == CV_CSN_OLD ) { si->si_too_old = 1; - ldap_controls_free( rctrls ); rc = 0; /* Should we loop instead? */ goto entry_done; @@ -1537,7 +1531,6 @@ do_syncrep2( /* check pending CSNs too */ if (( rc = get_pmutex( si ))) { - ldap_controls_free( rctrls ); goto entry_done; } @@ -1547,7 +1540,6 @@ do_syncrep2( syncCookie.ctxcsn ); } else if ( i == CV_CSN_OLD ) { ldap_pvt_thread_mutex_unlock( &si->si_cookieState->cs_pmutex ); - ldap_controls_free( rctrls ); rc = 0; /* Should we loop instead? */ goto entry_done; @@ -1563,7 +1555,6 @@ do_syncrep2( bdn.bv_val[bdn.bv_len] = '\0'; Debug( LDAP_DEBUG_SYNC, "do_syncrep2: %s CSN too old, ignoring (%s)\n", si->si_ridtxt, bdn.bv_val ); - ldap_controls_free( rctrls ); rc = 0; /* Should we loop instead? */ goto entry_done; @@ -1606,7 +1597,6 @@ logerr: { if ( punlock < 0 ) { if (( rc = get_pmutex( si ))) { - ldap_controls_free( rctrls ); slap_mods_free( modlist, 1 ); entry_free( entry ); goto entry_done; @@ -1639,7 +1629,6 @@ logerr: } ldap_pvt_thread_mutex_unlock( &si->si_cookieState->cs_pmutex ); } - ldap_controls_free( rctrls ); if ( modlist ) { slap_mods_free( modlist, 1 ); } @@ -1660,6 +1649,8 @@ entry_done: (int)now.tv_sec, (int)now.tv_usec, rc ? "failed" : "processed" ); } + if ( rctrls ) + ldap_controls_free( rctrls ); if ( rc ) goto done; break; From 3c8e8338f02b9855a75bcae761ceba9f7f668256 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Kuzn=C3=ADk?= Date: Mon, 16 Feb 2026 11:07:14 +0000 Subject: [PATCH 2/2] ITS#10293 Adjust when the new logs kick in --- include/ldap_log.h | 2 ++ servers/slapd/syncrepl.c | 28 ++++++++++++++-------------- 2 files changed, 16 insertions(+), 14 deletions(-) diff --git a/include/ldap_log.h b/include/ldap_log.h index eaa5dc10a0..7a53683a9f 100644 --- a/include/ldap_log.h +++ b/include/ldap_log.h @@ -122,6 +122,8 @@ LDAP_BEGIN_DECL #endif #define LDAP_DEBUG_SYNC 0x4000 +#define LDAP_DEBUG_SYNCSTATS LDAP_DEBUG_STATS + #define LDAP_DEBUG_NONE 0x8000 #define LDAP_DEBUG_ANY (-1) diff --git a/servers/slapd/syncrepl.c b/servers/slapd/syncrepl.c index aed438582e..d5700262ff 100644 --- a/servers/slapd/syncrepl.c +++ b/servers/slapd/syncrepl.c @@ -1392,7 +1392,7 @@ do_syncrep2( if ( modlist ) slap_mods_free( modlist, 1); - if ( LogTest( LDAP_DEBUG_STATS ) ) { + if ( LogTest( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC ) ) { struct timeval now; gettimeofday( &now, NULL ); now.tv_sec -= si->si_lastcontact.tv_sec; @@ -1401,7 +1401,7 @@ do_syncrep2( --now.tv_sec; now.tv_usec += 1000000; } - Debug( LDAP_DEBUG_STATS, "%s DIRSYNC ENTRY " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s DIRSYNC ENTRY " "dn=\"%s\" state=%d etime=%d.%06d result=%s\n", si->si_ridtxt, entry ? entry->e_name.bv_val : "NULL", syncstate, (int)now.tv_sec, (int)now.tv_usec, @@ -1633,7 +1633,7 @@ logerr: slap_mods_free( modlist, 1 ); } entry_done: - if ( LogTest( LDAP_DEBUG_STATS ) ) { + if ( LogTest( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC ) ) { struct timeval now; gettimeofday( &now, NULL ); now.tv_sec -= si->si_lastcontact.tv_sec; @@ -1642,7 +1642,7 @@ entry_done: --now.tv_sec; now.tv_usec += 1000000; } - Debug( LDAP_DEBUG_STATS, "%s SYNC ENTRY " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC ENTRY " "dn=\"%s\" state=%d cookie=%s etime=%d.%06d result=%s\n", si->si_ridtxt, bdn.bv_val, syncstate, BER_BVISNULL( &cookie ) ? "" : cookie.bv_val, @@ -1659,7 +1659,7 @@ entry_done: Debug( LDAP_DEBUG_ANY, "do_syncrep2: %s reference received error\n", si->si_ridtxt ); - if ( LogTest( LDAP_DEBUG_STATS ) ) { + if ( LogTest( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC ) ) { struct timeval now; gettimeofday( &now, NULL ); now.tv_sec -= si->si_lastcontact.tv_sec; @@ -1668,7 +1668,7 @@ entry_done: --now.tv_sec; now.tv_usec += 1000000; } - Debug( LDAP_DEBUG_STATS, "%s SYNC REFERENCE " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC REFERENCE " "etime=%d.%06d result=failed\n", si->si_ridtxt, (int)now.tv_sec, (int)now.tv_usec ); } @@ -1824,7 +1824,7 @@ entry_done: rc = SYNC_REPOLL; } result_done: - if ( LogTest( LDAP_DEBUG_STATS ) ) { + if ( LogTest( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC ) ) { struct timeval now; gettimeofday( &now, NULL ); now.tv_sec -= si->si_lastcontact.tv_sec; @@ -1834,7 +1834,7 @@ result_done: } /* Space pointed to by cookie.bv_val is freed but the pointer * can still work as a discriminator */ - Debug( LDAP_DEBUG_STATS, "%s SYNC RESULT " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC RESULT " "err=%d delete=%d cookie=%s etime=%d.%06d result=%s\n", si->si_ridtxt, err, refreshDeletes != 0, BER_BVISNULL(&cookie) ? "" : syncCookie.octet_str.bv_val, @@ -1895,7 +1895,7 @@ result_done: si->si_ridtxt ); rc = LDAP_PROTOCOL_ERROR; - if ( LogTest( LDAP_DEBUG_STATS ) ) { + if ( LogTest( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC ) ) { struct timeval now; gettimeofday( &now, NULL ); now.tv_sec -= si->si_lastcontact.tv_sec; @@ -1903,7 +1903,7 @@ result_done: if ( now.tv_usec < 0 ) { --now.tv_sec; now.tv_usec += 1000000; } - Debug( LDAP_DEBUG_STATS, "%s SYNC %s " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC %s " "refreshDone=%d cookie=%s etime=%d.%06d result=failed\n", si->si_ridtxt, name, si->si_refreshDone != 0, BER_BVISNULL(&cookie) ? "" : cookie.bv_val, @@ -2056,7 +2056,7 @@ result_done: ldap_memfree( retoid ); ber_bvfree( retdata ); - if ( LogTest( LDAP_DEBUG_STATS ) ) { + if ( LogTest( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC ) ) { struct timeval now; const char *cookiestr = ""; @@ -2073,7 +2073,7 @@ result_done: switch ( si_tag ) { case LDAP_TAG_SYNC_NEW_COOKIE: - Debug( LDAP_DEBUG_STATS, "%s SYNC %s " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC %s " "cookie=%s etime=%d.%06d result=%s\n", si->si_ridtxt, name, cookiestr, (int)now.tv_sec, (int)now.tv_usec, @@ -2081,14 +2081,14 @@ result_done: break; case LDAP_TAG_SYNC_REFRESH_DELETE: case LDAP_TAG_SYNC_REFRESH_PRESENT: - Debug( LDAP_DEBUG_STATS, "%s SYNC %s refreshDone=%d " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC %s refreshDone=%d " "cookie=%s etime=%d.%06d result=%s\n", si->si_ridtxt, name, si->si_refreshDone != 0, cookiestr, (int)now.tv_sec, (int)now.tv_usec, rc ? "failed" : "processed" ); break; case LDAP_TAG_SYNC_ID_SET: - Debug( LDAP_DEBUG_STATS, "%s SYNC %s refreshDeletes=%d " + Debug( LDAP_DEBUG_SYNCSTATS | LDAP_DEBUG_SYNC, "%s SYNC %s refreshDeletes=%d " "cookie=%s etime=%d.%06d result=%s\n", si->si_ridtxt, name, refreshDeletes != 0, cookiestr, (int)now.tv_sec, (int)now.tv_usec,