Merge branch 'devel' of https://github.com/arangodb/arangodb into devel

arangod/Cluster/DBServerAgencySync.cpp

@@ -54,6 +54,8 @@ void DBServerAgencySync::work() {
 DBServerAgencySyncResult DBServerAgencySync::execute() {
   // default to system database
 
+  double startTime = TRI_microtime();
+
   LOG_TOPIC(DEBUG, Logger::HEARTBEAT) << "DBServerAgencySync::execute starting";
   DatabaseFeature* database = 
     ApplicationServer::getFeature<DatabaseFeature>("Database");
@@ -80,6 +82,11 @@ DBServerAgencySyncResult DBServerAgencySync::execute() {
     return result;
   }
 
+  double now = TRI_microtime();
+  if (now - startTime > 5.0) {
+    LOG(INFO) << "DBServerAgencySync::execute took more than 5s to get free V8 context, starting handle-plan-change now";
+  }
+
   TRI_DEFER(V8DealerFeature::DEALER->exitContext(context));
 
   auto isolate = context->_isolate;

js/server/modules/@arangodb/cluster.js

@@ -120,14 +120,12 @@ function startReadLockOnLeader (endpoint, database, collName, timeout) {
   const id = r.id;
 
   var body = { 'id': id, 'collection': collName, 'ttl': timeout };
-  r = request({ url: url + '/_api/replication/holdReadLockCollection',
+  request({ url: url + '/_api/replication/holdReadLockCollection',
-                body: JSON.stringify(body),
+            body: JSON.stringify(body),
-                method: 'POST', headers: {'x-arango-async': true} });
+            method: 'POST', headers: {'x-arango-async': true} });
-  if (r.status !== 202) {
+  // Intentionally do not look at the outcome, even in case of an error
-    console.error('startReadLockOnLeader: Could not start read lock for shard',
+  // we must make sure that the read lock on the leader is not active!
-      collName, r);
+  // This is done automatically below.
-    return false;
-  }
 
   var count = 0;
   while (++count < 20) { // wait for some time until read lock established:
@@ -170,7 +168,10 @@ function startReadLockOnLeader (endpoint, database, collName, timeout) {
 // /////////////////////////////////////////////////////////////////////////////
 
 function cancelReadLockOnLeader (endpoint, database, lockJobId) {
-  var url = endpointToURL(endpoint) + '/_db/' + database +
+  // Note that we always use the _system database here because the actual
+  // database might be gone already on the leader and we need to cancel
+  // the read lock under all circumstances.
+  var url = endpointToURL(endpoint) + '/_db/_system' +
     '/_api/replication/holdReadLockCollection';
   var r;
   var body = {'id': lockJobId};
@@ -181,7 +182,8 @@ function cancelReadLockOnLeader (endpoint, database, lockJobId) {
     return false;
   }
   if (r.status !== 200) {
-    console.error('cancelReadLockOnLeader: error', r);
+    console.error('cancelReadLockOnLeader: error', lockJobId, r.status,
+                  r.message, r.body, r.json);
     return false;
   }
   console.debug('cancelReadLockOnLeader: success');
@@ -453,6 +455,7 @@ function synchronizeOneShard (database, shard, planId, leader) {
   // synchronize this shard from the leader
   // this function will throw if anything goes wrong
 
+  var startTime = new Date();
   var isStopping = require('internal').isStopping;
   var ourselves = global.ArangoServerState.id();
 
@@ -485,8 +488,9 @@ function synchronizeOneShard (database, shard, planId, leader) {
       planned[0] !== leader) {
       // Things have changed again, simply terminate:
       terminateAndStartOther();
-      console.debug('synchronizeOneShard: cancelled, %s/%s, %s/%s',
+      let endTime = new Date();
-        database, shard, database, planId);
+      console.debug('synchronizeOneShard: cancelled, %s/%s, %s/%s, started %s, ended %s',
+        database, shard, database, planId, startTime.toString(), endTime.toString());
       return;
     }
     var current = [];
@@ -500,8 +504,9 @@ function synchronizeOneShard (database, shard, planId, leader) {
       }
       // We are already there, this is rather strange, but never mind:
       terminateAndStartOther();
-      console.debug('synchronizeOneShard: already done, %s/%s, %s/%s',
+      let endTime = new Date();
-        database, shard, database, planId);
+      console.debug('synchronizeOneShard: already done, %s/%s, %s/%s, started %s, ended %s',
+        database, shard, database, planId, startTime.toString(), endTime.toString());
       return;
     }
     console.debug('synchronizeOneShard: waiting for leader, %s/%s, %s/%s',
@@ -522,9 +527,16 @@ function synchronizeOneShard (database, shard, planId, leader) {
     if (isStopping()) {
       throw 'server is shutting down';
     }
+    let startTime = new Date();
     sy = rep.syncCollection(shard,
       { endpoint: ep, incremental: true,
       keepBarrier: true, useCollectionId: false });
+    let endTime = new Date();
+    let longSync = false;
+    if (endTime - startTime > 5000) {
+      console.error('synchronizeOneShard: long call to syncCollection for shard', shard, JSON.stringify(sy), "start time: ", startTime.toString(), "end time: ", endTime.toString());
+      longSync = true;
+    }
     if (sy.error) {
       console.error('synchronizeOneShard: could not initially synchronize',
         'shard ', shard, sy);
@@ -532,7 +544,15 @@ function synchronizeOneShard (database, shard, planId, leader) {
     } else {
       if (sy.collections.length === 0 ||
         sy.collections[0].name !== shard) {
+        if (longSync) {
+          console.error('synchronizeOneShard: long sync, before cancelBarrier',
+                        new Date().toString());
+        }
         cancelBarrier(ep, database, sy.barrierId);
+        if (longSync) {
+          console.error('synchronizeOneShard: long sync, after cancelBarrier',
+                        new Date().toString());
+        }
         throw 'Shard ' + shard + ' seems to be gone from leader!';
       } else {
         // Now start a read transaction to stop writes:
@@ -592,14 +612,17 @@ function synchronizeOneShard (database, shard, planId, leader) {
       } else if (err2 && err2.errorNum === 1402 && err2.errorMessage.match(/HTTP 404/)) {
         logLevel = 'debug';
       }
-      console[logLevel]("synchronization of local shard '%s/%s' for central '%s/%s' failed: %s",
+      let endTime = new Date();
-        database, shard, database, planId, JSON.stringify(err2));
+      console[logLevel]("synchronization of local shard '%s/%s' for central '%s/%s' failed: %s, started: %s, ended: %s",
+        database, shard, database, planId, JSON.stringify(err2),
+        startTime.toString(), endTime.toString());
     }
   }
   // Tell others that we are done:
   terminateAndStartOther();
-  console.debug('synchronizeOneShard: done, %s/%s, %s/%s',
+  let endTime = new Date();
-    database, shard, database, planId);
+  console.debug('synchronizeOneShard: done, %s/%s, %s/%s, started: %s, ended: %s',
+    database, shard, database, planId, startTime.toString(), endTime.toString());
 }
 
 // /////////////////////////////////////////////////////////////////////////////