Add debug logging to sync polling. Add speculative fix for vector-im/vector-web#544

lib/sync.js

@@ -30,6 +30,8 @@ var utils = require("./utils");
 var httpApi = require("./http-api");
 var Filter = require("./filter");
 
+var DEBUG = true;
+
 // /sync requests allow you to set a timeout= but the request may continue
 // beyond that and wedge forever, so we need to track how long we are willing
 // to keep open the connection. This constant is *ADDED* to the timeout= value
@@ -42,6 +44,10 @@ function getFilterName(userId, suffix) {
     return "FILTER_SYNC_" + userId + (suffix ? "_" + suffix : "");
 }
 
+function debuglog() {
+    if (!DEBUG) { return; }
+    console.log.apply(console, arguments);
+}
 
 
 /**
@@ -60,6 +66,7 @@ function SyncApi(client, opts) {
     opts.pendingEventOrdering = opts.pendingEventOrdering || "chronological";
     this.opts = opts;
     this._peekRoomId = null;
+    this._lowClientTimeouts = false;
 }
 
 /**
@@ -224,7 +231,7 @@ SyncApi.prototype.stopPeeking = function() {
  */
 SyncApi.prototype._peekPoll = function(roomId, token) {
     if (this._peekRoomId !== roomId) {
-        console.log("Stopped peeking in room %s", roomId);
+        debuglog("Stopped peeking in room %s", roomId);
         return;
     }
 
@@ -254,7 +261,7 @@ SyncApi.prototype._peekPoll = function(roomId, token) {
  * Main entry point
  */
 SyncApi.prototype.sync = function() {
-    console.log("SyncApi.sync");
+    debuglog("SyncApi.sync");
     var client = this.client;
     var self = this;
 
@@ -269,7 +276,7 @@ SyncApi.prototype.sync = function() {
         attempt += 1;
 
         client.pushRules().done(function(result) {
-            console.log("Got push rules");
+            debuglog("Got push rules");
             client.pushRules = result;
             getFilter(); // Now get the filter
         }, retryHandler(attempt, getPushRules));
@@ -285,7 +292,7 @@ SyncApi.prototype.sync = function() {
         self._getOrCreateFilter(
             getFilterName(client.credentials.userId), filter
         ).done(function(filterId) {
-            console.log("Using existing filter ID %s", filterId);
+            debuglog("Using existing filter ID %s", filterId);
             self._sync({ filterId: filterId });
         }, retryHandler(attempt, getFilter));
     }
@@ -339,10 +346,28 @@ SyncApi.prototype._sync = function(syncOptions, attempt) {
         qps.timeout = 0;
     }
 
+    // normal timeout= plus buffer time
+    var clientSideTimeoutMs = this.opts.pollTimeout + BUFFER_PERIOD_MS;
+
+    if (self._lowClientTimeouts) {
+        debuglog("_lowClientTimeouts flag set.");
+        clientSideTimeoutMs = this.opts.pollTimeout;
+    }
+
+    var dateStamp = new Date();
+    dateStamp = dateStamp.getHours() + ":" + dateStamp.getMinutes() + ":" + dateStamp.getSeconds() +
+        "." + dateStamp.getMilliseconds();
+    debuglog("DEBUG[%s]: NEW _sync attempt=%s qp_timeout=%s cli_timeout=%s",
+        dateStamp, attempt, qps.timeout, clientSideTimeoutMs);
+
+
+
     client._http.authedRequestWithPrefix(
         undefined, "GET", "/sync", qps, undefined, httpApi.PREFIX_V2_ALPHA,
-        this.opts.pollTimeout + BUFFER_PERIOD_MS // normal timeout= plus buffer time
+        clientSideTimeoutMs
     ).done(function(data) {
+        debuglog("DEBUG[%s]: _sync RECV", dateStamp);
+        self._lowClientTimeouts = false;
         // data looks like:
         // {
         //    next_batch: $token,
@@ -506,10 +531,16 @@ SyncApi.prototype._sync = function(syncOptions, attempt) {
 
         self._sync(syncOptions);
     }, function(err) {
+        debuglog("DEBUG[%s]: RECV FAIL %s", dateStamp, require("util").inspect(err));
         console.error("/sync error (%s attempts): %s", attempt, err);
         console.error(err);
         attempt += 1;
-        startSyncingRetryTimer(client, attempt, function(newAttempt) {
+        startSyncingRetryTimer(client, attempt, function(newAttempt, extendedWait) {
+            debuglog("DEBUG[%s]: Init new _sync new_attempt=%s extended_wait=%s",
+                dateStamp, newAttempt, extendedWait);
+            if (extendedWait) {
+                self._lowClientTimeouts = true;
+            }
             self._sync(syncOptions, newAttempt);
         });
         updateSyncState(client, "ERROR", { error: err });
@@ -704,17 +735,19 @@ function startSyncingRetryTimer(client, attempt, fn) {
     client._syncingRetry.timeoutId = setTimeout(function() {
         var timeAfterWaitingMs = Date.now();
         var timeDeltaMs = timeAfterWaitingMs - timeBeforeWaitingMs;
+        var extendedWait = false;
         if (timeDeltaMs > (2 * timeToWaitMs)) {
             // we've waited more than twice what we were supposed to. Reset the
             // attempt number back to 1. This can happen when the comp goes to
             // sleep whilst the timer is running.
             newAttempt = 1;
+            extendedWait = true;
             console.warn(
                 "Sync retry timer: Tried to wait %s ms but actually waited %s ms",
                 timeToWaitMs, timeDeltaMs
             );
         }
-        fn(newAttempt);
+        fn(newAttempt, extendedWait);
     }, timeToWaitMs);
 }