From 28bd54a06d22e9ea8e45807317395fadd7f8d66c Mon Sep 17 00:00:00 2001 From: Howard Chu Date: Fri, 17 Nov 2006 02:11:57 +0000 Subject: [PATCH] ITS#4755 add rid to syncrepl debug msgs --- servers/slapd/syncrepl.c | 191 +++++++++++++++++++++------------------ 1 file changed, 104 insertions(+), 87 deletions(-) diff --git a/servers/slapd/syncrepl.c b/servers/slapd/syncrepl.c index 51b84f7ab0..4676ee46b0 100644 --- a/servers/slapd/syncrepl.c +++ b/servers/slapd/syncrepl.c @@ -495,8 +495,9 @@ do_syncrep1( rc = ldap_sync_search( si, op->o_tmpmemctx ); if( rc != LDAP_SUCCESS ) { - Debug( LDAP_DEBUG_ANY, "do_syncrep1: " - "ldap_search_ext: %s (%d)\n", ldap_err2string( rc ), rc, 0 ); + Debug( LDAP_DEBUG_ANY, "do_syncrep1: rid %03d " + "ldap_search_ext: %s (%d)\n", + si->si_rid, ldap_err2string( rc ), rc ); } done: @@ -560,7 +561,7 @@ do_syncrep2( ber_init2( ber, NULL, LBER_USE_DER ); ber_set_option( ber, LBER_OPT_BER_MEMCTX, &op->o_tmpmemctx ); - Debug( LDAP_DEBUG_TRACE, "=>do_syncrep2\n", 0, 0, 0 ); + Debug( LDAP_DEBUG_TRACE, "=>do_syncrep2 rid %03d\n", si->si_rid, 0, 0 ); psub = &si->si_be->be_nsuffix[0]; @@ -599,9 +600,9 @@ do_syncrep2( rctrlp = ldap_find_control( LDAP_CONTROL_SYNC_STATE, rctrls ); } if ( rctrlp == NULL ) { - Debug( LDAP_DEBUG_ANY, "do_syncrep2: " + Debug( LDAP_DEBUG_ANY, "do_syncrep2: rid %03d " "got search entry without " - "Sync State control\n", 0, 0, 0 ); + "Sync State control\n", si->si_rid, 0, 0 ); rc = -1; goto done; } @@ -610,8 +611,8 @@ do_syncrep2( /* FIXME: what if syncUUID is NULL or empty? * (happens with back-sql...) */ if ( BER_BVISEMPTY( &syncUUID ) ) { - Debug( LDAP_DEBUG_ANY, "do_syncrep2: " - "got empty syncUUID\n", 0, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "do_syncrep2: rid %03d " + "got empty syncUUID\n", si->si_rid, 0, 0 ); ldap_controls_free( rctrls ); rc = -1; goto done; @@ -653,12 +654,14 @@ do_syncrep2( case LDAP_RES_SEARCH_REFERENCE: Debug( LDAP_DEBUG_ANY, - "do_syncrep2: reference received error\n", 0, 0, 0 ); + "do_syncrep2: rid %03d reference received error\n", + si->si_rid, 0, 0 ); break; case LDAP_RES_SEARCH_RESULT: Debug( LDAP_DEBUG_SYNC, - "do_syncrep2: LDAP_RES_SEARCH_RESULT\n", 0, 0, 0 ); + "do_syncrep2: rid %03d LDAP_RES_SEARCH_RESULT\n", + si->si_rid, 0, 0 ); ldap_parse_result( si->si_ld, msg, &err, NULL, NULL, NULL, &rctrls, 0 ); #ifdef LDAP_X_SYNC_REFRESH_REQUIRED @@ -749,19 +752,20 @@ do_syncrep2( ber_tag_t tag; case LDAP_TAG_SYNC_NEW_COOKIE: Debug( LDAP_DEBUG_SYNC, - "do_syncrep2: %s - %s%s\n", + "do_syncrep2: rid %03d %s - %s%s\n", + si->si_rid, "LDAP_RES_INTERMEDIATE", - "NEW_COOKIE", "\n" ); + "NEW_COOKIE" ); ber_scanf( ber, "tm", &tag, &cookie ); break; case LDAP_TAG_SYNC_REFRESH_DELETE: case LDAP_TAG_SYNC_REFRESH_PRESENT: Debug( LDAP_DEBUG_SYNC, - "do_syncrep2: %s - %s%s\n", + "do_syncrep2: rid %03d %s - %s\n", + si->si_rid, "LDAP_RES_INTERMEDIATE", si_tag == LDAP_TAG_SYNC_REFRESH_PRESENT ? - "REFRESH_PRESENT" : "REFRESH_DELETE", - "\n" ); + "REFRESH_PRESENT" : "REFRESH_DELETE" ); if ( si_tag == LDAP_TAG_SYNC_REFRESH_DELETE ) { si->si_refreshDelete = 1; } else { @@ -789,10 +793,10 @@ do_syncrep2( break; case LDAP_TAG_SYNC_ID_SET: Debug( LDAP_DEBUG_SYNC, - "do_syncrep2: %s - %s%s\n", + "do_syncrep2: rid %03d %s - %s\n", + si->si_rid, "LDAP_RES_INTERMEDIATE", - "SYNC_ID_SET", - "\n" ); + "SYNC_ID_SET" ); ber_scanf( ber, "t{" /*"}"*/, &tag ); if ( ber_peek_tag( ber, &len ) == LDAP_TAG_SYNC_COOKIE ) @@ -834,8 +838,8 @@ do_syncrep2( break; default: Debug( LDAP_DEBUG_ANY, - "do_syncrep2 : unknown syncinfo tag (%ld)\n", - (long) si_tag, 0, 0 ); + "do_syncrep2: rid %03d unknown syncinfo tag (%ld)\n", + si->si_rid, (long) si_tag, 0 ); ldap_memfree( retoid ); ber_bvfree( retdata ); continue; @@ -869,9 +873,9 @@ do_syncrep2( break; } else { - Debug( LDAP_DEBUG_ANY, "do_syncrep2 : " + Debug( LDAP_DEBUG_ANY, "do_syncrep2: rid %03d " "unknown intermediate response (%d)\n", - rc, 0, 0 ); + si->si_rid, rc, 0 ); ldap_memfree( retoid ); ber_bvfree( retdata ); break; @@ -879,8 +883,8 @@ do_syncrep2( break; default: - Debug( LDAP_DEBUG_ANY, "do_syncrep2 : " - "unknown message\n", 0, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "do_syncrep2: rid %03d " + "unknown message\n", si->si_rid, 0, 0 ); break; } @@ -901,7 +905,7 @@ do_syncrep2( errstr = ldap_err2string( rc ); Debug( LDAP_DEBUG_ANY, - "do_syncrep2 : %s\n", errstr, 0, 0 ); + "do_syncrep2: rid %03d %s\n", si->si_rid, errstr, 0 ); } done: @@ -940,7 +944,7 @@ do_syncrepl( int i, defer = 1; Backend *be; - Debug( LDAP_DEBUG_TRACE, "=>do_syncrepl\n", 0, 0, 0 ); + Debug( LDAP_DEBUG_TRACE, "=>do_syncrepl rid %03d\n", si->si_rid, 0, 0 ); if ( si == NULL ) return NULL; @@ -1180,8 +1184,9 @@ syncrepl_message_to_op( int rc, deleteOldRdn = 0, freeReqDn = 0; if ( ldap_msgtype( msg ) != LDAP_RES_SEARCH_ENTRY ) { - Debug( LDAP_DEBUG_ANY, - "Message type should be entry (%d)", ldap_msgtype( msg ), 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_op: rid %03d " + "Message type should be entry (%d)", + si->si_rid, ldap_msgtype( msg ), 0 ); return -1; } @@ -1194,7 +1199,8 @@ syncrepl_message_to_op( if ( rc != LDAP_SUCCESS ) { Debug( LDAP_DEBUG_ANY, - "syncrepl_message_to_op : dn get failed (%d)", rc, 0, 0 ); + "syncrepl_message_to_op: rid %03d dn get failed (%d)", + si->si_rid, rc, 0 ); return rc; } @@ -1217,8 +1223,8 @@ syncrepl_message_to_op( int i = verb_to_mask( bvals[0].bv_val, modops ); if ( i < 0 ) { Debug( LDAP_DEBUG_ANY, - "syncrepl_message_to_op : unknown op %s", - bvals[0].bv_val, 0, 0 ); + "syncrepl_message_to_op: rid %03d unknown op %s", + si->si_rid, bvals[0].bv_val, 0 ); ch_free( bvals ); rc = -1; goto done; @@ -1262,8 +1268,9 @@ syncrepl_message_to_op( rc = slap_mods_check( modlist, &text, txtbuf, textlen, NULL ); if ( rc != LDAP_SUCCESS ) { - Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_op: mods check (%s)\n", - text, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_op: rid %03d " + "mods check (%s)\n", + si->si_rid, text, 0 ); goto done; } @@ -1274,21 +1281,22 @@ syncrepl_message_to_op( freeReqDn = 0; rc = slap_mods2entry( modlist, &op->ora_e, 1, 0, &text, txtbuf, textlen); if( rc != LDAP_SUCCESS ) { - Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_op: mods2entry (%s)\n", - text, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_op: rid %03d " + "mods2entry (%s)\n", + si->si_rid, text, 0 ); } else { rc = op->o_bd->be_add( op, &rs ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_message_to_op: be_add %s (%d)\n", - op->o_req_dn.bv_val, rc, 0 ); + "syncrepl_message_to_op: rid %03d be_add %s (%d)\n", + si->si_rid, op->o_req_dn.bv_val, rc ); } be_entry_release_w( op, op->ora_e ); } else { op->orm_modlist = modlist; rc = op->o_bd->be_modify( op, &rs ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_message_to_op: be_modify %s (%d)\n", - op->o_req_dn.bv_val, rc, 0 ); + "syncrepl_message_to_op: rid %03d be_modify %s (%d)\n", + si->si_rid, op->o_req_dn.bv_val, rc ); } break; case LDAP_REQ_MODRDN: @@ -1316,14 +1324,14 @@ syncrepl_message_to_op( rc = op->o_bd->be_modrdn( op, &rs ); slap_mods_free( op->orr_modlist, 1 ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_message_to_op: be_modrdn %s (%d)\n", - op->o_req_dn.bv_val, rc, 0 ); + "syncrepl_message_to_op: rid %03d be_modrdn %s (%d)\n", + si->si_rid, op->o_req_dn.bv_val, rc ); break; case LDAP_REQ_DELETE: rc = op->o_bd->be_delete( op, &rs ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_message_to_op: be_delete %s (%d)\n", - op->o_req_dn.bv_val, rc, 0 ); + "syncrepl_message_to_op: rid %03d be_delete %s (%d)\n", + si->si_rid, op->o_req_dn.bv_val, rc ); break; } done: @@ -1376,8 +1384,9 @@ syncrepl_message_to_entry( *modlist = NULL; if ( ldap_msgtype( msg ) != LDAP_RES_SEARCH_ENTRY ) { - Debug( LDAP_DEBUG_ANY, - "Message type should be entry (%d)", ldap_msgtype( msg ), 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: rid %03d " + "Message type should be entry (%d)", + si->si_rid, ldap_msgtype( msg ), 0 ); return -1; } @@ -1387,7 +1396,8 @@ syncrepl_message_to_entry( if ( rc != LDAP_SUCCESS ) { Debug( LDAP_DEBUG_ANY, - "syncrepl_message_to_entry : dn get failed (%d)", rc, 0, 0 ); + "syncrepl_message_to_entry: rid %03d dn get failed (%d)", + si->si_rid, rc, 0 ); return rc; } @@ -1433,8 +1443,8 @@ syncrepl_message_to_entry( } if ( *modlist == NULL ) { - Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: no attributes\n", - 0, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: rid %03d no attributes\n", + si->si_rid, 0, 0 ); rc = -1; goto done; } @@ -1442,8 +1452,8 @@ syncrepl_message_to_entry( rc = slap_mods_check( *modlist, &text, txtbuf, textlen, NULL ); if ( rc != LDAP_SUCCESS ) { - Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: mods check (%s)\n", - text, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: rid %03d mods check (%s)\n", + si->si_rid, text, 0 ); goto done; } @@ -1474,8 +1484,8 @@ syncrepl_message_to_entry( rc = slap_mods2entry( *modlist, &e, 1, 1, &text, txtbuf, textlen); if( rc != LDAP_SUCCESS ) { - Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: mods2entry (%s)\n", - text, 0, 0 ); + Debug( LDAP_DEBUG_ANY, "syncrepl_message_to_entry: rid %03d mods2entry (%s)\n", + si->si_rid, text, 0 ); } done: @@ -1556,28 +1566,28 @@ syncrepl_entry( switch( syncstate ) { case LDAP_SYNC_PRESENT: - Debug( LDAP_DEBUG_SYNC, "%s: %s\n", - "syncrepl_entry", + Debug( LDAP_DEBUG_SYNC, "syncrepl_entry: rid %03d %s\n", + si->si_rid, "LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_PRESENT)", 0 ); break; case LDAP_SYNC_ADD: - Debug( LDAP_DEBUG_SYNC, "%s: %s\n", - "syncrepl_entry", + Debug( LDAP_DEBUG_SYNC, "syncrepl_entry: rid %03d %s\n", + si->si_rid, "LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_ADD)", 0 ); break; case LDAP_SYNC_DELETE: - Debug( LDAP_DEBUG_SYNC, "%s: %s\n", - "syncrepl_entry", + Debug( LDAP_DEBUG_SYNC, "syncrepl_entry: rid %03d %s\n", + si->si_rid, "LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_DELETE)", 0 ); break; case LDAP_SYNC_MODIFY: - Debug( LDAP_DEBUG_SYNC, "%s: %s\n", - "syncrepl_entry", + Debug( LDAP_DEBUG_SYNC, "syncrepl_entry: rid %03d %s\n", + si->si_rid, "LDAP_RES_SEARCH_ENTRY(LDAP_SYNC_MODIFY)", 0 ); break; default: - Debug( LDAP_DEBUG_ANY, "%s: %s\n", - "syncrepl_entry", + Debug( LDAP_DEBUG_ANY, "syncrepl_entry: rid %03d %s\n", + si->si_rid, "LDAP_RES_SEARCH_ENTRY(UNKNOWN syncstate)", 0 ); } @@ -1604,8 +1614,8 @@ syncrepl_entry( (void)slap_uuidstr_from_normalized( &syncUUID_strrep, syncUUID, op->o_tmpmemctx ); if ( syncuuid_bv ) { - Debug( LDAP_DEBUG_SYNC, "syncrepl_entry: inserted UUID %s\n", - syncUUID_strrep.bv_val, 0, 0 ); + Debug( LDAP_DEBUG_SYNC, "syncrepl_entry: rid %03d inserted UUID %s\n", + si->si_rid, syncUUID_strrep.bv_val, 0 ); } op->ors_filter = &f; @@ -1642,8 +1652,8 @@ syncrepl_entry( if ( limits_check( op, &rs_search ) == 0 ) { rc = be->be_search( op, &rs_search ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s (%d)\n", - "be_search", rc, 0 ); + "syncrepl_entry: rid %03d be_search (%d)\n", + si->si_rid, rc, 0 ); } if ( !BER_BVISNULL( &op->ors_filterstr ) ) { @@ -1655,12 +1665,12 @@ syncrepl_entry( if ( entry && !BER_BVISNULL( &entry->e_name ) ) { Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s\n", - entry->e_name.bv_val, 0, 0 ); + "syncrepl_entry: rid %03d %s\n", + si->si_rid, entry->e_name.bv_val, 0 ); } else { Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s\n", - dni.dn.bv_val ? dni.dn.bv_val : "(null)", 0, 0 ); + "syncrepl_entry: rid %03d %s\n", + si->si_rid, dni.dn.bv_val ? dni.dn.bv_val : "(null)", 0 ); } if ( syncstate != LDAP_SYNC_DELETE ) { @@ -1724,8 +1734,8 @@ retry_add:; rc = be->be_add( op, &rs_add ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s (%d)\n", - "be_add", rc, 0 ); + "syncrepl_entry: rid %03d be_add (%d)\n", + si->si_rid, rc, 0 ); switch ( rs_add.sr_err ) { case LDAP_SUCCESS: be_entry_release_w( op, entry ); @@ -1784,8 +1794,8 @@ retry_add:; default: Debug( LDAP_DEBUG_ANY, - "syncrepl_entry : be_add failed (%d)\n", - rs_add.sr_err, 0, 0 ); + "syncrepl_entry: rid %03d be_add failed (%d)\n", + si->si_rid, rs_add.sr_err, 0 ); break; } goto done; @@ -1828,8 +1838,8 @@ retry_add:; slap_mods_free( op->orr_modlist, 1 ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s (%d)\n", - "be_modrdn", rc, 0 ); + "syncrepl_entry: rid %03d be_modrdn (%d)\n", + si->si_rid, rc, 0 ); if ( rs_modify.sr_err == LDAP_SUCCESS ) { op->o_req_dn = entry->e_name; op->o_req_ndn = entry->e_nname; @@ -1893,12 +1903,12 @@ retry_add:; rc = be->be_modify( op, &rs_modify ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s (%d)\n", - "be_modify", rc, 0 ); + "syncrepl_entry: rid %03d be_modify (%d)\n", + si->si_rid, rc, 0 ); if ( rs_modify.sr_err != LDAP_SUCCESS ) { Debug( LDAP_DEBUG_ANY, - "syncrepl_entry : be_modify failed (%d)\n", - rs_modify.sr_err, 0, 0 ); + "syncrepl_entry: rid %03d be_modify failed (%d)\n", + si->si_rid, rs_modify.sr_err, 0 ); } } goto done; @@ -1909,8 +1919,8 @@ retry_add:; op->o_tag = LDAP_REQ_DELETE; rc = be->be_delete( op, &rs_delete ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_entry: %s (%d)\n", - "be_delete", rc, 0 ); + "syncrepl_entry: rid %03d be_delete (%d)\n", + si->si_rid, rc, 0 ); while ( rs_delete.sr_err == LDAP_SUCCESS && op->o_delete_glue_parent ) { @@ -1932,7 +1942,7 @@ retry_add:; default : Debug( LDAP_DEBUG_ANY, - "syncrepl_entry : unknown syncstate\n", 0, 0, 0 ); + "syncrepl_entry: rid %03d unknown syncstate\n", si->si_rid, 0, 0 ); goto done; } @@ -2069,8 +2079,8 @@ syncrepl_del_nonpresent( op->o_req_ndn = *np_prev->npe_nname; rc = op->o_bd->be_delete( op, &rs_delete ); Debug( LDAP_DEBUG_SYNC, - "syncrepl_del_nonpresent: be_delete %s (%d)\n", - op->o_req_dn.bv_val, rc, 0 ); + "syncrepl_del_nonpresent: rid %03d be_delete %s (%d)\n", + si->si_rid, op->o_req_dn.bv_val, rc ); if ( rs_delete.sr_err == LDAP_NOT_ALLOWED_ON_NONLEAF ) { Modifications mod1, mod2; @@ -2322,7 +2332,8 @@ syncrepl_updateCookie( slap_dup_sync_cookie( &si->si_syncCookie, syncCookie ); } else { Debug( LDAP_DEBUG_ANY, - "be_modify failed (%d)\n", rs_modify.sr_err, 0, 0 ); + "syncrepl_updateCookie: rid %03d be_modify failed (%d)\n", + si->si_rid, rs_modify.sr_err, 0 ); } slap_graduate_commit_csn( op ); @@ -2449,14 +2460,20 @@ nonpresent_callback( } else if ( rs->sr_type == REP_SEARCH ) { if ( !(si->si_refreshDelete & NP_DELETE_ONE )) { + char buf[sizeof("000 not")]; + a = attr_find( rs->sr_entry->e_attrs, slap_schema.si_ad_entryUUID ); if ( a ) present_uuid = avl_find( si->si_presentlist, &a->a_nvals[0], syncuuid_cmp ); - Debug( LDAP_DEBUG_SYNC, "nonpresent_callback: UUID %s, dn %s, %sfound\n", - a ? a->a_vals[0].bv_val : "", rs->sr_entry->e_name.bv_val, present_uuid ? "" : "not " ); + if ( slap_debug & LDAP_DEBUG_SYNC ) + sprintf( buf, "%03d %s", si->si_rid, + present_uuid ? "got" : "not" ); + + Debug( LDAP_DEBUG_SYNC, "nonpresent_callback: rid %s UUID %s, dn %s\n", + buf, a ? a->a_vals[0].bv_val : "", rs->sr_entry->e_name.bv_val ); if ( a == NULL ) return 0; } -- 2.39.5