Wait for replication before inserting documents (#9151)

* Wait for replication before inserting documents

Also, increased some timeouts and fixed a log message

* Fixed some log levels and a log message

* Removed repair-distribute-shards-like-spec from greylisted tests

arangod/Cluster/SynchronizeShard.cpp

@@ -560,13 +560,10 @@ static arangodb::Result replicationSynchronize(
     Result r = syncer->run(configuration._incremental);
 
     if (r.fail()) {
-      LOG_TOPIC("3efff", ERR, Logger::REPLICATION)
+      LOG_TOPIC("3efff", DEBUG, Logger::REPLICATION)
           << "initial sync failed for database '" << database
           << "': " << r.errorMessage();
-      THROW_ARANGO_EXCEPTION_MESSAGE(r.errorNumber(),
-                                     "cannot sync from remote endpoint: " + r.errorMessage() +
-                                         ". last progress message was '" +
-                                         syncer->progress() + "'");
+      THROW_ARANGO_EXCEPTION_MESSAGE(r.errorNumber(), r.errorMessage());
     }
 
     {
@@ -883,7 +880,7 @@ bool SynchronizeShard::first() {
         std::stringstream error;
         error << "could not initially synchronize shard " << shard << ": "
               << res.errorMessage();
-        LOG_TOPIC("c1b31", ERR, Logger::MAINTENANCE) << "SynchronizeOneShard: " << error.str();
+        LOG_TOPIC("c1b31", DEBUG, Logger::MAINTENANCE) << "SynchronizeOneShard: " << error.str();
         _result.reset(TRI_ERROR_INTERNAL, error.str());
         return false;
       }

arangod/Replication/DatabaseInitialSyncer.cpp

@@ -228,7 +228,7 @@ Result DatabaseInitialSyncer::runWithInventory(bool incremental, VPackSlice dbIn
     }
 
     if (r.fail()) {
-      LOG_TOPIC("12556", ERR, Logger::REPLICATION)
+      LOG_TOPIC("12556", DEBUG, Logger::REPLICATION)
           << "Error during initial sync: " << r.errorMessage();
     }
 

arangod/V8Server/v8-replication.cpp

@@ -234,7 +234,7 @@ static void SynchronizeReplication(v8::FunctionCallbackInfo<v8::Value> const& ar
     Result r = syncer->run(configuration._incremental);
 
     if (r.fail()) {
-      LOG_TOPIC("3d58b", ERR, Logger::REPLICATION)
+      LOG_TOPIC("3d58b", DEBUG, Logger::REPLICATION)
           << "initial sync failed for database '" << vocbase.name()
           << "': " << r.errorMessage();
       TRI_V8_THROW_EXCEPTION_MESSAGE(r.errorNumber(),

lib/Basics/Exceptions.h

@@ -58,10 +58,10 @@
   throw arangodb::basics::Exception(code, message, __FILE__, __LINE__)
 
 /// @brief throws an arango result if the result fails
-#define THROW_ARANGO_EXCEPTION_IF_FAIL(reSUlt)                         \
+#define THROW_ARANGO_EXCEPTION_IF_FAIL(result)                         \
   do {                                                                 \
-    if ((reSUlt).fail()) {                                             \
-      throw arangodb::basics::Exception((reSUlt), __FILE__, __LINE__); \
+    if ((result).fail()) {                                             \
+      throw arangodb::basics::Exception((result), __FILE__, __LINE__); \
     }                                                                  \
   } while (0);
 

tests/Greylist.txt

@@ -102,24 +102,6 @@ Mount: /unittest/paths
 
 ======================================================================
 
-- `tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js`
-
-    [FAILED]  tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js
-
-      "Collections with distributeShardsLike with data if broken, should be repaired" failed: AssertionError: expected false to be true
-    at createBrokenClusterState (tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js:220:57)
-    at Context.<anonymous> (tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js:560:11)
-
-      "Collections with distributeShardsLike with data if interrupted, should complete repairs" failed: AssertionError: expected false to be true
-    at createBrokenClusterState (tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js:221:52)
-    at Context.<anonymous> (tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js:624:13)
-
-      "Collections with distributeShardsLike with data if called via GET, only return planned operations" failed: AssertionError: expected false to be true
-    at createBrokenClusterState (tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js:221:52)
-    at Context.<anonymous> (tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js:761:11)
-
-======================================================================
-
 - `tests/js/server/resilience/failover/resilience-synchronous-repl-cluster.js`
 
     [FAILED]  tests/js/server/resilience/failover/resilience-synchronous-repl-cluster.js

tests/js/server/resilience/repair/repair-distribute-shards-like-spec.js

@@ -43,7 +43,7 @@ let dbServerCount = instanceInfo.arangods.filter(arangod => {
 
 const waitForPlanEqualCurrent = function (collection) {
   const waitTime = 1.0;
-  const maxTime = 120;
+  const maxTime = 300;
 
   for (let start = Date.now(); (Date.now() - start)/1000 < maxTime; ) {
     global.ArangoClusterInfo.flush();
@@ -58,13 +58,13 @@ const waitForPlanEqualCurrent = function (collection) {
     wait(waitTime);
   }
 
-  console.error(`Collection "${collection}" failed to get plan in sync after ${maxTime/1000} sec`);
+  console.error(`Collection "${collection}" failed to get plan in sync after ${maxTime} sec`);
   return false;
 };
 
 const waitForReplicationFactor = function (collection) {
   const waitTime = 1.0;
-  const maxTime = 120;
+  const maxTime = 300;
 
   for (let start = Date.now(); (Date.now() - start)/1000 < maxTime; ) {
     global.ArangoClusterInfo.flush();
@@ -486,6 +486,10 @@ const createCollectionOptionallyWithData =
   let dataInfo;
 
   if (withData) {
+    // Waiting here is not strictly necessary. However, it should speed up the
+    // whole process, as we start with synchronous replication immediately,
+    // and thus hopefully reduce random timeouts.
+    expect(waitForPlanEqualCurrent(collection), 'Timeout while waiting for a newly created, empty collection to come in sync').to.be.true;
     dataInfo = fillWithAndReturnDataInfo(collection);
   } else {
     // zero length data