Skip to content

Commit

Permalink
Issue 6347 - better fix for desyncronized vlv cache (389ds#6358)
Browse files Browse the repository at this point in the history 
A better fix than PR 6349 about corrupted vlv cache
Problem is a race condition because txn was released while building the cache.
Solution keep the write txn open until the cache is fully rebuilt.
Also fixed some debug logs
And also added the source of a tool useful to check the vlv cache consistency
Note: this remove PR 389ds#6349 and integrate PR 389ds#6356

Issue: 389ds#6347

Reviewed by @tbodaz (Thanks!)
  • Loading branch information
@progier389
progier389 authored Oct 10, 2024
1 parent 92eadd1 commit 8366819
Show file tree
Hide file tree
Showing 8 changed files with 458 additions and 77 deletions.
56 changes: 36 additions & 20 deletions ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -149,7 +149,7 @@ static inline void log_stack(int loglvl)
}
}

void dbi_str(MDB_cursor *cursor, int dbi, char *dbistr)
void dbi_str(MDB_cursor *cursor, int dbi, char dbistr[DBISTRMAXSIZE])
{
const char *str = "?";
dbmdb_dbi_t * dbi1;
Expand All @@ -161,7 +161,7 @@ void dbi_str(MDB_cursor *cursor, int dbi, char *dbistr)
if (dbi1 && dbi1->dbname) {
str = dbi1->dbname;
}
PR_snprintf(dbistr, DBGVAL2STRMAXSIZE, "dbi: %d <%s>", dbi, str);
PR_snprintf(dbistr, DBISTRMAXSIZE, "dbi: %d <%s>", dbi, str);
}

#ifdef DBMDB_DEBUG
Expand Down Expand Up @@ -297,7 +297,7 @@ dbg_mdb_cursor_open(const char *file, int lineno, const char *funcname, MDB_txn
{
int rc = mdb_cursor_open(txn, dbi, cursor);
if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];
dbi_str(NULL, dbi, dbistr);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_FORCE, "mdb_cursor_open(txn: %p, %s, cursor: %p)=%d", txn, dbistr, *cursor, rc);
}
Expand All @@ -318,7 +318,7 @@ void
dbg_mdb_cursor_close(const char *file, int lineno, const char *funcname, MDB_cursor *cursor)
{
if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, 0, cursor)) {
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];
dbi_str(cursor, 0, dbistr);
mdb_cursor_close(cursor);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_FORCE, "mdb_cursor_close(cursor: %p) %s", cursor, dbistr);
Expand All @@ -336,7 +336,7 @@ __dbg_mdb_cursor_get(const char *file, int lineno, const char *funcname, int log
char datastr[DBGVAL2STRMAXSIZE];
char flagsstr[DBGVAL2STRMAXSIZE];
char cursorstr[DBGVAL2STRMAXSIZE];
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];
int sl = 0;
if (dbg_should_log(loglvl, 0, cursor)) {
dbi_str(cursor, 0, dbistr);
Expand Down Expand Up @@ -376,7 +376,7 @@ if (data->mv_size <= 511) return 0;
char keystr[DBGVAL2STRMAXSIZE];
char datastr[DBGVAL2STRMAXSIZE];
char flagsstr[DBGVAL2STRMAXSIZE];
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];

