From 27d5704978ae0b4e30b571fc73c637c5757ec5ac Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 14 Jun 2017 16:06:39 +0100 Subject: [PATCH 1/3] Improve logging in mock-request Try to make it a bit more obvious what's been going on in mock-request: add timestamps to lines, and an identifier so that where we have two flushes in parallel, we can see what's what. --- test/mock-request.js | 33 +++++++++++++++------------------ 1 file changed, 15 insertions(+), 18 deletions(-) diff --git a/test/mock-request.js b/test/mock-request.js index 0ebabb038c..c58301100a 100644 --- a/test/mock-request.js +++ b/test/mock-request.js @@ -13,7 +13,7 @@ function HttpBackend() { // the request function dependency that the SDK needs. this.requestFn = function(opts, callback) { const req = new Request(opts, callback); - console.log("HTTP backend received request: " + req); + console.log(`${Date.now()} HTTP backend received request: ${req}`); self.requests.push(req); const abort = function() { @@ -50,45 +50,42 @@ HttpBackend.prototype = { if (waitTime === undefined) { waitTime = 5; } - console.log( - "HTTP backend flushing... (path=" + path + + function log(msg) { + console.log(`${Date.now()} flush[${path || ''}]: ${msg}`); + } + + log("HTTP backend flushing... (path=" + path + " numToFlush=" + numToFlush + " waitTime=" + waitTime + ")", ); const tryFlush = function() { // if there's more real requests and more expected requests, flush 'em. - console.log( - " trying to flush queue => reqs=[" + self.requests - + "] expected=[" + self.expectedRequests - + "]", + log(` trying to flush => reqs=[${self.requests}] ` + + `expected=[${self.expectedRequests}]`, ); if (self._takeFromQueue(path)) { // try again on the next tick. flushed += 1; if (numToFlush && flushed === numToFlush) { - console.log(" Flushed assigned amount:", numToFlush); + log(`Flushed assigned amount: ${numToFlush}`); defer.resolve(flushed); } else { - console.log(" flushed. Trying for more."); + log(` flushed. Trying for more.`); setTimeout(tryFlush, 0); } } else if (flushed === 0 && !triedWaiting) { // we may not have made the request yet, wait a generous amount of // time before giving up. - console.log( - " nothing to flush yet; waiting " + waitTime + - "ms for requests.") + log(` nothing to flush yet; waiting for requests.`); setTimeout(tryFlush, waitTime); triedWaiting = true; } else { if (flushed === 0) { - console.log(" nothing to flush; giving up"); + log("nothing to flush; giving up"); } else { - console.log( - " no more flushes after flushing", flushed, - "requests", - ); + log(`no more flushes after flushing ${flushed} requests`); } defer.resolve(flushed); } @@ -138,7 +135,7 @@ HttpBackend.prototype = { matchingReq.checks[j](req); } testResponse = matchingReq.response; - console.log(" responding to %s", matchingReq.path); + console.log(`${Date.now()} responding to ${matchingReq.path}`); let body = testResponse.body; if (Object.prototype.toString.call(body) == "[object Function]") { body = body(req.path, req.data); From 6f2eee1f03ce44a5f6bfb35290d74f28c7ad818c Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Wed, 14 Jun 2017 16:07:40 +0100 Subject: [PATCH 2/3] Attempts to deflakify the joining test Treat the waitTime passed into `flush` as a timeout rather than a time-between-loops, so that we can pass in bigger times and not slow the tests down too much. Bump the timeout when waiting for /publicRooms and /initialSync in the joining test. --- test/app-tests/joining.js | 10 ++++++---- test/mock-request.js | 10 +++++----- 2 files changed, 11 insertions(+), 9 deletions(-) diff --git a/test/app-tests/joining.js b/test/app-tests/joining.js index e835ebb9cb..0aeb081a5e 100644 --- a/test/app-tests/joining.js +++ b/test/app-tests/joining.js @@ -68,7 +68,7 @@ describe('joining a room', function () { } }); - it('should not get stuck at a spinner', function(done) { + it('should not get stuck at a spinner', function() { var ROOM_ALIAS = '#alias:localhost'; var ROOM_ID = '!id:localhost'; @@ -140,12 +140,14 @@ describe('joining a room', function () { .respond(401, {errcode: 'M_GUEST_ACCESS_FORBIDDEN'}); return q.all([ - httpBackend.flush('/directory/room/'+encodeURIComponent(ROOM_ALIAS)), - httpBackend.flush('/rooms/'+encodeURIComponent(ROOM_ID)+"/initialSync"), + httpBackend.flush('/directory/room/'+encodeURIComponent(ROOM_ALIAS), 1, 200), + httpBackend.flush('/rooms/'+encodeURIComponent(ROOM_ID)+"/initialSync", 1, 200), ]); }).then(() => { httpBackend.verifyNoOutstandingExpectation(); + return q.delay(1); + }).then(() => { // we should now have a roomview, with a preview bar roomView = ReactTestUtils.findRenderedComponentWithType( matrixChat, RoomView); @@ -208,7 +210,7 @@ describe('joining a room', function () { }).then(() => { // now the room should have loaded expect(roomView.state.room).toExist(); - }).done(done, done); + }); }); }); }); diff --git a/test/mock-request.js b/test/mock-request.js index c58301100a..46d165824d 100644 --- a/test/mock-request.js +++ b/test/mock-request.js @@ -46,9 +46,8 @@ HttpBackend.prototype = { const defer = q.defer(); const self = this; let flushed = 0; - let triedWaiting = false; if (waitTime === undefined) { - waitTime = 5; + waitTime = 10; } function log(msg) { @@ -60,6 +59,8 @@ HttpBackend.prototype = { + " waitTime=" + waitTime + ")", ); + const endTime = waitTime + Date.now(); + const tryFlush = function() { // if there's more real requests and more expected requests, flush 'em. log(` trying to flush => reqs=[${self.requests}] ` + @@ -75,12 +76,11 @@ HttpBackend.prototype = { log(` flushed. Trying for more.`); setTimeout(tryFlush, 0); } - } else if (flushed === 0 && !triedWaiting) { + } else if (flushed === 0 && Date.now() < endTime) { // we may not have made the request yet, wait a generous amount of // time before giving up. log(` nothing to flush yet; waiting for requests.`); - setTimeout(tryFlush, waitTime); - triedWaiting = true; + setTimeout(tryFlush, 5); } else { if (flushed === 0) { log("nothing to flush; giving up"); From a28af8bcc6e5ba1df09d957a8c9621e951c3c84e Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 15 Jun 2017 16:01:26 +0100 Subject: [PATCH 3/3] Extend timeouts in joining tests again this seems to work? maybe? --- test/app-tests/joining.js | 2 +- test/mock-request.js | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/test/app-tests/joining.js b/test/app-tests/joining.js index 0aeb081a5e..d967012567 100644 --- a/test/app-tests/joining.js +++ b/test/app-tests/joining.js @@ -119,8 +119,8 @@ describe('joining a room', function () { httpBackend.when('POST', '/publicRooms').respond(200, {chunk: []}); httpBackend.when('GET', '/thirdparty/protocols').respond(200, {}); return q.all([ - httpBackend.flush('/publicRooms'), httpBackend.flush('/thirdparty/protocols'), + httpBackend.flush('/publicRooms'), ]); }).then(() => { var roomDir = ReactTestUtils.findRenderedComponentWithType( diff --git a/test/mock-request.js b/test/mock-request.js index 46d165824d..8b5b0e0a16 100644 --- a/test/mock-request.js +++ b/test/mock-request.js @@ -37,7 +37,7 @@ HttpBackend.prototype = { * @param {string} path The path to flush (optional) default: all. * @param {integer} numToFlush The number of things to flush (optional), default: all. * @param {integer=} waitTime The time (in ms) to wait for a request to happen. - * default: 5 + * default: 100 * * @return {Promise} resolves when there is nothing left to flush, with the * number of requests flushed @@ -47,7 +47,7 @@ HttpBackend.prototype = { const self = this; let flushed = 0; if (waitTime === undefined) { - waitTime = 10; + waitTime = 100; } function log(msg) {