From 537e97be73bc4aec2bbdbef78726a8d5746b286c Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Thu, 20 Aug 2020 14:05:50 +0100 Subject: [PATCH 1/2] [misc] OError.tag all the errors in async contexts See the docs of OError.tag: https://github.com/overleaf/o-error#long-stack-traces-with-oerrortag (currently at 221dd902e7bfa0ee92de1ea5a3cbf3152c3ceeb4) I am tagging all errors at each async hop. Most of the controller code will only ever see already tagged errors -- or new errors created in our app code. They should have enough info that we do not need to tag them again. --- services/real-time/app/js/ChannelManager.js | 3 ++ .../real-time/app/js/ConnectedUsersManager.js | 34 +++++++------ .../app/js/DocumentUpdaterManager.js | 20 ++++---- services/real-time/app/js/RoomManager.js | 5 ++ services/real-time/app/js/SessionSockets.js | 4 ++ services/real-time/app/js/WebApiManager.js | 2 + .../real-time/app/js/WebsocketController.js | 49 ++++++------------- .../test/unit/js/WebsocketControllerTests.js | 4 +- 8 files changed, 63 insertions(+), 58 deletions(-) diff --git a/services/real-time/app/js/ChannelManager.js b/services/real-time/app/js/ChannelManager.js index e84cfe44a9..da0490ff9a 100644 --- a/services/real-time/app/js/ChannelManager.js +++ b/services/real-time/app/js/ChannelManager.js @@ -1,6 +1,7 @@ const logger = require('logger-sharelatex') const metrics = require('metrics-sharelatex') const settings = require('settings-sharelatex') +const OError = require('@overleaf/o-error') const ClientMap = new Map() // for each redis client, store a Map of subscribed channels (channelname -> subscribe promise) @@ -35,6 +36,8 @@ module.exports = { .catch(function (err) { logger.error({ channel, err }, 'failed to subscribe to channel') metrics.inc(`subscribe.failed.${baseChannel}`) + // add context for the stack-trace at the call-site + OError.tag(err, 'failed to subscribe to channel', { channel }) }) return p } diff --git a/services/real-time/app/js/ConnectedUsersManager.js b/services/real-time/app/js/ConnectedUsersManager.js index 06ea442d63..340d0706fd 100644 --- a/services/real-time/app/js/ConnectedUsersManager.js +++ b/services/real-time/app/js/ConnectedUsersManager.js @@ -5,6 +5,7 @@ const async = require('async') const Settings = require('settings-sharelatex') const logger = require('logger-sharelatex') const redis = require('redis-sharelatex') +const OError = require('@overleaf/o-error') const rclient = redis.createClient(Settings.redis.realtime) const Keys = Settings.redis.realtime.key_schema @@ -67,10 +68,7 @@ module.exports = { multi.exec(function (err) { if (err) { - logger.err( - { err, project_id, client_id }, - 'problem marking user as connected' - ) + OError.tag(err, 'problem marking user as connected') } callback(err) }) @@ -104,7 +102,12 @@ module.exports = { multi.srem(Keys.clientsInProject({ project_id }), client_id) multi.expire(Keys.clientsInProject({ project_id }), FOUR_DAYS_IN_S) multi.del(Keys.connectedUser({ project_id, client_id })) - multi.exec(callback) + multi.exec(function (err) { + if (err) { + OError.tag(err, 'problem marking user as disconnected') + } + callback(err) + }) }, _getConnectedUser(project_id, client_id, callback) { @@ -112,6 +115,12 @@ module.exports = { err, result ) { + if (err) { + OError.tag(err, 'problem fetching connected user details', { + other_client_id: client_id + }) + return callback(err) + } if (!(result && result.user_id)) { result = { connected: false, @@ -126,15 +135,10 @@ module.exports = { try { result.cursorData = JSON.parse(result.cursorData) } catch (e) { - logger.error( - { - err: e, - project_id, - client_id, - cursorData: result.cursorData - }, - 'error parsing cursorData JSON' - ) + OError.tag(e, 'error parsing cursorData JSON', { + other_client_id: client_id, + cursorData: result.cursorData + }) return callback(e) } } @@ -150,6 +154,7 @@ module.exports = { results ) { if (err) { + OError.tag(err, 'problem getting clients in project') return callback(err) } const jobs = results.map((client_id) => (cb) => @@ -157,6 +162,7 @@ module.exports = { ) async.series(jobs, function (err, users) { if (err) { + OError.tag(err, 'problem getting connected users') return callback(err) } users = users.filter( diff --git a/services/real-time/app/js/DocumentUpdaterManager.js b/services/real-time/app/js/DocumentUpdaterManager.js index 3fd09d7b1d..587b6f959d 100644 --- a/services/real-time/app/js/DocumentUpdaterManager.js +++ b/services/real-time/app/js/DocumentUpdaterManager.js @@ -3,6 +3,7 @@ */ const request = require('request') const _ = require('underscore') +const OError = require('@overleaf/o-error') const logger = require('logger-sharelatex') const settings = require('settings-sharelatex') const metrics = require('metrics-sharelatex') @@ -23,10 +24,7 @@ const DocumentUpdaterManager = { request.get(url, function (err, res, body) { timer.done() if (err) { - logger.error( - { err, url, project_id, doc_id }, - 'error getting doc from doc updater' - ) + OError.tag(err, 'error getting doc from doc updater') return callback(err) } if (res.statusCode >= 200 && res.statusCode < 300) { @@ -37,6 +35,7 @@ const DocumentUpdaterManager = { try { body = JSON.parse(body) } catch (error) { + OError.tag(error, 'error parsing doc updater response') return callback(error) } body = body || {} @@ -79,10 +78,7 @@ const DocumentUpdaterManager = { request.del(url, function (err, res) { timer.done() if (err) { - logger.error( - { err, project_id }, - 'error deleting project from document updater' - ) + OError.tag(err, 'error deleting project from document updater') callback(err) } else if (res.statusCode >= 200 && res.statusCode < 300) { logger.log({ project_id }, 'deleted project from document updater') @@ -140,9 +136,15 @@ const DocumentUpdaterManager = { error ) { if (error) { + OError.tag(error, 'error pushing update into redis') return callback(error) } - rclient.rpush('pending-updates-list', doc_key, callback) + rclient.rpush('pending-updates-list', doc_key, function (error) { + if (error) { + OError.tag(error, 'error pushing doc_id into redis') + } + callback(error) + }) }) } } diff --git a/services/real-time/app/js/RoomManager.js b/services/real-time/app/js/RoomManager.js index 81827e5e9a..549975843e 100644 --- a/services/real-time/app/js/RoomManager.js +++ b/services/real-time/app/js/RoomManager.js @@ -4,6 +4,7 @@ const logger = require('logger-sharelatex') const metrics = require('metrics-sharelatex') const { EventEmitter } = require('events') +const OError = require('@overleaf/o-error') const IdMap = new Map() // keep track of whether ids are from projects or docs const RoomEvents = new EventEmitter() // emits {project,doc}-active and {project,doc}-empty events @@ -65,6 +66,10 @@ module.exports = { logger.log({ entity, id }, 'room is now active') RoomEvents.once(`${entity}-subscribed-${id}`, function (err) { // only allow the client to join when all the relevant channels have subscribed + if (err) { + OError.tag(err, 'error joining', { entity, id }) + return callback(err) + } logger.log( { client: client.id, entity, id, beforeCount }, 'client joined new room and subscribed to channel' diff --git a/services/real-time/app/js/SessionSockets.js b/services/real-time/app/js/SessionSockets.js index 4ade959829..2edb48bb6e 100644 --- a/services/real-time/app/js/SessionSockets.js +++ b/services/real-time/app/js/SessionSockets.js @@ -1,3 +1,4 @@ +const OError = require('@overleaf/o-error') const { EventEmitter } = require('events') module.exports = function (io, sessionStore, cookieParser, cookieName) { @@ -17,6 +18,9 @@ module.exports = function (io, sessionStore, cookieParser, cookieName) { } sessionStore.get(sessionId, function (error, session) { if (error) { + OError.tag(error, 'error getting session from sessionStore', { + sessionId + }) return next(error, socket) } if (!session) { diff --git a/services/real-time/app/js/WebApiManager.js b/services/real-time/app/js/WebApiManager.js index 62020a98ab..79b0937ad5 100644 --- a/services/real-time/app/js/WebApiManager.js +++ b/services/real-time/app/js/WebApiManager.js @@ -2,6 +2,7 @@ camelcase, */ const request = require('request') +const OError = require('@overleaf/o-error') const settings = require('settings-sharelatex') const logger = require('logger-sharelatex') const { CodedError } = require('./Errors') @@ -30,6 +31,7 @@ module.exports = { }, function (error, response, data) { if (error) { + OError.tag(error, 'join project request failed') return callback(error) } let err diff --git a/services/real-time/app/js/WebsocketController.js b/services/real-time/app/js/WebsocketController.js index 8867320dbe..7a9233b6d2 100644 --- a/services/real-time/app/js/WebsocketController.js +++ b/services/real-time/app/js/WebsocketController.js @@ -1,6 +1,7 @@ /* eslint-disable camelcase, */ +const OError = require('@overleaf/o-error') const logger = require('logger-sharelatex') const metrics = require('metrics-sharelatex') const WebApiManager = require('./WebApiManager') @@ -91,7 +92,14 @@ module.exports = WebsocketController = { client.publicId, user, null, - function () {} + function (err) { + if (err) { + logger.warn( + { err, project_id, user_id, client_id: client.id }, + 'background cursor update failed' + ) + } + } ) }) }, @@ -229,17 +237,7 @@ module.exports = WebsocketController = { try { line = encodeForWebsockets(line) } catch (err) { - logger.err( - { - err, - project_id, - doc_id, - fromVersion, - line, - client_id: client.id - }, - 'error encoding line uri component' - ) + OError.tag(err, 'error encoding line uri component', { line }) return callback(err) } escapedLines.push(line) @@ -260,17 +258,9 @@ module.exports = WebsocketController = { } } } catch (err) { - logger.err( - { - err, - project_id, - doc_id, - fromVersion, - ranges, - client_id: client.id - }, - 'error encoding range uri component' - ) + OError.tag(err, 'error encoding range uri component', { + ranges + }) return callback(err) } } @@ -538,16 +528,9 @@ module.exports = WebsocketController = { } if (error) { - logger.error( - { - err: error, - project_id, - doc_id, - client_id: client.id, - version: update.v - }, - 'document was not available for update' - ) + OError.tag(error, 'document was not available for update', { + version: update.v + }) client.disconnect() } callback(error) diff --git a/services/real-time/test/unit/js/WebsocketControllerTests.js b/services/real-time/test/unit/js/WebsocketControllerTests.js index 515d407cc2..1d363123a7 100644 --- a/services/real-time/test/unit/js/WebsocketControllerTests.js +++ b/services/real-time/test/unit/js/WebsocketControllerTests.js @@ -1464,8 +1464,8 @@ describe('WebsocketController', function () { return this.client.disconnect.called.should.equal(true) }) - it('should log an error', function () { - return this.logger.error.called.should.equal(true) + it('should not log an error', function () { + return this.logger.error.called.should.equal(false) }) return it('should call the callback with the error', function () { From ee3d3b09ed72f1f78d4aaea29b3448d080b30a3f Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Fri, 21 Aug 2020 12:15:35 +0100 Subject: [PATCH 2/2] [misc] wrap redis errors as tagging does not work with them ioredis may reuse the error instance for multiple callbacks. E.g. when the connection to redis fails, the queue is flushed with the same MaxRetriesPerRequestError instance. --- services/real-time/app/js/ChannelManager.js | 18 ++++++++++-------- .../real-time/app/js/ConnectedUsersManager.js | 10 +++++----- .../real-time/app/js/DocumentUpdaterManager.js | 4 ++-- .../test/unit/js/ChannelManagerTests.js | 3 ++- 4 files changed, 19 insertions(+), 16 deletions(-) diff --git a/services/real-time/app/js/ChannelManager.js b/services/real-time/app/js/ChannelManager.js index da0490ff9a..8e2bb57863 100644 --- a/services/real-time/app/js/ChannelManager.js +++ b/services/real-time/app/js/ChannelManager.js @@ -23,12 +23,13 @@ module.exports = { const channel = `${baseChannel}:${id}` const actualSubscribe = function () { // subscribe is happening in the foreground and it should reject - const p = rclient.subscribe(channel) - p.finally(function () { - if (clientChannelMap.get(channel) === subscribePromise) { - clientChannelMap.delete(channel) - } - }) + return rclient + .subscribe(channel) + .finally(function () { + if (clientChannelMap.get(channel) === subscribePromise) { + clientChannelMap.delete(channel) + } + }) .then(function () { logger.log({ channel }, 'subscribed to channel') metrics.inc(`subscribe.${baseChannel}`) @@ -37,9 +38,10 @@ module.exports = { logger.error({ channel, err }, 'failed to subscribe to channel') metrics.inc(`subscribe.failed.${baseChannel}`) // add context for the stack-trace at the call-site - OError.tag(err, 'failed to subscribe to channel', { channel }) + throw new OError('failed to subscribe to channel', { + channel + }).withCause(err) }) - return p } const pendingActions = clientChannelMap.get(channel) || Promise.resolve() diff --git a/services/real-time/app/js/ConnectedUsersManager.js b/services/real-time/app/js/ConnectedUsersManager.js index 340d0706fd..ed37db1ef6 100644 --- a/services/real-time/app/js/ConnectedUsersManager.js +++ b/services/real-time/app/js/ConnectedUsersManager.js @@ -68,7 +68,7 @@ module.exports = { multi.exec(function (err) { if (err) { - OError.tag(err, 'problem marking user as connected') + err = new OError('problem marking user as connected').withCause(err) } callback(err) }) @@ -104,7 +104,7 @@ module.exports = { multi.del(Keys.connectedUser({ project_id, client_id })) multi.exec(function (err) { if (err) { - OError.tag(err, 'problem marking user as disconnected') + err = new OError('problem marking user as disconnected').withCause(err) } callback(err) }) @@ -116,9 +116,9 @@ module.exports = { result ) { if (err) { - OError.tag(err, 'problem fetching connected user details', { + err = new OError('problem fetching connected user details', { other_client_id: client_id - }) + }).withCause(err) return callback(err) } if (!(result && result.user_id)) { @@ -154,7 +154,7 @@ module.exports = { results ) { if (err) { - OError.tag(err, 'problem getting clients in project') + err = new OError('problem getting clients in project').withCause(err) return callback(err) } const jobs = results.map((client_id) => (cb) => diff --git a/services/real-time/app/js/DocumentUpdaterManager.js b/services/real-time/app/js/DocumentUpdaterManager.js index 587b6f959d..2d7f2890c6 100644 --- a/services/real-time/app/js/DocumentUpdaterManager.js +++ b/services/real-time/app/js/DocumentUpdaterManager.js @@ -136,12 +136,12 @@ const DocumentUpdaterManager = { error ) { if (error) { - OError.tag(error, 'error pushing update into redis') + error = new OError('error pushing update into redis').withCause(error) return callback(error) } rclient.rpush('pending-updates-list', doc_key, function (error) { if (error) { - OError.tag(error, 'error pushing doc_id into redis') + error = new OError('error pushing doc_id into redis').withCause(error) } callback(error) }) diff --git a/services/real-time/test/unit/js/ChannelManagerTests.js b/services/real-time/test/unit/js/ChannelManagerTests.js index 6026f6ab5c..95e9000a49 100644 --- a/services/real-time/test/unit/js/ChannelManagerTests.js +++ b/services/real-time/test/unit/js/ChannelManagerTests.js @@ -91,7 +91,8 @@ describe('ChannelManager', function () { ) p.then(() => done(new Error('should not subscribe but fail'))).catch( (err) => { - err.message.should.equal('some redis error') + err.message.should.equal('failed to subscribe to channel') + err.cause.message.should.equal('some redis error') this.ChannelManager.getClientMapEntry(this.rclient) .has('applied-ops:1234567890abcdef') .should.equal(false)