dbi_str(NULL, dbi, dbistr);
dbgval2str(keystr, sizeof keystr, key);
Expand All @@ -394,7 +394,7 @@ dbg_mdb_get(const char *file, int lineno, const char *funcname, MDB_txn *txn, MD
{
char keystr[DBGVAL2STRMAXSIZE];
char datastr[DBGVAL2STRMAXSIZE];
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];

if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
dbi_str(NULL, dbi, dbistr);
Expand All @@ -419,7 +419,7 @@ dbg_mdb_del(const char *file, int lineno, const char *funcname, MDB_txn *txn, MD
if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
char keystr[DBGVAL2STRMAXSIZE];
char datastr[DBGVAL2STRMAXSIZE];
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];

dbi_str(NULL, dbi, dbistr);
dbgval2str(keystr, sizeof keystr, key);
Expand All @@ -438,7 +438,7 @@ dbg_mdb_cursor_put(const char *file, int lineno, const char *funcname, MDB_curso
char datastr[DBGVAL2STRMAXSIZE];
char flagsstr[DBGVAL2STRMAXSIZE];
char cursorstr[DBGVAL2STRMAXSIZE];
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];

dbi_str(cursor, 0, dbistr);
dbgval2str(keystr, sizeof keystr, key);
Expand Down Expand Up @@ -467,32 +467,46 @@ dbg_mdb_drop(const char *file, int lineno, const char *funcname, MDB_txn *txn, M
{
int rc = mdb_drop(txn, dbi, del);
if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
char dbistr[DBGVAL2STRMAXSIZE];
char dbistr[DBISTRMAXSIZE];
dbi_str(NULL, dbi, dbistr);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_FORCE, "mdb_drop(txn: %p, %s, del: %d)=%d", txn, dbistr, del, rc);
}
return rc;
}

int txn_loglvl()
{
if (dbgmdb_level & DBGMDB_LEVEL_MDBAPI) {
return DBGMDB_LEVEL_MDBAPI;
}
if (dbgmdb_level & DBGMDB_LEVEL_TXN) {
return DBGMDB_LEVEL_TXN;
}
return 0;
}

int dbg_txn_begin(const char *file, int lineno, const char *funcname, MDB_env *env, MDB_txn *parent_txn, int flags, MDB_txn **txn)
{
if (!(dbgmdb_level & DBGMDB_LEVEL_TXN)) {
int lvl = txn_loglvl();
if (lvl == 0) {
return mdb_txn_begin(env, parent_txn, flags, txn);
}
char strflags[100];
dbmdb_envflags2str(flags, strflags, sizeof strflags);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_BEGIN[%d]. txn_parent=%p, %s, stack is:", pthread_gettid(), parent_txn, strflags);
dbg_log(file, lineno, funcname, lvl, "TXN_BEGIN[%d]. txn_parent=%p, %s, stack is:", pthread_gettid(), parent_txn, strflags);
log_stack(DBGMDB_LEVEL_TXN);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "Waiting ...\n");
dbg_log(file, lineno, funcname, lvl, "Waiting ...\n");
int rc = mdb_txn_begin(env, parent_txn, flags, txn);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "Done. txn_begin(env=%p, txn_parent=%p, flags=0x%x, txn=0x%p) returned %d.",
dbg_log(file, lineno, funcname, lvl, "Done. txn_begin(env=%p, txn_parent=%p, flags=0x%x, txn=0x%p) returned %d.",
env, parent_txn, flags, *txn, rc);
return rc;
}

