From 83668192bddcb6daa272eb418a96c10931d3386b Mon Sep 17 00:00:00 2001 From: progier389 Date: Thu, 10 Oct 2024 11:29:00 +0200 Subject: [PATCH] Issue 6347 - better fix for desyncronized vlv cache (#6358) 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 #6349 and integrate PR #6356 Issue: #6347 Reviewed by @tbodaz (Thanks!) --- .../slapd/back-ldbm/db-mdb/mdb_debug.c | 56 ++- .../slapd/back-ldbm/db-mdb/mdb_debug.h | 2 + .../back-ldbm/db-mdb/mdb_import_threads.c | 1 + .../slapd/back-ldbm/db-mdb/mdb_instance.c | 15 + .../slapd/back-ldbm/db-mdb/mdb_layer.c | 94 ++--- .../slapd/back-ldbm/db-mdb/mdb_ldif2db.c | 2 +- ldap/servers/slapd/back-ldbm/idl_new.c | 2 - ldap/servers/slapd/tools/chkvlv.c | 363 ++++++++++++++++++ 8 files changed, 458 insertions(+), 77 deletions(-) create mode 100644 ldap/servers/slapd/tools/chkvlv.c diff --git a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c index 3ccff4c2cf..33e71f1a8a 100644 --- a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c +++ b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c @@ -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; @@ -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 @@ -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); } @@ -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); @@ -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); @@ -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); @@ -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); @@ -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); @@ -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); @@ -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 { @@ -503,12 +517,14 @@ 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; } @@ -516,14 +532,14 @@ int dbg_txn_end(const char *file, int lineno, const char *funcname, MDB_txn *txn 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; } @@ -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) diff --git a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h index e25d775099..3bd709a4c6 100644 --- a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h +++ b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h @@ -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+ \ diff --git a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_import_threads.c b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_import_threads.c index f03e6741b1..9504c24343 100644 --- a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_import_threads.c +++ b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_import_threads.c @@ -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); } diff --git a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_instance.c b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_instance.c index 66e6e0e8de..50db548d95 100644 --- a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_instance.c +++ b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_instance.c @@ -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; @@ -1292,19 +1294,24 @@ 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)) { @@ -1312,12 +1319,15 @@ int dbmdb_open_dbi_from_filename(dbmdb_dbi_t **dbi, backend *be, const char *fil 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; } @@ -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; } } @@ -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; } diff --git a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_layer.c b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_layer.c index 313eb35aec..e4bf27b96c 100644 --- a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_layer.c +++ b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_layer.c @@ -2108,6 +2108,7 @@ void *dbmdb_recno_cache_build(void *arg) int len = 0; int rc = 0; + DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_build(%s)", rcctx->rcdbname); /* Open/creat cache dbi */ rc = dbmdb_open_dbi_from_filename(&rcctx->rcdbi, rcctx->cursor->be, rcctx->rcdbname, NULL, MDB_CREATE); slapi_ch_free_string(&rcctx->rcdbname); @@ -2131,63 +2132,46 @@ void *dbmdb_recno_cache_build(void *arg) txn_ctx.flags |= DBMDB_TXNCTX_NEED_COMMIT; } } + if (rc == 0) { + rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_FIRST); + recno = 1; + } while (rc == 0) { slapi_log_err(SLAPI_LOG_DEBUG, "dbmdb_recno_cache_build", "recno=%d\n", recno); - if (recno % RECNO_CACHE_INTERVAL != 1) { - recno++; - rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_NEXT); - continue; - } - /* close the txn from time to time to avoid locking all dbi page */ - rc = dbmdb_end_recno_cache_txn(&txn_ctx, 0); - rc |= dbmdb_begin_recno_cache_txn(rcctx, &txn_ctx, rcctx->dbi->dbi); - if (rc) { - break; - } - /* Reset to new cursor to the old position */ - if (recno == 1) { - rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_FIRST); - } else { - rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_SET); - if (rc == MDB_NOTFOUND) { - rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_SET_RANGE); - } - } - if (rc) { - break; - } - /* Prepare the cache data */ - len = sizeof(*rce) + data.mv_size + key.mv_size; - rce = (dbmdb_recno_cache_elmt_t*)slapi_ch_malloc(len); - rce->len = len; - rce->recno = recno; - rce->key.mv_size = key.mv_size; - rce->key.mv_data = &rce[1]; - rce->data.mv_size = data.mv_size; - rce->data.mv_data = ((char*)&rce[1])+rce->key.mv_size; - memcpy(rce->key.mv_data, key.mv_data, key.mv_size); - memcpy(rce->data.mv_data, data.mv_data, data.mv_size); - rcdata.mv_data = rce; - rcdata.mv_size = len; - dbmdb_generate_recno_cache_key_by_recno(&rckey, recno); - rc = MDB_PUT(txn_ctx.txn, rcctx->rcdbi->dbi, &rckey, &rcdata, 0); - slapi_ch_free(&rckey.mv_data); - if (rc) { - slapi_log_err(SLAPI_LOG_ERR, "dbmdb_recno_cache_build", - "Failed to write record in db %s, key=%s error: %s\n", - rcctx->rcdbi->dbname, (char*)(key.mv_data), mdb_strerror(rc)); - } else { - dbmdb_generate_recno_cache_key_by_data(&rckey, &key, &data); + if (recno % RECNO_CACHE_INTERVAL == 1) { + /* Prepare the cache data */ + len = sizeof(*rce) + data.mv_size + key.mv_size; + rce = (dbmdb_recno_cache_elmt_t*)slapi_ch_malloc(len); + rce->len = len; + rce->recno = recno; + rce->key.mv_size = key.mv_size; + rce->key.mv_data = &rce[1]; + rce->data.mv_size = data.mv_size; + rce->data.mv_data = ((char*)&rce[1])+rce->key.mv_size; + memcpy(rce->key.mv_data, key.mv_data, key.mv_size); + memcpy(rce->data.mv_data, data.mv_data, data.mv_size); + rcdata.mv_data = rce; + rcdata.mv_size = len; + dbmdb_generate_recno_cache_key_by_recno(&rckey, recno); rc = MDB_PUT(txn_ctx.txn, rcctx->rcdbi->dbi, &rckey, &rcdata, 0); slapi_ch_free(&rckey.mv_data); - txn_ctx.flags |= DBMDB_TXNCTX_NEED_COMMIT; if (rc) { slapi_log_err(SLAPI_LOG_ERR, "dbmdb_recno_cache_build", "Failed to write record in db %s, key=%s error: %s\n", rcctx->rcdbi->dbname, (char*)(key.mv_data), mdb_strerror(rc)); + } else { + dbmdb_generate_recno_cache_key_by_data(&rckey, &key, &data); + rc = MDB_PUT(txn_ctx.txn, rcctx->rcdbi->dbi, &rckey, &rcdata, 0); + slapi_ch_free(&rckey.mv_data); + txn_ctx.flags |= DBMDB_TXNCTX_NEED_COMMIT; + if (rc) { + slapi_log_err(SLAPI_LOG_ERR, "dbmdb_recno_cache_build", + "Failed to write record in db %s, key=%s error: %s\n", + rcctx->rcdbi->dbname, (char*)(key.mv_data), mdb_strerror(rc)); + } } + slapi_ch_free(&rcdata.mv_data); } - slapi_ch_free(&rcdata.mv_data); rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_NEXT); recno++; } @@ -2378,26 +2362,27 @@ int dbmdb_cursor_set_recno(dbi_cursor_t *cursor, MDB_val *dbmdb_key, MDB_val *db } memcpy(&recno, dbmdb_key->mv_data, sizeof (dbi_recno_t)); +#ifdef DBMDB_DEBUG + char dbistr[DBISTRMAXSIZE]; + dbi_str(cursor->cur, 0, dbistr); + DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_cursor_set_recno: recno=%d dbi=%s", recno, dbistr); +#endif dbmdb_generate_recno_cache_key_by_recno(&cache_key, recno); rc = dbmdb_recno_cache_lookup(cursor, &cache_key, &rce); if (rc ==0) { rc = MDB_CURSOR_GET(cursor->cur, &rce->key, &rce->data, MDB_SET_RANGE); } while (rc == 0 && recno > rce->recno) { - DBG_LOG(DBGMDB_LEVEL_VLV, "Current record index is %d Target is %d\n", rce->recno, recno); + DBG_LOG(DBGMDB_LEVEL_VLV, "Current record index is %d Target is %d", rce->recno, recno); rce->recno++; rc = MDB_CURSOR_GET(cursor->cur, &rce->key, &rce->data, MDB_NEXT); } - if (rc == MDB_NOTFOUND) { - /* Stay on last record if there are no more records */ - rc = 0; - } if (rc == 0 && dbmdb_data->mv_size == rce->data.mv_size) { /* Should always be the case */ - DBG_LOG(DBGMDB_LEVEL_VLV, "SUCCESS\n"); + DBG_LOG(DBGMDB_LEVEL_VLV, "SUCCESS"); memcpy(dbmdb_data->mv_data , rce->data.mv_data, dbmdb_data->mv_size); } else { - DBG_LOG(DBGMDB_LEVEL_VLV, "FAILURE: rc=%d dbmdb_data->mv_size=%d rce->data.mv_size=%d\n", rc, dbmdb_data->mv_size, rce->data.mv_size); + DBG_LOG(DBGMDB_LEVEL_VLV, "FAILURE: rc=%d dbmdb_data->mv_size=%d rce->data.mv_size=%d", rc, dbmdb_data->mv_size, rce->data.mv_size); } slapi_ch_free((void**)&rce); @@ -2878,6 +2863,7 @@ dbmdb_public_clear_vlv_cache(Slapi_Backend *be, dbi_txn_t *txn, dbi_db_t *db) MDB_val ok = { 0 }; int rc = 0; + DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_public_clear_vlv_cache(%s)", rcdbname); ok.mv_data = "OK"; ok.mv_size = 2; rc = dbmdb_open_dbi_from_filename(&rcdbi, be, rcdbname, NULL, 0); diff --git a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_ldif2db.c b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_ldif2db.c index 548ad2910d..477a48ec95 100644 --- a/ldap/servers/slapd/back-ldbm/db-mdb/mdb_ldif2db.c +++ b/ldap/servers/slapd/back-ldbm/db-mdb/mdb_ldif2db.c @@ -1423,7 +1423,7 @@ _get_and_add_parent_rdns(backend *be, key.mv_data = &storedid; memset(&data, 0, sizeof(data)); - rc = mdb_get(TXN(cur->txn), cur->dbi->dbi, &key, &data); + rc = MDB_GET(TXN(cur->txn), cur->dbi->dbi, &key, &data); if (rc) { slapi_log_err(SLAPI_LOG_ERR, "_get_and_add_parent_rdns", "Failed to position cursor at ID " ID_FMT "\n", id); diff --git a/ldap/servers/slapd/back-ldbm/idl_new.c b/ldap/servers/slapd/back-ldbm/idl_new.c index 9c455f5df3..a1c1395bc2 100644 --- a/ldap/servers/slapd/back-ldbm/idl_new.c +++ b/ldap/servers/slapd/back-ldbm/idl_new.c @@ -939,7 +939,6 @@ idl_lmdb_range_fetch( /* Close the cursor */ if (0 == idl_range_ctx.flag_err) { idl_range_ctx.flag_err = ret; -slapi_log_err(SLAPI_LOG_INFO, "idl_lmdb_range_fetch", "flag_err=%d\n", idl_range_ctx.flag_err); } ret = dblayer_cursor_op(&cursor, DBI_OP_CLOSE, NULL, NULL); if (ret) { @@ -955,7 +954,6 @@ slapi_log_err(SLAPI_LOG_INFO, "idl_lmdb_range_fetch", "flag_err=%d\n", idl_range } if (0 == idl_range_ctx.flag_err) { idl_range_ctx.flag_err = ret; -slapi_log_err(SLAPI_LOG_INFO, "idl_lmdb_range_fetch", "flag_err=%d\n", idl_range_ctx.flag_err); } /* sort idl */ diff --git a/ldap/servers/slapd/tools/chkvlv.c b/ldap/servers/slapd/tools/chkvlv.c new file mode 100644 index 0000000000..2438021504 --- /dev/null +++ b/ldap/servers/slapd/tools/chkvlv.c @@ -0,0 +1,363 @@ +/** BEGIN COPYRIGHT BLOCK + * Copyright (C) 2024 Red Hat, Inc. + * All rights reserved. + * + * License: GPL (version 3 or any later version). + * See LICENSE for details. + * END COPYRIGHT BLOCK **/ + + +/* Build with: gcc -o chkvlv chkvlv.c -llmdb */ +/* Usage: chkvlv dbdir */ + +#include +#include +#include +#include +#include +#include +#include +#include +#include + + +#define T(expr) rc = expr; if (rc) { printf("%s[%d]: %s returned %s (%d)\n", __FILE__, __LINE__, #expr, mdb_strerror(rc), rc); exit(1); } + +#define RECNO_CACHE_PREFIX "/~recno-cache" +#define VLV_PREFIX "/vlv#" + + +typedef struct { + char *name; + MDB_dbi dbi; + int is_vlv; + int recno_idx; +} dbi_t; + +typedef struct { + MDB_val data; + MDB_val key; + int len; + uint32_t recno; + /* followed by key value then data value */ +} recno_elmt_t; + +typedef struct { + MDB_cursor *cur; + MDB_txn *txn; + MDB_val key; + MDB_val data; + int count; +} iterator_t; + + +int nbdbis; +dbi_t *dbis; +MDB_env *env = NULL; +MDB_dbi dbi = 0; + + +/* Iterate calling 'cb' callback on each database instance records */ +int +iterate(MDB_txn *txn, MDB_dbi dbi, int (*cb)(iterator_t *, void*), void *ctx) +{ + int rc = 0; + iterator_t it = {0}; + it.txn = txn; + T(mdb_cursor_open(txn, dbi, &it.cur)); + rc = mdb_cursor_get(it.cur, &it.key, &it.data, MDB_FIRST); + while (rc==0) { + rc = cb(&it, ctx); + if (rc == 0) { + it.count++; + rc = mdb_cursor_get(it.cur, &it.key, &it.data, MDB_NEXT); + } + } + mdb_cursor_close(it.cur); + if (rc == MDB_NOTFOUND) { + rc = 0; + } + return rc; +} + +void +open_db(const char *dbdir) +{ + int rc = 0; + char buf[200]; + char buf2[200]; + + FILE *fd = NULL; + size_t maxsize = 0; + MDB_dbi maxdbs = 0; + unsigned int maxreaders = 0; + char *pt = NULL; + + T(mdb_env_create(&env)); + sprintf(buf,"%s/INFO.mdb",dbdir); + fd = fopen(buf, "r"); + if (fd==NULL) { + perror(buf); + printf("The ' parameter is probably invalid.\n"); + exit(1); + } + while (pt=fgets(buf2, (sizeof buf2), fd)) { + sscanf(buf2, "MAXSIZE=%ld", &maxsize); + sscanf(buf2, "MAXREADERS=%ud", &maxreaders); + sscanf(buf2, "MAXDBS=%ud", &maxdbs); + } + fclose(fd); + + sprintf(buf,"%s/data.mdb",dbdir); + T(mdb_env_set_maxdbs(env, maxdbs)); + T(mdb_env_set_mapsize(env, maxsize)); + T(mdb_env_set_maxreaders(env, maxreaders)); + T(mdb_env_open(env, dbdir, MDB_RDONLY , 0700)); +} + +char * +dup_val(const MDB_val *val) +{ + char *str = malloc(val->mv_size+1); + if (str==NULL) { + fprintf(stderr, "Cannot alloc %ld bytes.\n", val->mv_size+1); + exit(1); + } + memcpy(str, val->mv_data, val->mv_size); + str[val->mv_size] = 0; + return str; +} + + +int +dup_recno_elmt(const MDB_val *val, recno_elmt_t *elmt) +{ + if (val->mv_size < sizeof *elmt) { + printf("Unexpected record size %ld (Should be >= %ld)\n", + val->mv_size, sizeof *elmt); + return -1; + } + memcpy(elmt, val->mv_data, sizeof *elmt); + size_t expected_size = (sizeof *elmt) + elmt->key.mv_size + elmt->data.mv_size; + if (val->mv_size != expected_size) { + printf("Unexpected record size %ld (Should be %ld)\n", + val->mv_size, expected_size); + elmt->key.mv_data = elmt->data.mv_data = NULL; + return -1; + } + char *pt = val->mv_data; + elmt->key.mv_data = pt+sizeof *elmt; + elmt->data.mv_data = pt+(sizeof *elmt)+elmt->key.mv_size; + elmt->key.mv_data = dup_val(&elmt->key); + elmt->data.mv_data = dup_val(&elmt->data); + return 0; +} + +void +free_recno_elmt(recno_elmt_t *elmt) +{ + if (elmt->key.mv_data) { + free(elmt->key.mv_data); + elmt->key.mv_data = NULL; + } + if (elmt->data.mv_data) { + free(elmt->data.mv_data); + elmt->data.mv_data = NULL; + } +} + +int +count_cb(iterator_t *it, void *ctx) +{ + *(int*)ctx = it->count; + return 0; +} + +int +store_dbi(iterator_t *it, void *ctx) +{ + int rc = 0; + if (it->count > nbdbis) { + return MDB_NOTFOUND; + } + char *name = dup_val(&it->key); + T(mdb_dbi_open(it->txn, name , 0, &dbis[it->count].dbi)); + dbis[it->count].name = name; + dbis[it->count].is_vlv = strstr(name, VLV_PREFIX) && !strstr(name, RECNO_CACHE_PREFIX); + return 0; +} + +void open_dbis() +{ + int rc = 0; + MDB_dbi dbi = 0; + MDB_txn *txn = 0; + + T(mdb_txn_begin(env, NULL, MDB_RDONLY, &txn)); + T(mdb_dbi_open(txn, "__DBNAMES", 0, &dbi)); + T(mdb_txn_commit(txn)); + T(mdb_txn_begin(env, NULL, MDB_RDONLY, &txn)); + T(iterate(txn, dbi, count_cb, &nbdbis)); + dbis = calloc(nbdbis, sizeof (dbi_t)); + if (!dbis) { + fprintf(stderr, "Cannot alloc %ld bytes.\n", nbdbis*sizeof (dbi_t)); + exit(1); + } + T(iterate(txn, dbi, store_dbi, NULL)); + T(mdb_txn_commit(txn)); + + for (size_t count = 0; count < nbdbis; count++) { + if (dbis[count].is_vlv) { + char buf2[200]; + char *pt = dbis[count].name; + char *pt2 = buf2; + while (*pt!='/') { + *pt2++ = *pt++; + } + strcpy(pt2,RECNO_CACHE_PREFIX); + pt2 += strlen(pt2); + strcpy(pt2,pt); + + for (size_t i = 0; i < nbdbis; i++) { + if (strcmp(dbis[i].name, buf2)==0) { + dbis[count].recno_idx = i; + } + } + } + } +} + +void +dump_val(const MDB_val *val) +{ + unsigned char *pt = val->mv_data; + for (size_t i = val->mv_size; i >0; i--) { + if ( *pt >= 0x32 && *pt < 0x7f && *pt != '\\') { + putchar(*pt); + } else { + printf("\\%02x", *pt); + } + pt++; + } +} + +int +cmp_val(const MDB_val *val1, const MDB_val *val2) +{ + size_t len = val1->mv_size > val2->mv_size ? val2->mv_size : val1->mv_size; + int rc = memcmp(val1->mv_data, val2->mv_data, len); + if (rc!=0) return rc; + return val1->mv_size - val2->mv_size; +} + +typedef struct { + dbi_t *vlvdbi; + recno_elmt_t *elmt; + iterator_t *it; + int found; +} check_recno_ctx_t; + +int +check_recno_ctx(iterator_t *it, void *ctx) +{ + check_recno_ctx_t *rctx = ctx; + if (cmp_val(&it->key, &rctx->elmt->key) == 0) { + rctx->found = 1; + if (it->count+1 != rctx->elmt->recno) { + printf("Problem (invalid recno value) detected in vlv cache record #%d\n", it->count); + printf("Found %d instead of %d\n", rctx->elmt->recno, it->count+1); + } + } + return 0; +} + +void +check_recno_record(iterator_t *it, dbi_t *vlvdbi, recno_elmt_t *elmt) +{ + int rc = 0; + check_recno_ctx_t ctx = {0}; + ctx.vlvdbi = vlvdbi; + ctx.elmt = elmt; + ctx.it = it; + if (dup_recno_elmt(&it->data, elmt)) { + printf("Problem (invalid data size) detected in vlv cache record #%d\n", it->count); + return; + } + T(iterate(it->txn, vlvdbi->dbi, check_recno_ctx, &ctx)); +} + +int +walk_cache(iterator_t *it, void *ctx) +{ + char *pt = it->key.mv_data; + recno_elmt_t elmt = {0}; + MDB_val vkey; + MDB_val vdata; + switch (*pt) { + case 'O': + printf("vlv cache is in sync.\n"); + return 0; + case 'D': + if (it->key.mv_size < sizeof vkey.mv_size) { + printf("Problem (invalid key size) detected in vlv cache record #%d\n", it->count); + return 0; + } + memcpy(&vkey.mv_size, pt + it->key.mv_size - sizeof vkey.mv_size, sizeof vkey.mv_size); + vkey.mv_data = pt+1; + vdata.mv_data = pt+1+vkey.mv_size; + vdata.mv_size = it->key.mv_size - 1-vkey.mv_size - sizeof vkey.mv_size; + printf("vkey: "); dump_val(&vkey); putchar('\n'); + printf("vdata: "); dump_val(&vdata); putchar('\n'); + check_recno_record(it, ctx, &elmt); + if (cmp_val(&vkey, &elmt.key) != 0) { + printf("Problem (missmatching key value) detected in vlv cache record #%d\n", it->count); + return 0; + } + if (cmp_val(&vdata, &elmt.data) != 0) { + printf("Problem (missmatching data value) detected in vlv cache record #%d\n", it->count); + return 0; + } + return 0; + case 'R': + if (it->key.mv_size !=11) { + printf("Problem (invalid key size) detected in vlv cache record #%d\n", it->count); + return 0; + } + check_recno_record(it, ctx, &elmt); + return 0; + } + + return 0; +} + +void +process_vlv(int idx) +{ + int rc = 0; + MDB_txn *txn = 0; + printf("Processing: %s\n", dbis[idx].name); + T(mdb_txn_begin(env, NULL, MDB_RDONLY, &txn)); + T(iterate(txn, dbis[dbis[idx].recno_idx].dbi, walk_cache, &dbis[idx])) + T(mdb_txn_commit(txn)); +} + + +int main(int argc, char **argv) +{ + int rc = 0; + if (argc != 2) { + printf("Usage: %s \n", argv[1]); + printf("\tThis tools check the lmdb vlv caches consistency\n") + exit(1); + } + char *dbdir = argv[1]; + + open_db(argv[1]); + open_dbis(); + for (size_t i = 0; i < nbdbis; i++) { + if (dbis[i].is_vlv) { + process_vlv(i); + } + } + return 0; +}