diff --git a/arangod/MMFiles/mmfiles-replication-dump.cpp b/arangod/MMFiles/mmfiles-replication-dump.cpp index 32ad5fbbc4..c190aa3ba7 100644 --- a/arangod/MMFiles/mmfiles-replication-dump.cpp +++ b/arangod/MMFiles/mmfiles-replication-dump.cpp @@ -483,8 +483,6 @@ int MMFilesDumpLogReplication(MMFilesReplicationDumpContext* dump, std::unordered_set const& transactionIds, TRI_voc_tick_t firstRegularTick, TRI_voc_tick_t tickMin, TRI_voc_tick_t tickMax, bool outputAsArray) { - LOG_TOPIC(DEBUG, arangodb::Logger::REPLICATION) - << "dumping log, tick range " << tickMin << " - " << tickMax; // get a custom type handler auto customTypeHandler = dump->_transactionContext->orderCustomTypeHandler(); @@ -494,6 +492,12 @@ int MMFilesDumpLogReplication(MMFilesReplicationDumpContext* dump, bool fromTickIncluded = false; std::vector logfiles = MMFilesLogfileManager::instance()->getLogfilesForTickRange(tickMin, tickMax, fromTickIncluded); + + // always return the logfiles we have used + TRI_DEFER(MMFilesLogfileManager::instance()->returnLogfiles(logfiles)); + + LOG_TOPIC(DEBUG, arangodb::Logger::REPLICATION) + << "dumping log, tick range " << tickMin << " - " << tickMax << ", fromTickIncluded: " << fromTickIncluded; // setup some iteration state int res = TRI_ERROR_NO_ERROR; @@ -520,6 +524,9 @@ int MMFilesDumpLogReplication(MMFilesReplicationDumpContext* dump, char const* ptr; char const* end; MMFilesLogfileManager::instance()->getActiveLogfileRegion(logfile, ptr, end); + + LOG_TOPIC(DEBUG, arangodb::Logger::REPLICATION) + << "dumping logfile " << logfile->id(); while (ptr < end) { auto const* marker = reinterpret_cast(ptr); @@ -654,9 +661,6 @@ int MMFilesDumpLogReplication(MMFilesReplicationDumpContext* dump, res = TRI_ERROR_INTERNAL; } - // always return the logfiles we have used - MMFilesLogfileManager::instance()->returnLogfiles(logfiles); - dump->_fromTickIncluded = fromTickIncluded; dump->_lastScannedTick = lastScannedTick; @@ -674,9 +678,11 @@ int MMFilesDumpLogReplication(MMFilesReplicationDumpContext* dump, } LOG_TOPIC(DEBUG, arangodb::Logger::REPLICATION) - << "dumped log, tick range " - << tickMin << " - " << tickMax << ", markers: " << numMarkers + << "dumped log, tick range " << tickMin << " - " << tickMax + << ", markers: " << numMarkers << ", last found tick: " << dump->_lastFoundTick + << ", last scanned tick: " << dump->_lastScannedTick + << ", from tick included: " << dump->_fromTickIncluded << ", hasMore: " << dump->_hasMore << ", buffer full: " << dump->_bufferFull; } @@ -696,14 +702,14 @@ int MMFilesDetermineOpenTransactionsReplication(MMFilesReplicationDumpContext* d bool fromTickIncluded = false; std::vector logfiles = MMFilesLogfileManager::instance()->getLogfilesForTickRange(tickMin, tickMax, fromTickIncluded); + + // always return the logfiles we have used + TRI_DEFER(MMFilesLogfileManager::instance()->returnLogfiles(logfiles)); // setup some iteration state TRI_voc_tick_t lastFoundTick = 0; int res = TRI_ERROR_NO_ERROR; - // LOG_TOPIC(INFO, arangodb::Logger::REPLICATION) << "found logfiles: " << - // logfiles.size(); - try { // iterate over the datafiles found size_t const n = logfiles.size(); @@ -714,8 +720,6 @@ int MMFilesDetermineOpenTransactionsReplication(MMFilesReplicationDumpContext* d char const* end; MMFilesLogfileManager::instance()->getActiveLogfileRegion(logfile, ptr, end); - // LOG_TOPIC(INFO, arangodb::Logger::REPLICATION) << "scanning logfile " - // << i; while (ptr < end) { auto const* marker = reinterpret_cast(ptr); @@ -770,10 +774,6 @@ int MMFilesDetermineOpenTransactionsReplication(MMFilesReplicationDumpContext* d } } - // LOG_TOPIC(INFO, arangodb::Logger::REPLICATION) << "found transactions: " - // << transactions.size(); LOG_TOPIC(INFO, arangodb::Logger::REPLICATION) << - // "last tick: " << lastFoundTick; - VPackBuffer buffer; VPackBuilder builder(buffer); if (useVst) { @@ -817,9 +817,6 @@ int MMFilesDetermineOpenTransactionsReplication(MMFilesReplicationDumpContext* d dump->_fromTickIncluded = fromTickIncluded; dump->_lastFoundTick = lastFoundTick; - // LOG_TOPIC(INFO, arangodb::Logger::REPLICATION) << "last tick2: " << - // lastFoundTick; - dump->_slices.push_back(std::move(buffer)); } catch (arangodb::basics::Exception const& ex) { @@ -836,8 +833,5 @@ int MMFilesDetermineOpenTransactionsReplication(MMFilesReplicationDumpContext* d res = TRI_ERROR_INTERNAL; } - // always return the logfiles we have used - MMFilesLogfileManager::instance()->returnLogfiles(logfiles); - return res; } diff --git a/arangod/Replication/TailingSyncer.cpp b/arangod/Replication/TailingSyncer.cpp index ae57943094..65f9f4c236 100644 --- a/arangod/Replication/TailingSyncer.cpp +++ b/arangod/Replication/TailingSyncer.cpp @@ -1033,7 +1033,6 @@ Result TailingSyncer::applyLog(SimpleHttpResult* response, TRI_voc_tick_t firstR } // update tick value - // postApplyMarker(processedMarkers, skipped); WRITE_LOCKER_EVENTUAL(writeLocker, _applier->_statusLock); if (markerTick > firstRegularTick && @@ -1702,7 +1701,7 @@ Result TailingSyncer::processMasterLog(std::shared_ptr TRI_voc_tick_t& fetchTick, TRI_voc_tick_t& lastScannedTick, TRI_voc_tick_t firstRegularTick, uint64_t& ignoreCount, bool& worked, bool& mustFetchBatch) { - LOG_TOPIC(TRACE, Logger::REPLICATION) + LOG_TOPIC(DEBUG, Logger::REPLICATION) << "entering processMasterLog. fetchTick: " << fetchTick << ", worked: " << worked << ", mustFetchBatch: " << mustFetchBatch; @@ -1756,9 +1755,12 @@ Result TailingSyncer::processMasterLog(std::shared_ptr StaticStrings::ReplicationHeaderLastIncluded + " is missing in logger-follow response"); } - + TRI_voc_tick_t lastIncludedTick = getUIntHeader(response, StaticStrings::ReplicationHeaderLastIncluded); + TRI_voc_tick_t tick = getUIntHeader(response, StaticStrings::ReplicationHeaderLastTick); + + LOG_TOPIC(DEBUG, Logger::REPLICATION) << "applyLog. fetchTick: " << fetchTick << ", checkMore: " << checkMore << ", fromIncluded: " << fromIncluded << ", lastScannedTick: " << lastScannedTick << ", lastIncludedTick: " << lastIncludedTick << ", tick: " << tick; if (lastIncludedTick == 0 && lastScannedTick > 0 && lastScannedTick > fetchTick) { // master did not have any news for us @@ -1772,6 +1774,7 @@ Result TailingSyncer::processMasterLog(std::shared_ptr } else { // we got the same tick again, this indicates we're at the end checkMore = false; + LOG_TOPIC(DEBUG, Logger::REPLICATION) << "applyLog. got the same tick again, turning off checkMore"; } if (!hasHeader(response, StaticStrings::ReplicationHeaderLastTick)) { @@ -1783,7 +1786,6 @@ Result TailingSyncer::processMasterLog(std::shared_ptr } bool bumpTick = false; - TRI_voc_tick_t tick = getUIntHeader(response, StaticStrings::ReplicationHeaderLastTick); if (!checkMore && tick > lastIncludedTick) { // the master has a tick value which is not contained in this result @@ -1791,6 +1793,7 @@ Result TailingSyncer::processMasterLog(std::shared_ptr // so it's probably a tick from an invisible operation (such as // closing a WAL file) bumpTick = true; + LOG_TOPIC(DEBUG, Logger::REPLICATION) << "applyLog. bumping tick"; } { @@ -1837,6 +1840,12 @@ Result TailingSyncer::processMasterLog(std::shared_ptr uint64_t processedMarkers = 0; Result r = applyLog(response.get(), firstRegularTick, processedMarkers, ignoreCount); + if (r.fail()) { + LOG_TOPIC(DEBUG, Logger::REPLICATION) << "applyLog failed with error: " << r.errorMessage(); + } else { + LOG_TOPIC(DEBUG, Logger::REPLICATION) << "applyLog successful, lastAppliedTick: " << lastAppliedTick << ", firstRegularTick: " << firstRegularTick << ", processedMarkers: " << processedMarkers; + } + // cppcheck-suppress * if (processedMarkers > 0) { worked = true; diff --git a/tests/js/server/replication/replication-ongoing-32.js b/tests/js/server/replication/replication-ongoing-32.js index 4f88b8b588..b6e3d3ade5 100644 --- a/tests/js/server/replication/replication-ongoing-32.js +++ b/tests/js/server/replication/replication-ongoing-32.js @@ -95,7 +95,7 @@ const compare = function (masterFunc, masterFunc2, slaveFuncOngoing, slaveFuncFi applierConfiguration.username = 'root'; applierConfiguration.password = ''; applierConfiguration.force32mode = true; - applierConfiguration.requireFromPresent = false; + applierConfiguration.requireFromPresent = true; if (!applierConfiguration.hasOwnProperty('chunkSize')) { applierConfiguration.chunkSize = 16384; diff --git a/tests/js/server/replication/replication-ongoing-global.js b/tests/js/server/replication/replication-ongoing-global.js index 712f6fdb32..acdade3e2c 100644 --- a/tests/js/server/replication/replication-ongoing-global.js +++ b/tests/js/server/replication/replication-ongoing-global.js @@ -91,7 +91,7 @@ const compare = function (masterFunc, masterFunc2, slaveFuncOngoing, slaveFuncFi password: '', verbose: true, includeSystem: false, - keepBarrier: false, + keepBarrier: true, restrictType: applierConfiguration.restrictType, restrictCollections: applierConfiguration.restrictCollections }); @@ -111,7 +111,7 @@ const compare = function (masterFunc, masterFunc2, slaveFuncOngoing, slaveFuncFi connectToSlave(); replication.globalApplier.properties(applierConfiguration); - replication.globalApplier.start(syncResult.lastLogTick); + replication.globalApplier.start(syncResult.lastLogTick, syncResult.barrierId); var printed = false; var handled = false; @@ -501,10 +501,6 @@ function BaseTestConfig () { function (state) { const c = db._collection(cn); - let x = 10; - while (c.count() > 0 && x-- > 0) { - internal.sleep(1); - } assertEqual(c.count(), 0); assertEqual(c.all().toArray().length, 0); }