From ef3c44f0d51d3ddf454da5b738604787ea738c96 Mon Sep 17 00:00:00 2001 From: Sharon Kennedy Date: Wed, 18 Mar 2020 03:00:43 -0400 Subject: [PATCH] catch bot rate limiting error, update tests --- .gitignore | 3 +- __mocks__/matrix-js-sdk.js | 4 +- dist/bot.js | 96 +++++++++++++++---- dist/bot.test.js | 192 ------------------------------------- package.json | 3 + src/bot.js | 89 ++++++++++++----- src/bot.test.js | 11 ++- 7 files changed, 156 insertions(+), 242 deletions(-) delete mode 100644 dist/bot.test.js diff --git a/.gitignore b/.gitignore index 4c54642..d55a492 100644 --- a/.gitignore +++ b/.gitignore @@ -1,3 +1,4 @@ .env node_modules -*.log \ No newline at end of file +*.log +__mocks__/test_transcript.txt \ No newline at end of file diff --git a/__mocks__/matrix-js-sdk.js b/__mocks__/matrix-js-sdk.js index bc356ca..1911e4a 100644 --- a/__mocks__/matrix-js-sdk.js +++ b/__mocks__/matrix-js-sdk.js @@ -19,8 +19,8 @@ export const mockRegisterRequest = jest export const mockDeleteMultipleDevices = jest .fn() - .mockImplementation((params) => { - if (!params.auth) { + .mockImplementation((devices, auth) => { + if (!auth) { return Promise.reject({ data: { session: "session_id_1234" } }) diff --git a/dist/bot.js b/dist/bot.js index c7f093d..3ab0219 100644 --- a/dist/bot.js +++ b/dist/bot.js @@ -244,6 +244,48 @@ function () { value: function deleteOldDevices() { var _this6 = this; + var doDelete = function doDelete(oldDevices) { + var auth = arguments.length > 1 && arguments[1] !== undefined ? arguments[1] : null; + var retries = arguments.length > 2 && arguments[2] !== undefined ? arguments[2] : 0; + + if (retries > MAX_RETRIES) { + throw new Error("Exceeded max retries deleting old devices"); + } + + _logger["default"].log("info", "ATTEMPTING TO DELETE OLD DEVICES: ".concat(oldDevices)); + + _this6.client.deleteMultipleDevices(oldDevices, auth).then(function () { + return _logger["default"].log("info", "DELETED OLD DEVICES"); + })["catch"](function (err) { + if (err['errcode'] === undefined && err['data']) { + var _auth = { + session: err.data.session, + type: "m.login.password", + user: process.env.BOT_USERID, + identifier: { + type: "m.id.user", + user: process.env.BOT_USERID + }, + password: process.env.BOT_PASSWORD + }; + doDelete(oldDevices, _auth); + } else if (err['errcode'] === 'M_LIMIT_EXCEEDED') { + var retryCount = retries + 1; + var delay = err['retry_after_ms'] ? err['retry_after_ms'] : retryCount * 1000; + + _logger["default"].log("error", "RATE LIMIT EXCEEDED, RETRYING IN ".concat(delay, " MS")); + + setTimeout(function () { + doDelete(oldDevices, auth, retryCount); + }, delay); + } else { + _logger["default"].log("error", "ERROR DELETING OLD DEVICES ON RETRY ".concat(retries, ": ").concat(JSON.stringify(err))); + + doDelete(oldDevices, auth, retries + 1); + } + }); + }; + return this.client.getDevices().then(function (data) { var currentDeviceId = _this6.client.getDeviceId(); @@ -253,29 +295,41 @@ function () { var oldDevices = allDeviceIds.filter(function (id) { return id !== currentDeviceId; }); + doDelete(oldDevices); + })["catch"](function (err) { + _this6.handleBotCrash(undefined, err); - _logger["default"].log("info", "DELETING OLD DEVICES: ".concat(oldDevices)); - - _this6.client.deleteMultipleDevices(oldDevices)["catch"](function (err) { - var auth = { - session: err.data.session, - type: "m.login.password", - user: process.env.BOT_USERID, - identifier: { - type: "m.id.user", - user: process.env.BOT_USERID - }, - password: process.env.BOT_PASSWORD - }; - - _this6.client.deleteMultipleDevices(oldDevices, auth).then(function () { - return _logger["default"].log("info", "DELETED OLD DEVICES"); - })["catch"](function (err) { - return _logger["default"].log("error", "ERROR DELETING OLD DEVICES: ".concat(JSON.stringify(err.data))); - }); - }); + _logger["default"].log("error", "ERROR DELETING OLD DEVICES: ".concat(JSON.stringify(err.data))); }); - } + } // deleteOldDevices() { + // return this.client.getDevices().then(data => { + // const currentDeviceId = this.client.getDeviceId(); + // const allDeviceIds = data.devices.map(d => d.device_id); + // const oldDevices = allDeviceIds.filter(id => id !== currentDeviceId); + // logger.log("info", `DELETING OLD DEVICES: ${oldDevices}`); + // this.client + // .deleteMultipleDevices(oldDevices) + // .catch(err => { + // const auth = { + // session: err.data.session, + // type: "m.login.password", + // user: process.env.BOT_USERID, + // identifier: { type: "m.id.user", user: process.env.BOT_USERID }, + // password: process.env.BOT_PASSWORD + // }; + // this.client + // .deleteMultipleDevices(oldDevices, auth) + // .then(() => logger.log("info", "DELETED OLD DEVICES")) + // .catch(err => + // logger.log( + // "error", + // `ERROR DELETING OLD DEVICES: ${JSON.stringify(err.data)}` + // ) + // ); + // }); + // }); + // } + }, { key: "setMembershipListeners", value: function setMembershipListeners() { diff --git a/dist/bot.test.js b/dist/bot.test.js deleted file mode 100644 index c935098..0000000 --- a/dist/bot.test.js +++ /dev/null @@ -1,192 +0,0 @@ -"use strict"; - -function _typeof(obj) { "@babel/helpers - typeof"; if (typeof Symbol === "function" && typeof Symbol.iterator === "symbol") { _typeof = function _typeof(obj) { return typeof obj; }; } else { _typeof = function _typeof(obj) { return obj && typeof Symbol === "function" && obj.constructor === Symbol && obj !== Symbol.prototype ? "symbol" : typeof obj; }; } return _typeof(obj); } - -var path = _interopRequireWildcard(require("path")); - -var os = _interopRequireWildcard(require("os")); - -var _waitForExpect = _interopRequireDefault(require("wait-for-expect")); - -var _matrixJsSdk = require("matrix-js-sdk"); - -var _bot = _interopRequireDefault(require("./bot")); - -function _interopRequireDefault(obj) { return obj && obj.__esModule ? obj : { "default": obj }; } - -function _getRequireWildcardCache() { if (typeof WeakMap !== "function") return null; var cache = new WeakMap(); _getRequireWildcardCache = function _getRequireWildcardCache() { return cache; }; return cache; } - -function _interopRequireWildcard(obj) { if (obj && obj.__esModule) { return obj; } if (obj === null || _typeof(obj) !== "object" && typeof obj !== "function") { return { "default": obj }; } var cache = _getRequireWildcardCache(); if (cache && cache.has(obj)) { return cache.get(obj); } var newObj = {}; var hasPropertyDescriptor = Object.defineProperty && Object.getOwnPropertyDescriptor; for (var key in obj) { if (Object.prototype.hasOwnProperty.call(obj, key)) { var desc = hasPropertyDescriptor ? Object.getOwnPropertyDescriptor(obj, key) : null; if (desc && (desc.get || desc.set)) { Object.defineProperty(newObj, key, desc); } else { newObj[key] = obj[key]; } } } newObj["default"] = obj; if (cache) { cache.set(obj, newObj); } return newObj; } - -require('dotenv').config(); - -describe('OcrccBot', function () { - beforeEach(function () { - _matrixJsSdk.createClient.mockClear(); - - _matrixJsSdk.mockInitCrypto.mockClear(); - - _matrixJsSdk.mockStartClient.mockClear(); - - _matrixJsSdk.mockRegisterRequest.mockClear(); - - _matrixJsSdk.mockSetPowerLevel.mockClear(); - - _matrixJsSdk.mockCreateRoom.mockClear(); - - _matrixJsSdk.mockLeave.mockClear(); - - _matrixJsSdk.mockDeactivateAccount.mockClear(); - - _matrixJsSdk.mockStopClient.mockClear(); - - _matrixJsSdk.mockClearStores.mockClear(); - - _matrixJsSdk.mockOnce.mockClear(); - - _matrixJsSdk.mockOn.mockClear(); - - _matrixJsSdk.mockLogin.mockClear(); - - _matrixJsSdk.mockGetDevices.mockClear(); - - _matrixJsSdk.mockGetDeviceId.mockClear(); - - _matrixJsSdk.mockDeleteMultipleDevices.mockClear(); - - _matrixJsSdk.mockGetJoinedRooms.mockClear(); - - _matrixJsSdk.mockSetDeviceVerified.mockClear(); - - _matrixJsSdk.mockInvite.mockClear(); - - _matrixJsSdk.mockKick.mockClear(); - - _matrixJsSdk.mockGetJoinedRoomMembers.mockClear(); - - _matrixJsSdk.mockGetUser.mockClear(); - }); - test('constructor should inititialize matrix client', function () { - var bot = new _bot["default"](); - expect(_matrixJsSdk.createClient).toHaveBeenCalledWith(process.env.MATRIX_SERVER_URL); - expect(bot.joinedRooms).toEqual([]); - expect(bot.awaitingFacilitator).toEqual({}); - expect(bot.activeChatrooms).toEqual({}); - }); - test('#createLocalStorage should have correct storage location', function () { - var bot = new _bot["default"](); - var localStorage = bot.createLocalStorage(); - var localStoragePath = path.resolve(path.join(os.homedir(), ".local-storage", "matrix-chatbot-".concat(process.env.BOT_USERNAME))); - expect(localStorage._location).toBe(localStoragePath); - }); - test('#sendMessage should send a text message', function () { - var bot = new _bot["default"](); - bot.start(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockStartClient).toHaveBeenCalled(); - }); - var testRoom = 'room_id_1234'; - var testMsg = 'test message'; - bot.sendMessage(testRoom, testMsg); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockSetDeviceVerified).toHaveBeenCalledTimes(2); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockSendTextMessage).toHaveBeenCalledWith(testRoom, testMsg); - }); - }); - test('#inviteUserToRoom should add member to room and retry on rate limit error', function () { - var bot = new _bot["default"](); - bot.start(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockStartClient).toHaveBeenCalled(); - }); - bot.inviteUserToRoom(bot.client, 'room_id_1234', process.env.BOT_USERNAME); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockInvite).toHaveBeenCalledTimes(2); - }); - }); - test('#kickUserFromRoom should remove member from room and retry on rate limit error', function () { - var bot = new _bot["default"](); - bot.start(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockStartClient).toHaveBeenCalled(); - }); - bot.kickUserFromRoom(bot.client, 'room_id_1234', process.env.BOT_USERNAME); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockKick).toHaveBeenCalledTimes(2); - }); - }); - test('#inviteFacilitators should invite all members from Facilitator room', function () { - var bot = new _bot["default"](); - bot.start(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockStartClient).toHaveBeenCalled(); - }); - bot.inviteFacilitators(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetJoinedRoomMembers).toHaveBeenCalledWith(process.env.FACILITATOR_ROOM_ID); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetUser).toHaveBeenCalledTimes(2); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockInvite).toHaveBeenCalledTimes(2); - }); - }); - test('#uninviteFacilitators should remove all members that have not accepted the invite', function () { - var bot = new _bot["default"](); - bot.start(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockStartClient).toHaveBeenCalled(); - }); - bot.uninviteFacilitators(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetJoinedRoomMembers).toHaveBeenCalledWith(process.env.FACILITATOR_ROOM_ID); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetJoinedRoomMembers).toHaveBeenCalledWith('room_id_1234'); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockKick).toHaveBeenCalled(); - }); - }); - test('#handleBotCrash should notify rooms', function () {}); - test('#writeToTranscript should parse event and write to transcript file', function () {}); - test('#deleteOldDevices should delete old sessions', function () {}); // TODO test listeners for membership events and message events - - test('#start should start bot and set up listeners', function () { - var bot = new _bot["default"](); - bot.start(); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockLogin).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.WebStorageSessionStore).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.createClient).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetDevices).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetDeviceId).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockDeleteMultipleDevices).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockInitCrypto).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockGetJoinedRooms).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockOn).toHaveBeenCalled(); - }); - (0, _waitForExpect["default"])(function () { - expect(_matrixJsSdk.mockStartClient).toHaveBeenCalled(); - }); - }); -}); \ No newline at end of file diff --git a/package.json b/package.json index 1efd429..2b6ab53 100644 --- a/package.json +++ b/package.json @@ -30,5 +30,8 @@ "jest-cli": "^25.1.0", "nodemon": "^2.0.2", "wait-for-expect": "^3.0.2" + }, + "jest": { + "testPathIgnorePatterns": ["dist"] } } diff --git a/src/bot.js b/src/bot.js index a92322e..2ed314b 100644 --- a/src/bot.js +++ b/src/bot.js @@ -198,14 +198,15 @@ class OcrccBot { } deleteOldDevices() { - return this.client.getDevices().then(data => { - const currentDeviceId = this.client.getDeviceId(); - const allDeviceIds = data.devices.map(d => d.device_id); - const oldDevices = allDeviceIds.filter(id => id !== currentDeviceId); - logger.log("info", `DELETING OLD DEVICES: ${oldDevices}`); - this.client - .deleteMultipleDevices(oldDevices) - .catch(err => { + const doDelete = (oldDevices, auth=null, retries=0) => { + if (retries > MAX_RETRIES) { + throw new Error("Exceeded max retries deleting old devices") + } + logger.log("info", `ATTEMPTING TO DELETE OLD DEVICES: ${oldDevices}`); + this.client.deleteMultipleDevices(oldDevices, auth) + .then(() => logger.log("info", "DELETED OLD DEVICES")) + .catch(err => { + if (err['errcode'] === undefined && err['data']) { const auth = { session: err.data.session, type: "m.login.password", @@ -213,23 +214,67 @@ class OcrccBot { identifier: { type: "m.id.user", user: process.env.BOT_USERID }, password: process.env.BOT_PASSWORD }; - this.client - .deleteMultipleDevices(oldDevices, auth) - .then(() => logger.log("info", "DELETED OLD DEVICES")) - .catch(err => - // TODO: catch rate limiting error and retry - // if (err.errcode === "M_LIMIT_EXCEEDED") { - // setTimeout(err.retry_after_ms) - // } - logger.log( - "error", - `ERROR DELETING OLD DEVICES: ${JSON.stringify(err.data)}` - ) - ); + + doDelete(oldDevices, auth) + } else if (err['errcode'] === 'M_LIMIT_EXCEEDED') { + const retryCount = retries + 1 + const delay = err['retry_after_ms'] ? err['retry_after_ms'] : retryCount * 1000 + logger.log("error", `RATE LIMIT EXCEEDED, RETRYING IN ${delay} MS`); + setTimeout(() => { + doDelete(oldDevices, auth, retryCount) + }, delay) + } else { + logger.log("error", `ERROR DELETING OLD DEVICES ON RETRY ${retries}: ${JSON.stringify(err)}`) + doDelete(oldDevices, auth, retries + 1) + } + }) + } + + return this.client.getDevices() + .then(data => { + const currentDeviceId = this.client.getDeviceId(); + const allDeviceIds = data.devices.map(d => d.device_id); + const oldDevices = allDeviceIds.filter(id => id !== currentDeviceId); + doDelete(oldDevices) + }) + .catch(err => { + this.handleBotCrash(undefined, err); + logger.log( + "error", + `ERROR DELETING OLD DEVICES: ${JSON.stringify(err.data)}` + ) }); - }); } + // deleteOldDevices() { + // return this.client.getDevices().then(data => { + // const currentDeviceId = this.client.getDeviceId(); + // const allDeviceIds = data.devices.map(d => d.device_id); + // const oldDevices = allDeviceIds.filter(id => id !== currentDeviceId); + // logger.log("info", `DELETING OLD DEVICES: ${oldDevices}`); + // this.client + // .deleteMultipleDevices(oldDevices) + // .catch(err => { + // const auth = { + // session: err.data.session, + // type: "m.login.password", + // user: process.env.BOT_USERID, + // identifier: { type: "m.id.user", user: process.env.BOT_USERID }, + // password: process.env.BOT_PASSWORD + // }; + // this.client + // .deleteMultipleDevices(oldDevices, auth) + // .then(() => logger.log("info", "DELETED OLD DEVICES")) + // .catch(err => + // logger.log( + // "error", + // `ERROR DELETING OLD DEVICES: ${JSON.stringify(err.data)}` + // ) + // ); + // }); + // }); + // } + setMembershipListeners() { // Automatically accept all room invitations return this.client.on("RoomMember.membership", (event, member) => { diff --git a/src/bot.test.js b/src/bot.test.js index 088acc3..3ed056e 100644 --- a/src/bot.test.js +++ b/src/bot.test.js @@ -35,8 +35,11 @@ import { import OcrccBot from './bot' -describe('OcrccBot', () => { +const mockAppendFileSync = jest.fn() +fs.appendFileSync = mockAppendFileSync + +describe('OcrccBot', () => { beforeEach(() => { createClient.mockClear() mockInitCrypto.mockClear() @@ -61,6 +64,7 @@ describe('OcrccBot', () => { mockGetJoinedRoomMembers.mockClear() mockGetUser.mockClear() mockSendTextMessage.mockClear() + mockAppendFileSync.mockClear() }) test('constructor should inititialize matrix client', () => { @@ -196,11 +200,10 @@ describe('OcrccBot', () => { }) test('#writeToTranscript should parse event and write to transcript file', () => { - const appendFileSyncSpy = jest.spyOn(fs, 'appendFileSync') const bot = new OcrccBot() bot.start() - bot.activeChatrooms['test_room_id'] = { transcriptFile: 'test filepath' } + bot.activeChatrooms['test_room_id'] = { transcriptFile: '__mocks__/test_transcript.txt' } waitForExpect(() => { expect(mockStartClient).toHaveBeenCalled() @@ -216,7 +219,7 @@ describe('OcrccBot', () => { bot.writeToTranscript(mockEvent) waitForExpect(() => { - expect(appendFileSyncSpy).toHaveBeenCalledWith('test filepath', 'test_sender [00:00:00]: test content', 'utf8') + expect(mockAppendFileSync).toHaveBeenCalledWith('__mocks__/test_transcript.txt', 'test_sender [00:00:00]: test content', 'utf8') }) })