some more debug logging for replication (#8082)

arangod/MMFiles/mmfiles-replication-dump.cpp

@@ -483,8 +483,6 @@ int MMFilesDumpLogReplication(MMFilesReplicationDumpContext* dump,
                               std::unordered_set<TRI_voc_tid_t> 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<arangodb::MMFilesWalLogfile*> 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<MMFilesMarker const*>(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<arangodb::MMFilesWalLogfile*> 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<MMFilesMarker const*>(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<uint8_t> 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;
 }

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<Syncer::JobSynchronizer>
                                        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<Syncer::JobSynchronizer>
                       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<Syncer::JobSynchronizer>
   } 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<Syncer::JobSynchronizer>
   }
 
   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<Syncer::JobSynchronizer>
     // 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<Syncer::JobSynchronizer>
   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;

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;

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);
         }