mirror/openldap
2
0
Fork 0
mirror of https://git.openldap.org/openldap/openldap.git synced 2024-12-21 03:10:25 +08:00
Code Issues Packages Projects Releases Wiki Activity

ITS#9043 Improve replication loggging

Browse Source
This commit is contained in:
Ondřej Kuzník 2019-06-26 12:22:58 +02:00
parent bbe20cbf4c
commit f6d9fdc4f1
3 changed files with 156 additions and 26 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
servers/slapd/ctxcsn.c
View File

@ -209,6 +209,8 @@ slap_get_csn(
if ( csn == NULL ) return LDAP_OTHER; if ( csn == NULL ) return LDAP_OTHER;
csn->bv_len = ldap_pvt_csnstr( csn->bv_val, csn->bv_len, slap_serverID, 0 ); csn->bv_len = ldap_pvt_csnstr( csn->bv_val, csn->bv_len, slap_serverID, 0 );
Debug( LDAP_DEBUG_SYNC, "slap_get_csn: %s generated new csn=%s manage=%d\n",
op->o_log_prefix, csn->bv_val, manage_ctxcsn );
if ( manage_ctxcsn ) if ( manage_ctxcsn )
slap_queue_csn( op, csn ); slap_queue_csn( op, csn );

152
servers/slapd/overlays/syncprov.c
View File

@ -326,10 +326,18 @@ syncprov_sendinfo(
if ( type ) { if ( type ) {
switch ( type ) { switch ( type ) {
case LDAP_TAG_SYNC_NEW_COOKIE: case LDAP_TAG_SYNC_NEW_COOKIE:
Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendinfo: "
"sending a new cookie=%s\n",
op->o_log_prefix, cookie->bv_val );
ber_printf( ber, "tO", type, cookie ); ber_printf( ber, "tO", type, cookie );
break; break;
case LDAP_TAG_SYNC_REFRESH_DELETE: case LDAP_TAG_SYNC_REFRESH_DELETE:
case LDAP_TAG_SYNC_REFRESH_PRESENT: case LDAP_TAG_SYNC_REFRESH_PRESENT:
Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendinfo: "
"%s cookie=%s\n",
op->o_log_prefix,
type == LDAP_TAG_SYNC_REFRESH_DELETE ? "refreshDelete" : "refreshPresent",
cookie ? cookie->bv_val : "" );
ber_printf( ber, "t{", type ); ber_printf( ber, "t{", type );
if ( cookie ) { if ( cookie ) {
ber_printf( ber, "O", cookie ); ber_printf( ber, "O", cookie );
@ -340,6 +348,10 @@ syncprov_sendinfo(
ber_printf( ber, "N}" ); ber_printf( ber, "N}" );
break; break;
case LDAP_TAG_SYNC_ID_SET: case LDAP_TAG_SYNC_ID_SET:
Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendinfo: "
"%s syncIdSet cookie=%s\n",
op->o_log_prefix, refreshDeletes ? "delete" : "present",
cookie ? cookie->bv_val : "" );
ber_printf( ber, "t{", type ); ber_printf( ber, "t{", type );
if ( cookie ) { if ( cookie ) {
ber_printf( ber, "O", cookie ); ber_printf( ber, "O", cookie );
@ -352,8 +364,8 @@ syncprov_sendinfo(
break; break;
default: default:
Debug( LDAP_DEBUG_TRACE, Debug( LDAP_DEBUG_TRACE,
"syncprov_sendinfo: invalid syncinfo type (%d)\n", "%s syncprov_sendinfo: invalid syncinfo type (%d)\n",
type ); op->o_log_prefix, type );
return LDAP_OTHER; return LDAP_OTHER;
} }
} }
@ -472,6 +484,7 @@ syncprov_findbase( Operation *op, fbase_cookie *fc )
fop.ors_filter = &generic_filter; fop.ors_filter = &generic_filter;
fop.ors_filterstr = generic_filterstr; fop.ors_filterstr = generic_filterstr;
Debug( LDAP_DEBUG_SYNC, "%s syncprov_findbase: searching\n", op->o_log_prefix );
rc = fop.o_bd->be_search( &fop, &frs ); rc = fop.o_bd->be_search( &fop, &frs );
} else { } else {
ldap_pvt_thread_mutex_unlock( &fc->fss->s_mutex ); ldap_pvt_thread_mutex_unlock( &fc->fss->s_mutex );
@ -634,6 +647,15 @@ syncprov_findcsn( Operation *op, find_csn_t mode, struct berval *csn )
srs = op->o_controls[slap_cids.sc_LDAPsync]; srs = op->o_controls[slap_cids.sc_LDAPsync];
} }
Debug( LDAP_DEBUG_SYNC, "%s syncprov_findcsn: mode=%s csn=%s\n",
op->o_log_prefix,
mode == FIND_MAXCSN ?
"FIND_MAXCSN" :
mode == FIND_CSN ?
"FIND_CSN" :
"FIND_PRESENT",
csn ? csn->bv_val : "" );
fop = *op; fop = *op;
fop.o_sync_mode &= SLAP_CONTROL_MASK; /* turn off sync_mode */ fop.o_sync_mode &= SLAP_CONTROL_MASK; /* turn off sync_mode */
/* We want pure entries, not referrals */ /* We want pure entries, not referrals */
@ -754,6 +776,10 @@ again:
break; break;
case FIND_CSN: case FIND_CSN:
/* If matching CSN was not found, invalidate the context. */ /* If matching CSN was not found, invalidate the context. */
Debug( LDAP_DEBUG_SYNC, "%s syncprov_findcsn: csn%s=%s %sfound\n",
op->o_log_prefix,
cf.f_choice == LDAP_FILTER_EQUALITY ? "=" : "<",
cf.f_av_value.bv_val, cb.sc_private ? "" : "not " );
if ( !cb.sc_private ) { if ( !cb.sc_private ) {
/* If we didn't find an exact match, then try for <= */ /* If we didn't find an exact match, then try for <= */
if ( findcsn_retry ) { if ( findcsn_retry ) {
@ -865,11 +891,11 @@ syncprov_sendresp( Operation *op, resinfo *ri, syncops *so, int mode )
#ifdef LDAP_DEBUG #ifdef LDAP_DEBUG
if ( so->s_sid > 0 ) { if ( so->s_sid > 0 ) {
Debug( LDAP_DEBUG_SYNC, "syncprov_sendresp: to=%03x, cookie=%s\n", Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendresp: to=%03x, cookie=%s\n",
so->s_sid, cookie.bv_val ); op->o_log_prefix, so->s_sid, cookie.bv_val );
} else { } else {
Debug( LDAP_DEBUG_SYNC, "syncprov_sendresp: cookie=%s\n", Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendresp: cookie=%s\n",
cookie.bv_val ); op->o_log_prefix, cookie.bv_val );
} }
#endif #endif
@ -896,10 +922,17 @@ syncprov_sendresp( Operation *op, resinfo *ri, syncops *so, int mode )
} }
/* fallthru */ /* fallthru */
case LDAP_SYNC_MODIFY: case LDAP_SYNC_MODIFY:
Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendresp: sending %s, dn=%s\n",
op->o_log_prefix,
mode == LDAP_SYNC_ADD ? "LDAP_SYNC_ADD" : "LDAP_SYNC_MODIFY",
e_uuid.e_nname.bv_val );
rs.sr_attrs = op->ors_attrs; rs.sr_attrs = op->ors_attrs;
rs.sr_err = send_search_entry( op, &rs ); rs.sr_err = send_search_entry( op, &rs );
break; break;
case LDAP_SYNC_DELETE: case LDAP_SYNC_DELETE:
Debug( LDAP_DEBUG_SYNC, "%s syncprov_sendresp: "
"sending LDAP_SYNC_DELETE, dn=%s\n",
op->o_log_prefix, ri->ri_dn.bv_val );
e_uuid.e_attrs = NULL; e_uuid.e_attrs = NULL;
e_uuid.e_name = ri->ri_dn; e_uuid.e_name = ri->ri_dn;
e_uuid.e_nname = ri->ri_ndn; e_uuid.e_nname = ri->ri_ndn;
@ -1108,6 +1141,9 @@ syncprov_qresp( opcookie *opc, syncops *so, int mode )
slap_compose_sync_cookie( NULL, &ri->ri_cookie, si->si_ctxcsn, slap_compose_sync_cookie( NULL, &ri->ri_cookie, si->si_ctxcsn,
so->s_rid, slap_serverID ? slap_serverID : -1); so->s_rid, slap_serverID ? slap_serverID : -1);
} }
Debug( LDAP_DEBUG_SYNC, "%s syncprov_qresp: "
"set up a new syncres mode=%d csn=%s\n",
so->s_op->o_log_prefix, mode, csn.bv_val );
ldap_pvt_thread_mutex_unlock( &ri->ri_mutex ); ldap_pvt_thread_mutex_unlock( &ri->ri_mutex );
ldap_pvt_thread_mutex_lock( &so->s_mutex ); ldap_pvt_thread_mutex_lock( &so->s_mutex );
@ -1234,6 +1270,9 @@ syncprov_matchops( Operation *op, opcookie *opc, int saveit )
e = opc->se; e = opc->se;
} }
if ( rc ) { if ( rc ) {
Debug( LDAP_DEBUG_SYNC, "%s syncprov_matchops: "
"%s check, error finding entry dn=%s in database\n",
op->o_log_prefix, saveit ? "initial" : "final", fc.fdn->bv_val );
op->o_bd = b0; op->o_bd = b0;
return; return;
} }
@ -1253,6 +1292,9 @@ syncprov_matchops( Operation *op, opcookie *opc, int saveit )
a = attr_find( e->e_attrs, slap_schema.si_ad_entryUUID ); a = attr_find( e->e_attrs, slap_schema.si_ad_entryUUID );
if ( a ) if ( a )
ber_dupbv_x( &opc->suuid, &a->a_nvals[0], op->o_tmpmemctx ); ber_dupbv_x( &opc->suuid, &a->a_nvals[0], op->o_tmpmemctx );
Debug( LDAP_DEBUG_SYNC, "%s syncprov_matchops: "
"%srecording uuid for dn=%s on opc=%p\n",
op->o_log_prefix, a ? "" : "not ", opc->sdn.bv_val, opc );
} else if ( op->o_tag == LDAP_REQ_MODRDN && !saveit ) { } else if ( op->o_tag == LDAP_REQ_MODRDN && !saveit ) {
op->o_tmpfree( opc->sndn.bv_val, op->o_tmpmemctx ); op->o_tmpfree( opc->sndn.bv_val, op->o_tmpmemctx );
op->o_tmpfree( opc->sdn.bv_val, op->o_tmpmemctx ); op->o_tmpfree( opc->sdn.bv_val, op->o_tmpmemctx );
@ -1482,6 +1524,10 @@ syncprov_checkpoint( Operation *op, slap_overinst *on )
assert( !syn->ssyn_validate( syn, si->si_ctxcsn+i )); assert( !syn->ssyn_validate( syn, si->si_ctxcsn+i ));
} }
#endif #endif
Debug( LDAP_DEBUG_SYNC, "%s syncprov_checkpoint: running checkpoint\n",
op->o_log_prefix );
mod.sml_numvals = si->si_numcsns; mod.sml_numvals = si->si_numcsns;
mod.sml_values = si->si_ctxcsn; mod.sml_values = si->si_ctxcsn;
mod.sml_nvalues = NULL; mod.sml_nvalues = NULL;
@ -1583,6 +1629,17 @@ syncprov_add_slog( Operation *op )
se->se_sid = slap_parse_csn_sid( &se->se_csn ); se->se_sid = slap_parse_csn_sid( &se->se_csn );
ldap_pvt_thread_mutex_lock( &sl->sl_mutex ); ldap_pvt_thread_mutex_lock( &sl->sl_mutex );
if ( LogTest( LDAP_DEBUG_SYNC ) ) {
char uuidstr[40] = {};
if ( !BER_BVISEMPTY( &opc->suuid ) ) {
lutil_uuidstr_from_normalized( opc->suuid.bv_val, opc->suuid.bv_len,
uuidstr, 40 );
}
Debug( LDAP_DEBUG_SYNC, "%s syncprov_add_slog: "
"adding csn=%s to sessionlog, uuid=%s\n",
op->o_log_prefix, se->se_csn.bv_val, uuidstr );
}
if ( sl->sl_head ) { if ( sl->sl_head ) {
/* Keep the list in csn order. */ /* Keep the list in csn order. */
if ( ber_bvcmp( &sl->sl_tail->se_csn, &se->se_csn ) <= 0 ) { if ( ber_bvcmp( &sl->sl_tail->se_csn, &se->se_csn ) <= 0 ) {
@ -1617,13 +1674,22 @@ syncprov_add_slog( Operation *op )
int i; int i;
se = sl->sl_head; se = sl->sl_head;
sl->sl_head = se->se_next; sl->sl_head = se->se_next;
Debug( LDAP_DEBUG_SYNC, "%s syncprov_add_slog: "
"expiring csn=%s from sessionlog (sessionlog size=%d)\n",
op->o_log_prefix, se->se_csn.bv_val, sl->sl_num );
for ( i=0; i<sl->sl_numcsns; i++ ) for ( i=0; i<sl->sl_numcsns; i++ )
if ( sl->sl_sids[i] >= se->se_sid ) if ( sl->sl_sids[i] >= se->se_sid )
break; break;
if ( i == sl->sl_numcsns || sl->sl_sids[i] != se->se_sid ) { if ( i == sl->sl_numcsns || sl->sl_sids[i] != se->se_sid ) {
Debug( LDAP_DEBUG_SYNC, "%s syncprov_add_slog: "
"adding csn=%s to mincsn\n",
op->o_log_prefix, se->se_csn.bv_val );
slap_insert_csn_sids( (struct sync_cookie *)sl, slap_insert_csn_sids( (struct sync_cookie *)sl,
i, se->se_sid, &se->se_csn ); i, se->se_sid, &se->se_csn );
} else { } else {
Debug( LDAP_DEBUG_SYNC, "%s syncprov_add_slog: "
"updating mincsn for sid=%d csn=%s to %s\n",
op->o_log_prefix, se->se_sid, sl->sl_mincsn[i].bv_val, se->se_csn.bv_val );
ber_bvreplace( &sl->sl_mincsn[i], &se->se_csn ); ber_bvreplace( &sl->sl_mincsn[i], &se->se_csn );
} }
ch_free( se ); ch_free( se );
@ -1683,7 +1749,15 @@ syncprov_playlog( Operation *op, SlapReply *rs, sessionlog *sl,
srs->sr_state.ctxcsn[0].bv_val ); srs->sr_state.ctxcsn[0].bv_val );
for ( se=sl->sl_head; se; se=se->se_next ) { for ( se=sl->sl_head; se; se=se->se_next ) {
int k; int k;
Debug( LDAP_DEBUG_SYNC, "log csn %s\n", se->se_csn.bv_val );
if ( LogTest( LDAP_DEBUG_SYNC ) ) {
char uuidstr[40];
lutil_uuidstr_from_normalized( se->se_uuid.bv_val, se->se_uuid.bv_len,
uuidstr, 40 );
Debug( LDAP_DEBUG_SYNC, "%s syncprov_playlog: "
"log entry tag=%lu uuid=%s cookie=%s\n",
op->o_log_prefix, se->se_tag, uuidstr, se->se_csn.bv_val );
}
ndel = 1; ndel = 1;
for ( k=0; k<srs->sr_state.numcsns; k++ ) { for ( k=0; k<srs->sr_state.numcsns; k++ ) {
if ( se->se_sid == srs->sr_state.sids[k] ) { if ( se->se_sid == srs->sr_state.sids[k] ) {
@ -1692,7 +1766,8 @@ syncprov_playlog( Operation *op, SlapReply *rs, sessionlog *sl,
} }
} }
if ( ndel <= 0 ) { if ( ndel <= 0 ) {
Debug( LDAP_DEBUG_SYNC, "cmp %d, too old\n", ndel ); Debug( LDAP_DEBUG_SYNC, "%s syncprov_playlog: "
"cmp %d, too old\n", op->o_log_prefix, ndel );
continue; continue;
} }
ndel = 0; ndel = 0;
@ -1703,7 +1778,8 @@ syncprov_playlog( Operation *op, SlapReply *rs, sessionlog *sl,
} }
} }
if ( ndel > 0 ) { if ( ndel > 0 ) {
Debug( LDAP_DEBUG_SYNC, "cmp %d, too new\n", ndel ); Debug( LDAP_DEBUG_SYNC, "%s syncprov_playlog: "
"cmp %d, too new\n", op->o_log_prefix, ndel );
break; break;
} }
if ( se->se_tag == LDAP_REQ_DELETE ) { if ( se->se_tag == LDAP_REQ_DELETE ) {
@ -1721,6 +1797,16 @@ syncprov_playlog( Operation *op, SlapReply *rs, sessionlog *sl,
uuids[j].bv_val = uuids[0].bv_val + (j * UUID_LEN); uuids[j].bv_val = uuids[0].bv_val + (j * UUID_LEN);
AC_MEMCPY(uuids[j].bv_val, se->se_uuid.bv_val, UUID_LEN); AC_MEMCPY(uuids[j].bv_val, se->se_uuid.bv_val, UUID_LEN);
uuids[j].bv_len = UUID_LEN; uuids[j].bv_len = UUID_LEN;
if ( LogTest( LDAP_DEBUG_SYNC ) ) {
char uuidstr[40];
lutil_uuidstr_from_normalized( uuids[j].bv_val, uuids[j].bv_len,
uuidstr, 40 );
Debug( LDAP_DEBUG_SYNC, "%s syncprov_playlog: "
"picking a %s entry uuid=%s cookie=%s\n",
op->o_log_prefix, se->se_tag == LDAP_REQ_DELETE ? "deleted" : "modified",
uuidstr, delcsn[0].bv_len ? delcsn[0].bv_val : "(null)" );
}
} }
ldap_pvt_thread_mutex_lock( &sl->sl_mutex ); ldap_pvt_thread_mutex_lock( &sl->sl_mutex );
sl->sl_playing--; sl->sl_playing--;
@ -1809,7 +1895,8 @@ syncprov_playlog( Operation *op, SlapReply *rs, sessionlog *sl,
slap_compose_sync_cookie( op, &cookie, delcsn, srs->sr_state.rid, slap_compose_sync_cookie( op, &cookie, delcsn, srs->sr_state.rid,
slap_serverID ? slap_serverID : -1 ); slap_serverID ? slap_serverID : -1 );
Debug( LDAP_DEBUG_SYNC, "syncprov_playlog: cookie=%s\n", cookie.bv_val ); Debug( LDAP_DEBUG_SYNC, "%s syncprov_playlog: cookie=%s\n",
op->o_log_prefix, cookie.bv_val );
} }
uuids[ndel].bv_val = NULL; uuids[ndel].bv_val = NULL;
@ -2391,7 +2478,8 @@ syncprov_search_response( Operation *op, SlapReply *rs )
*/ */
if ( !rs->sr_entry ) { if ( !rs->sr_entry ) {
assert( rs->sr_entry != NULL ); assert( rs->sr_entry != NULL );
Debug( LDAP_DEBUG_ANY, "bogus referral in context\n" ); Debug( LDAP_DEBUG_ANY, "%s syncprov_search_response: "
"bogus referral in context\n", op->o_log_prefix );
return SLAP_CB_CONTINUE; return SLAP_CB_CONTINUE;
} }
a = attr_find( rs->sr_entry->e_attrs, slap_schema.si_ad_entryCSN ); a = attr_find( rs->sr_entry->e_attrs, slap_schema.si_ad_entryCSN );
@ -2408,8 +2496,9 @@ syncprov_search_response( Operation *op, SlapReply *rs )
for ( i=0; i<ss->ss_numcsns; i++ ) { for ( i=0; i<ss->ss_numcsns; i++ ) {
if ( sid == ss->ss_sids[i] && ber_bvcmp( &a->a_nvals[0], if ( sid == ss->ss_sids[i] && ber_bvcmp( &a->a_nvals[0],
&ss->ss_ctxcsn[i] ) > 0 ) { &ss->ss_ctxcsn[i] ) > 0 ) {
Debug( LDAP_DEBUG_SYNC, Debug( LDAP_DEBUG_SYNC, "%s syncprov_search_response: "
"Entry %s CSN %s greater than snapshot %s\n", "Entry %s CSN %s greater than snapshot %s\n",
op->o_log_prefix,
rs->sr_entry->e_name.bv_val, rs->sr_entry->e_name.bv_val,
a->a_nvals[0].bv_val, a->a_nvals[0].bv_val,
ss->ss_ctxcsn[i].bv_val ); ss->ss_ctxcsn[i].bv_val );
@ -2424,8 +2513,9 @@ syncprov_search_response( Operation *op, SlapReply *rs )
if ( sid == srs->sr_state.sids[i] && if ( sid == srs->sr_state.sids[i] &&
ber_bvcmp( &a->a_nvals[0], ber_bvcmp( &a->a_nvals[0],
&srs->sr_state.ctxcsn[i] )<= 0 ) { &srs->sr_state.ctxcsn[i] )<= 0 ) {
Debug( LDAP_DEBUG_SYNC, Debug( LDAP_DEBUG_SYNC, "%s syncprov_search_response: "
"Entry %s CSN %s older or equal to ctx %s\n", "Entry %s CSN %s older or equal to ctx %s\n",
op->o_log_prefix,
rs->sr_entry->e_name.bv_val, rs->sr_entry->e_name.bv_val,
a->a_nvals[0].bv_val, a->a_nvals[0].bv_val,
srs->sr_state.ctxcsn[i].bv_val ); srs->sr_state.ctxcsn[i].bv_val );
@ -2457,7 +2547,8 @@ syncprov_search_response( Operation *op, SlapReply *rs )
slap_compose_sync_cookie( op, &cookie, ss->ss_ctxcsn, slap_compose_sync_cookie( op, &cookie, ss->ss_ctxcsn,
srs->sr_state.rid, slap_serverID ? slap_serverID : -1 ); srs->sr_state.rid, slap_serverID ? slap_serverID : -1 );
Debug( LDAP_DEBUG_SYNC, "syncprov_search_response: cookie=%s\n", cookie.bv_val ); Debug( LDAP_DEBUG_SYNC, "%s syncprov_search_response: cookie=%s\n",
op->o_log_prefix, cookie.bv_val );
} }
/* Is this a regular refresh? /* Is this a regular refresh?
@ -2495,6 +2586,8 @@ syncprov_search_response( Operation *op, SlapReply *rs )
/* Turn off the refreshing flag */ /* Turn off the refreshing flag */
ss->ss_so->s_flags ^= PS_IS_REFRESHING; ss->ss_so->s_flags ^= PS_IS_REFRESHING;
Debug( LDAP_DEBUG_SYNC, "%s syncprov_search_response: "
"detaching op\n", op->o_log_prefix );
syncprov_detach_op( op, ss->ss_so, on ); syncprov_detach_op( op, ss->ss_so, on );
ldap_pvt_thread_mutex_unlock( &op->o_conn->c_mutex ); ldap_pvt_thread_mutex_unlock( &op->o_conn->c_mutex );
@ -2536,6 +2629,11 @@ syncprov_op_search( Operation *op, SlapReply *rs )
} }
srs = op->o_controls[slap_cids.sc_LDAPsync]; srs = op->o_controls[slap_cids.sc_LDAPsync];
Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"got a %ssearch with a cookie=%s\n",
op->o_log_prefix,
op->o_sync_mode & SLAP_SYNC_PERSIST ? "persistent ": "",
srs->sr_state.octet_str.bv_val );
/* If this is a persistent search, set it up right away */ /* If this is a persistent search, set it up right away */
if ( op->o_sync_mode & SLAP_SYNC_PERSIST ) { if ( op->o_sync_mode & SLAP_SYNC_PERSIST ) {
@ -2599,6 +2697,8 @@ syncprov_op_search( Operation *op, SlapReply *rs )
sop->s_si = si; sop->s_si = si;
si->si_ops = sop; si->si_ops = sop;
ldap_pvt_thread_mutex_unlock( &si->si_ops_mutex ); ldap_pvt_thread_mutex_unlock( &si->si_ops_mutex );
Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"registered persistent search\n", op->o_log_prefix );
} }
/* snapshot the ctxcsn /* snapshot the ctxcsn
@ -2658,6 +2758,9 @@ syncprov_op_search( Operation *op, SlapReply *rs )
if (srs->sr_state.numcsns != numcsns) { if (srs->sr_state.numcsns != numcsns) {
/* consumer doesn't have the right number of CSNs */ /* consumer doesn't have the right number of CSNs */
Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"consumer cookie is missing a csn we track\n",
op->o_log_prefix );
changed = SS_CHANGED; changed = SS_CHANGED;
if ( srs->sr_state.ctxcsn ) { if ( srs->sr_state.ctxcsn ) {
ber_bvarray_free_x( srs->sr_state.ctxcsn, op->o_tmpmemctx ); ber_bvarray_free_x( srs->sr_state.ctxcsn, op->o_tmpmemctx );
@ -2695,9 +2798,10 @@ syncprov_op_search( Operation *op, SlapReply *rs )
/* our state is older, complain to consumer */ /* our state is older, complain to consumer */
rs->sr_err = LDAP_UNWILLING_TO_PERFORM; rs->sr_err = LDAP_UNWILLING_TO_PERFORM;
rs->sr_text = "consumer state is newer than provider!"; rs->sr_text = "consumer state is newer than provider!";
Log( LDAP_DEBUG_SYNC, ldap_syslog_level, Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"consumer %d state %s is newer than provider %d state %s\n", "consumer %d state %s is newer than provider %d state %s\n",
sids[i], srs->sr_state.ctxcsn[i].bv_val, sids[j], /* == slap_serverID */ op->o_log_prefix, sids[i], srs->sr_state.ctxcsn[i].bv_val,
sids[j], /* == slap_serverID */
ctxcsn[j].bv_val); ctxcsn[j].bv_val);
bailout: bailout:
if ( sop ) { if ( sop ) {
@ -2736,6 +2840,9 @@ no_change: if ( !(op->o_sync_mode & SLAP_SYNC_PERSIST) ) {
rs->sr_ctrls = NULL; rs->sr_ctrls = NULL;
return rs->sr_err; return rs->sr_err;
} }
Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"no change, skipping log replay\n",
op->o_log_prefix );
goto shortcut; goto shortcut;
} }
@ -2788,6 +2895,9 @@ no_change: if ( !(op->o_sync_mode & SLAP_SYNC_PERSIST) ) {
rs->sr_text = "sync cookie is stale"; rs->sr_text = "sync cookie is stale";
goto bailout; goto bailout;
} }
Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"failed to find entry with csn=%s, ignoring cookie\n",
op->o_log_prefix, mincsn.bv_val );
if ( srs->sr_state.ctxcsn ) { if ( srs->sr_state.ctxcsn ) {
ber_bvarray_free_x( srs->sr_state.ctxcsn, op->o_tmpmemctx ); ber_bvarray_free_x( srs->sr_state.ctxcsn, op->o_tmpmemctx );
srs->sr_state.ctxcsn = NULL; srs->sr_state.ctxcsn = NULL;
@ -2874,6 +2984,9 @@ shortcut:
* us into persist phase * us into persist phase
*/ */
if ( !changed && !dirty ) { if ( !changed && !dirty ) {
Debug( LDAP_DEBUG_SYNC, "%s syncprov_op_search: "
"nothing changed, finishing up initial search early\n",
op->o_log_prefix );
rs->sr_err = LDAP_SUCCESS; rs->sr_err = LDAP_SUCCESS;
rs->sr_nentries = 0; rs->sr_nentries = 0;
send_ldap_result( op, rs ); send_ldap_result( op, rs );
@ -3165,6 +3278,10 @@ syncprov_db_open(
return rc; return rc;
} }
Debug( LDAP_DEBUG_SYNC, "syncprov_db_open: "
"starting syncprov for suffix %s\n",
be->be_suffix[0].bv_val );
thrctx = ldap_pvt_thread_pool_context(); thrctx = ldap_pvt_thread_pool_context();
connection_fake_init2( &conn, &opbuf, thrctx, 0 ); connection_fake_init2( &conn, &opbuf, thrctx, 0 );
op = &opbuf.ob_op; op = &opbuf.ob_op;
@ -3223,6 +3340,9 @@ syncprov_db_open(
si->si_numcsns = 1; si->si_numcsns = 1;
si->si_sids = ch_malloc( sizeof(int) ); si->si_sids = ch_malloc( sizeof(int) );
si->si_sids[0] = slap_serverID; si->si_sids[0] = slap_serverID;
Debug( LDAP_DEBUG_SYNC, "syncprov_db_open: "
"generated a new ctxcsn=%s for suffix %s\n",
csn.bv_val, be->be_suffix[0].bv_val );
/* make sure we do a checkpoint on close */ /* make sure we do a checkpoint on close */
si->si_numops++; si->si_numops++;

28
servers/slapd/syncrepl.c
View File

@ -946,8 +946,8 @@ do_syncrep1(
} }
si->si_refreshDone = 0; si->si_refreshDone = 0;
Debug( LDAP_DEBUG_SYNC, "do_syncrep1: %s starting refresh\n", Debug( LDAP_DEBUG_SYNC, "do_syncrep1: %s starting refresh (sending cookie=%s)\n",
si->si_ridtxt ); si->si_ridtxt, si->si_syncCookie.octet_str.bv_val );
rc = ldap_sync_search( si, op->o_tmpmemctx ); rc = ldap_sync_search( si, op->o_tmpmemctx );
@ -3700,8 +3700,8 @@ syncrepl_entry(
int freecsn = 1; int freecsn = 1;
Debug( LDAP_DEBUG_SYNC, Debug( LDAP_DEBUG_SYNC,
"syncrepl_entry: %s LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_%s) tid %x\n", "syncrepl_entry: %s LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_%s) csn=%s tid %x\n",
si->si_ridtxt, syncrepl_state2str( syncstate ), op->o_tid ); si->si_ridtxt, syncrepl_state2str( syncstate ), syncCSN ? syncCSN->bv_val : "(none)", op->o_tid );
if (( syncstate == LDAP_SYNC_PRESENT || syncstate == LDAP_SYNC_ADD ) ) { if (( syncstate == LDAP_SYNC_PRESENT || syncstate == LDAP_SYNC_ADD ) ) {
if ( !si->si_refreshPresent && !si->si_refreshDone ) { if ( !si->si_refreshPresent && !si->si_refreshDone ) {
@ -4327,6 +4327,9 @@ syncrepl_del_nonpresent(
op->ors_slimit = 1; op->ors_slimit = 1;
uf.f_av_value = uuids[i]; uf.f_av_value = uuids[i];
filter2bv_x( op, op->ors_filter, &op->ors_filterstr ); filter2bv_x( op, op->ors_filter, &op->ors_filterstr );
Debug( LDAP_DEBUG_SYNC, "syncrepl_del_nonpresent: %s "
"checking non-present filter=%s\n",
si->si_ridtxt, op->ors_filterstr.bv_val );
rc = be->be_search( op, &rs_search ); rc = be->be_search( op, &rs_search );
op->o_tmpfree( op->ors_filterstr.bv_val, op->o_tmpmemctx ); op->o_tmpfree( op->ors_filterstr.bv_val, op->o_tmpmemctx );
} }
@ -5310,6 +5313,8 @@ nonpresent_callback(
if ( rs->sr_type == REP_RESULT ) { if ( rs->sr_type == REP_RESULT ) {
count = presentlist_free( si->si_presentlist ); count = presentlist_free( si->si_presentlist );
si->si_presentlist = NULL; si->si_presentlist = NULL;
Debug( LDAP_DEBUG_SYNC, "nonpresent_callback: %s "
"had %d items left in the list\n", si->si_ridtxt, count );
} else if ( rs->sr_type == REP_SEARCH ) { } else if ( rs->sr_type == REP_SEARCH ) {
if ( !( si->si_refreshDelete & NP_DELETE_ONE ) ) { if ( !( si->si_refreshDelete & NP_DELETE_ONE ) ) {
@ -5319,12 +5324,12 @@ nonpresent_callback(
present_uuid = presentlist_find( si->si_presentlist, &a->a_nvals[0] ); present_uuid = presentlist_find( si->si_presentlist, &a->a_nvals[0] );
} }
Debug(LDAP_DEBUG_SYNC, Debug(LDAP_DEBUG_SYNC, "nonpresent_callback: "
"nonpresent_callback: %s %spresent UUID %s, dn %s\n", "%s %spresent UUID %s, dn %s\n",
si->si_ridtxt, si->si_ridtxt,
present_uuid ? "" : "non", present_uuid ? "" : "non",
a ? a->a_vals[0].bv_val : "<missing>", a ? a->a_vals[0].bv_val : "<missing>",
rs->sr_entry->e_name.bv_val ); rs->sr_entry->e_name.bv_val );
if ( a == NULL ) return 0; if ( a == NULL ) return 0;
} }
@ -5335,6 +5340,9 @@ nonpresent_callback(
np_entry->npe_name = ber_dupbv( NULL, &rs->sr_entry->e_name ); np_entry->npe_name = ber_dupbv( NULL, &rs->sr_entry->e_name );
np_entry->npe_nname = ber_dupbv( NULL, &rs->sr_entry->e_nname ); np_entry->npe_nname = ber_dupbv( NULL, &rs->sr_entry->e_nname );
LDAP_LIST_INSERT_HEAD( &si->si_nonpresentlist, np_entry, npe_link ); LDAP_LIST_INSERT_HEAD( &si->si_nonpresentlist, np_entry, npe_link );
Debug( LDAP_DEBUG_SYNC, "nonpresent_callback: %s "
"adding entry %s to non-present list\n",
si->si_ridtxt, np_entry->npe_name->bv_val );
} else { } else {
presentlist_delete( &si->si_presentlist, &a->a_nvals[0] ); presentlist_delete( &si->si_presentlist, &a->a_nvals[0] );