diff --git a/lib/sync.js b/lib/sync.js index 2e160756e..ebc24aaa7 100644 --- a/lib/sync.js +++ b/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); }