From 537e97be73bc4aec2bbdbef78726a8d5746b286c Mon Sep 17 00:00:00 2001 From: Jakob Ackermann Date: Thu, 20 Aug 2020 14:05:50 +0100 Subject: [PATCH] [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 () {