int dbg_txn_end(const char *file, int lineno, const char *funcname, MDB_txn *txn, int iscommit)
{
if (!(dbgmdb_level & DBGMDB_LEVEL_TXN)) {
int lvl = txn_loglvl();
char *stackis = (lvl == DBGMDB_LEVEL_TXN) ? " stack is:" : "";
if (lvl == 0) {
if (iscommit) {
return mdb_txn_commit(txn);
} else {
Expand All @@ -503,27 +517,29 @@ int dbg_txn_end(const char *file, int lineno, const char *funcname, MDB_txn *txn
int rc = 0;
if (iscommit) {
rc = mdb_txn_commit(txn);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_COMMIT[%d] (txn=0x%p) returned %d. stack is:", pthread_gettid(), txn, rc);
dbg_log(file, lineno, funcname, lvl, "TXN_COMMIT[%d] (txn=0x%p) returned %d.%s", pthread_gettid(), txn, rc, stackis);
} else {
mdb_txn_abort(txn);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_ABORT[%d] (txn=0x%p). stack is:", pthread_gettid(), txn);
dbg_log(file, lineno, funcname, lvl, "TXN_ABORT[%d] (txn=0x%p).%s", pthread_gettid(), txn, stackis);
}
if (lvl == DBGMDB_LEVEL_TXN) {
log_stack(DBGMDB_LEVEL_TXN);
}
return rc;
}


void dbg_txn_reset(const char *file, int lineno, const char *funcname, MDB_txn *txn)
{
mdb_txn_reset(txn);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_RESET[%d] (txn=0x%p). stack is:", pthread_gettid(), txn);
dbg_log(file, lineno, funcname, txn_loglvl(), "TXN_RESET[%d] (txn=0x%p). stack is:", pthread_gettid(), txn);
log_stack(DBGMDB_LEVEL_TXN);
}

int dbg_txn_renew(const char *file, int lineno, const char *funcname, MDB_txn *txn)
{
int rc = mdb_txn_renew(txn);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_RENEW[%d] (txn=0x%p) returned %d. stack is:", pthread_gettid(), txn, rc);
dbg_log(file, lineno, funcname, txn_loglvl(), "TXN_RENEW[%d] (txn=0x%p) returned %d. stack is:", pthread_gettid(), txn, rc);
log_stack(DBGMDB_LEVEL_TXN);
return rc;
}
Expand All @@ -533,7 +549,7 @@ void dbmdb_log_dbi_set_fn(const char *file, int lineno, const char *funcname, co
Dl_info info = {0};
dladdr(fn, &info);
/* Cannot use dbi_str here because slot is not yet up2date (so dbname is an argument) */
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI, "%s(txn=0x%p, dbi=%d <%s>, fn=0x%p <%s>)\n", action, txn, dbi, dbname, fn, info.dli_sname);
dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI, "%s(txn=0x%p, dbi=%d <%s>, fn=0x%p <%s>)\n", action, txn, dbi, dbname, fn, info.dli_sname);
}

int dbg_mdb_bulkop_cursor_get(const char *file, int lineno, const char *funcname, MDB_cursor *cursor, MDB_val *key, MDB_val *data, MDB_cursor_op op)
Expand Down
2 changes: 2 additions & 0 deletions ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,11 +20,13 @@ void dbmdb_format_dbslist_info(char *info, dbmdb_dbi_t *dbi);

#define DBGMDB_LEVEL_PRINTABLE 0xfff

#define DBISTRMAXSIZE 80

extern int dbgmdb_level; /* defined in mdb_debug.c */
void dbg_log(const char *file, int lineno, const char *funcname, int loglevel, char *fmt, ...);
void dbgval2str(char *buff, size_t bufsiz, MDB_val *val);
void dbmdb_dbg_set_dbi_slots(dbmdb_dbi_t *slots);
void dbi_str(MDB_cursor *cursor, int dbi, char dbistr[DBISTRMAXSIZE]);

/* #define DBMDB_DEBUG 1 */
#define DBGMDB_LEVEL_DEFAULT DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_TXN+DBGMDB_LEVEL_IMPORT+ \
Expand Down
1 change: 1 addition & 0 deletions ldap/servers/slapd/back-ldbm/db-mdb/mdb_import_threads.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3413,6 +3413,7 @@ dbmdb_add_import_index(ImportCtx_t *ctx, const char *name, IndexInfo *ii)
}
}

