BerVarray syncUUIDs;
ber_len_t len;
ber_tag_t si_tag;
- Entry *entry;
+ Entry *entry = NULL;
struct berval bdn;
if ( slapd_shutdown ) {
op->o_tmpfree( syncUUID[0].bv_val, op->o_tmpmemctx );
if ( modlist )
slap_mods_free( modlist, 1);
+
+ if ( LogTest( LDAP_DEBUG_STATS ) ) {
+ struct timeval now;
+ gettimeofday( &now, NULL );
+ now.tv_sec -= si->si_lastcontact.tv_sec;
+ now.tv_usec -= si->si_lastcontact.tv_usec;
+ if ( now.tv_usec < 0 ) {
+ --now.tv_sec; now.tv_usec += 1000000;
+ }
+
+ Debug( LDAP_DEBUG_STATS, "%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,
+ rc ? "failed" : "processed" );
+ }
if ( rc )
goto done;
break;
slap_mods_free( modlist, 1);
}
if ( rc )
- goto done;
+ goto entry_done;
break;
}
/* we can't work without the control */
"Sync State control (%s)\n", si->si_ridtxt, bdn.bv_val );
ldap_controls_free( rctrls );
rc = -1;
- goto done;
+ goto entry_done;
}
}
if ( rctrlp == NULL ) {
rc = -1;
if ( rctrls )
ldap_controls_free( rctrls );
- goto done;
+ goto entry_done;
}
ber_init2( ber, &rctrlp->ldctl_value, LBER_USE_DER );
if ( ber_scanf( ber, "{em" /*"}"*/, &syncstate, &syncUUID[0] )
si->si_ridtxt, bdn.bv_val );
ldap_controls_free( rctrls );
rc = -1;
- goto done;
+ goto entry_done;
}
/* FIXME: what if syncUUID is NULL or empty?
* (happens with back-sql...) */
syncrepl_state2str( syncstate ), bdn.bv_val );
ldap_controls_free( rctrls );
rc = -1;
- goto done;
+ goto entry_done;
}
if ( ber_peek_tag( ber, &len ) == LDAP_TAG_SYNC_COOKIE ) {
if ( ber_scanf( ber, /*"{"*/ "m}", &cookie ) != LBER_ERROR ) {
si->si_too_old = 1;
ldap_controls_free( rctrls );
rc = 0;
- goto done;
+ /* Should we loop instead? */
+ goto entry_done;
}
si->si_too_old = 0;
/* check pending CSNs too */
if (( rc = get_pmutex( si ))) {
ldap_controls_free( rctrls );
- goto done;
+ goto entry_done;
}
i = check_csn_age( si, &bdn, syncCookie.ctxcsn, sid, (cookie_vals *)&si->si_cookieState->cs_pvals, &slot );
ldap_pvt_thread_mutex_unlock( &si->si_cookieState->cs_pmutex );
ldap_controls_free( rctrls );
rc = 0;
- goto done;
+ /* Should we loop instead? */
+ goto entry_done;
} else {
/* new SID, add it */
slap_insert_csn_sids(
si->si_ridtxt, bdn.bv_val );
ldap_controls_free( rctrls );
rc = 0;
- goto done;
+ /* Should we loop instead? */
+ goto entry_done;
}
op->o_controls[slap_cids.sc_LDAPsync] = &syncCookie;
}
ldap_controls_free( rctrls );
slap_mods_free( modlist, 1 );
entry_free( entry );
- goto done;
+ goto entry_done;
}
}
if ( ( rc = syncrepl_entry( si, op, entry, &modlist,
if ( modlist ) {
slap_mods_free( modlist, 1 );
}
- if ( LogTest( LDAP_DEBUG_SYNC ) ) {
+entry_done:
+ if ( LogTest( LDAP_DEBUG_STATS ) ) {
struct timeval now;
gettimeofday( &now, NULL );
now.tv_sec -= si->si_lastcontact.tv_sec;
if ( now.tv_usec < 0 ) {
--now.tv_sec; now.tv_usec += 1000000;
}
- Debug( LDAP_DEBUG_SYNC, "do_syncrep2: %s etime=%d.%06d\n",
- si->si_ridtxt, (int)now.tv_sec, (int)now.tv_usec );
+
+ Debug( LDAP_DEBUG_STATS, "%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,
+ (int)now.tv_sec, (int)now.tv_usec,
+ rc ? "failed" : "processed" );
}
if ( rc )
goto done;
Debug( LDAP_DEBUG_ANY,
"do_syncrep2: %s reference received error\n",
si->si_ridtxt );
+ if ( LogTest( LDAP_DEBUG_STATS ) ) {
+ struct timeval now;
+ gettimeofday( &now, NULL );
+ now.tv_sec -= si->si_lastcontact.tv_sec;
+ now.tv_usec -= si->si_lastcontact.tv_usec;
+ if ( now.tv_usec < 0 ) {
+ --now.tv_sec; now.tv_usec += 1000000;
+ }
+
+ Debug( LDAP_DEBUG_STATS, "%s SYNC REFERENCE "
+ "etime=%d.%06d result=failed\n",
+ si->si_ridtxt, (int)now.tv_sec, (int)now.tv_usec );
+ }
break;
case LDAP_RES_SEARCH_RESULT:
}
}
rc = err;
- goto done;
+ goto result_done;
}
if ( err ) {
Debug( LDAP_DEBUG_ANY,
rc = SYNC_REPOLL;
}
}
- goto done;
+ goto result_done;
}
if ( rctrls ) {
LDAPControl **next = NULL;
rc = syncrepl_dirsync_cookie( si, op, rctrls );
if ( rc == LDAP_SUCCESS )
rc = SYNC_REPOLL; /* schedule a re-poll */
- goto done;
+ goto result_done;
}
#endif
/* NOTE: make sure we use the right one;
"Sync State control\n", si->si_ridtxt );
ldap_controls_free( rctrls );
rc = SYNC_ERROR;
- goto done;
+ goto result_done;
}
}
if ( rctrlp ) {
else
rc = SYNC_REPOLL;
}
+result_done:
+ if ( LogTest( LDAP_DEBUG_STATS ) ) {
+ struct timeval now;
+ gettimeofday( &now, NULL );
+ now.tv_sec -= si->si_lastcontact.tv_sec;
+ now.tv_usec -= si->si_lastcontact.tv_usec;
+ if ( now.tv_usec < 0 ) {
+ --now.tv_sec; now.tv_usec += 1000000;
+ }
+ /* 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 "
+ "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,
+ (int)now.tv_sec, (int)now.tv_usec,
+ ( si->si_refreshDone || rc == SYNC_REPOLL ) ?
+ "processed" : "failed" );
+ }
goto done;
case LDAP_RES_INTERMEDIATE:
rc = ldap_parse_intermediate( si->si_ld, msg,
&retoid, &retdata, NULL, 0 );
if ( !rc && !strcmp( retoid, LDAP_SYNC_INFO ) ) {
+ const char *name;
ber_init2( ber, retdata, LBER_USE_DER );
switch ( si_tag = ber_peek_tag( ber, &len ) ) {
ber_tag_t tag;
case LDAP_TAG_SYNC_NEW_COOKIE:
+ name = "NEW_COOKIE";
Debug( LDAP_DEBUG_SYNC,
"do_syncrep2: %s %s - %s\n",
si->si_ridtxt,
break;
case LDAP_TAG_SYNC_REFRESH_DELETE:
case LDAP_TAG_SYNC_REFRESH_PRESENT:
+ name = (si_tag == LDAP_TAG_SYNC_REFRESH_PRESENT) ?
+ "REFRESH_PRESENT" : "REFRESH_DELETE";
Debug( LDAP_DEBUG_SYNC,
"do_syncrep2: %s %s - %s\n",
si->si_ridtxt,
- "LDAP_RES_INTERMEDIATE",
- si_tag == LDAP_TAG_SYNC_REFRESH_PRESENT ?
- "REFRESH_PRESENT" : "REFRESH_DELETE" );
+ "LDAP_RES_INTERMEDIATE", name );
if ( si->si_refreshDone ) {
Debug( LDAP_DEBUG_ANY, "do_syncrep2: %s "
"server sent multiple refreshDone "
"messages? Ending session\n",
si->si_ridtxt );
rc = LDAP_PROTOCOL_ERROR;
+
+ if ( LogTest( LDAP_DEBUG_STATS ) ) {
+ struct timeval now;
+ gettimeofday( &now, NULL );
+ now.tv_sec -= si->si_lastcontact.tv_sec;
+ now.tv_usec -= si->si_lastcontact.tv_usec;
+ if ( now.tv_usec < 0 ) {
+ --now.tv_sec; now.tv_usec += 1000000;
+ }
+ Debug( LDAP_DEBUG_STATS, "%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,
+ (int)now.tv_sec, (int)now.tv_usec );
+ }
+
goto done;
}
if ( si_tag == LDAP_TAG_SYNC_REFRESH_DELETE ) {
}
break;
case LDAP_TAG_SYNC_ID_SET:
+ name = "ID_SET";
Debug( LDAP_DEBUG_SYNC,
"do_syncrep2: %s %s - %s\n",
si->si_ridtxt,
si->si_ridtxt, (long) si_tag );
ldap_memfree( retoid );
ber_bvfree( retdata );
+ ldap_msgfree( msg );
+ msg = NULL;
continue;
}
ldap_memfree( retoid );
ber_bvfree( retdata );
+ if ( LogTest( LDAP_DEBUG_STATS ) ) {
+ struct timeval now;
+ const char *cookiestr = "";
+
+ gettimeofday( &now, NULL );
+ now.tv_sec -= si->si_lastcontact.tv_sec;
+ now.tv_usec -= si->si_lastcontact.tv_usec;
+ if ( now.tv_usec < 0 ) {
+ --now.tv_sec; now.tv_usec += 1000000;
+ }
+
+ if ( !BER_BVISNULL( &cookie ) ) {
+ cookiestr = syncCookie.octet_str.bv_val;
+ }
+
+ switch ( si_tag ) {
+ case LDAP_TAG_SYNC_NEW_COOKIE:
+ Debug( LDAP_DEBUG_STATS, "%s SYNC %s "
+ "cookie=%s etime=%d.%06d result=%s\n",
+ si->si_ridtxt, name, cookiestr,
+ (int)now.tv_sec, (int)now.tv_usec,
+ rc ? "failed" : "processed" );
+ break;
+ case LDAP_TAG_SYNC_REFRESH_DELETE:
+ case LDAP_TAG_SYNC_REFRESH_PRESENT:
+ Debug( LDAP_DEBUG_STATS, "%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 "
+ "cookie=%s etime=%d.%06d result=%s\n",
+ si->si_ridtxt, name, refreshDeletes != 0,
+ cookiestr, (int)now.tv_sec, (int)now.tv_usec,
+ rc ? "failed" : "processed" );
+ break;
+ default:
+ break;
+ }
+ }
+
if ( rc )
goto done;
projects / thirdparty / openldap.git / commitdiff