DBG_LOG(DBGMDB_LEVEL_OTHER,"Calling dbmdb_open_dbi_from_filename for %s flags = 0x%x", mii->name, dbi_flags);
dbmdb_open_dbi_from_filename(&mii->dbi, job->inst->inst_be, mii->name, mii->ai, dbi_flags);
avl_insert(&ctx->indexes, mii, cmp_mii, NULL);
}
Expand Down
15 changes: 15 additions & 0 deletions ldap/servers/slapd/back-ldbm/db-mdb/mdb_instance.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1245,6 +1245,8 @@ int dbmdb_open_dbi_from_filename(dbmdb_dbi_t **dbi, backend *be, const char *fil
dbi_open_ctx_t octx = {0};
dbi_txn_t *txn = NULL;
int rc = 0;
DBG_LOG(DBGMDB_LEVEL_OTHER, "dbmdb_open_dbi_from_filename: filename=%s flags=0x%x", filename, flags);


if (ctx->readonly || (flags&MDB_RDONLY)) {
flags &= ~MDB_CREATE;
Expand Down Expand Up @@ -1292,32 +1294,40 @@ int dbmdb_open_dbi_from_filename(dbmdb_dbi_t **dbi, backend *be, const char *fil
}
}
if (rc) {
DBG_LOG(DBGMDB_LEVEL_OTHER, "returning %d", rc);
return rc;
}
if (!*dbi) {
DBG_LOG(DBGMDB_LEVEL_OTHER, "returning MDB_NOTFOUND");
return MDB_NOTFOUND;
}
DBG_LOG(DBGMDB_LEVEL_OTHER, "So far rc = %d", rc);
if (ai && ai->ai_key_cmp_fn != (*dbi)->cmp_fn) {
if (! (*dbi)->cmp_fn) {
rc = dbmdb_update_dbi_cmp_fn(ctx, *dbi, ai->ai_key_cmp_fn, NULL);
}
(*dbi)->cmp_fn = ai->ai_key_cmp_fn;
}
DBG_LOG(DBGMDB_LEVEL_OTHER, "So far rc = %d", rc);

if (((*dbi)->state.state & DBIST_DIRTY) && !(flags & MDB_OPEN_DIRTY_DBI)) {
DBG_LOG(DBGMDB_LEVEL_OTHER, "returning MDB_NOTFOUND");
return MDB_NOTFOUND;
}
if (!rc && !((*dbi)->state.state & DBIST_DIRTY) && (flags & MDB_MARK_DIRTY_DBI)) {
dbistate_t st = (*dbi)->state;
st.state |= DBIST_DIRTY;
rc = dbmdb_update_dbi_state(ctx, *dbi, &st, NULL, PR_FALSE);
}
DBG_LOG(DBGMDB_LEVEL_OTHER, "So far rc = %d", rc);
if (!rc && (flags & MDB_TRUNCATE_DBI)) {
octx.ctx = ctx;
octx.dbi = *dbi;
octx.deletion_flags = 0;
DBG_LOG(DBGMDB_LEVEL_OTHER, "truncating db");
rc = dbi_remove(&octx);
}
DBG_LOG(DBGMDB_LEVEL_OTHER, "returning rc=%d", rc);
return rc;
}

Expand Down Expand Up @@ -1401,11 +1411,14 @@ int dbmdb_recno_cache_get_mode(dbmdb_recno_cache_ctx_t *rcctx)
rc = MDB_GET(txn, rcctx->rcdbi->dbi, &rcctx->key, &rcctx->data);
if (rc == MDB_SUCCESS) {
rcctx->mode = RCMODE_USE_CURSOR_TXN;
DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_USE_CURSOR_TXN rc=0", rcdbname);
return rc;
}
if (rc != MDB_NOTFOUND) {
/* There was an error or cache is valid.
* Im both cases there is no need to rebuilt the cache.
*/
DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_UNKNOWN rc=%d", rcdbname, rc);
return rc;
}
}
Expand All @@ -1415,7 +1428,9 @@ int dbmdb_recno_cache_get_mode(dbmdb_recno_cache_ctx_t *rcctx)
TXN_ABORT(txn);
txn = NULL;
rcctx->mode = RCMODE_USE_SUBTXN;
DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_USE_SUBTXN rc=0", rcdbname);
} else if (rc == EINVAL) {
DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_USE_NEW_THREAD rc=0", rcdbname);
rcctx->mode = RCMODE_USE_NEW_THREAD;
rc = 0;
}
Expand Down
Loading

0 comments on commit 8366819

Please sign in to comment.