From 618cf995488897bc2ce71c81346ce04b8580a579 Mon Sep 17 00:00:00 2001 From: Brian Gough Date: Tue, 14 Sep 2021 09:36:24 +0100 Subject: [PATCH] Merge pull request #4950 from overleaf/bg-realtime-log-relevelling realtime log re-levelling GitOrigin-RevId: 81d86ba648e7fc1436b638b67371b35fd831a62f --- services/real-time/app.js | 26 ++++++------ services/real-time/app/js/ChannelManager.js | 8 ++-- .../real-time/app/js/ConnectedUsersManager.js | 9 ++-- .../real-time/app/js/DeploymentManager.js | 6 +-- .../app/js/DocumentUpdaterController.js | 10 ++--- .../app/js/DocumentUpdaterManager.js | 8 ++-- services/real-time/app/js/DrainManager.js | 6 +-- services/real-time/app/js/EventLogger.js | 2 +- .../real-time/app/js/HttpApiController.js | 8 ++-- .../real-time/app/js/RedisClientManager.js | 2 +- services/real-time/app/js/RoomManager.js | 14 +++---- services/real-time/app/js/Router.js | 22 ++++++++-- services/real-time/app/js/WebApiManager.js | 2 +- .../app/js/WebsocketAddressManager.js | 30 +++++++++++++ .../real-time/app/js/WebsocketController.js | 42 +++++++++++++------ .../real-time/app/js/WebsocketLoadBalancer.js | 8 ++-- .../real-time/config/settings.defaults.js | 3 ++ services/real-time/package-lock.json | 14 +++---- services/real-time/package.json | 1 + .../test/acceptance/js/LeaveDocTests.js | 6 +-- .../acceptance/js/helpers/RealtimeServer.js | 2 +- .../test/unit/js/DrainManagerTests.js | 2 +- 22 files changed, 150 insertions(+), 81 deletions(-) create mode 100644 services/real-time/app/js/WebsocketAddressManager.js diff --git a/services/real-time/app.js b/services/real-time/app.js index 31216bb07e..902b5debcb 100644 --- a/services/real-time/app.js +++ b/services/real-time/app.js @@ -27,10 +27,10 @@ const DeploymentManager = require('./app/js/DeploymentManager') // NOTE: debug is invoked for every blob that is put on the wire const socketIoLogger = { error(...message) { - logger.info({ fromSocketIo: true, originalLevel: 'error' }, ...message) + logger.debug({ fromSocketIo: true, originalLevel: 'error' }, ...message) }, warn(...message) { - logger.info({ fromSocketIo: true, originalLevel: 'warn' }, ...message) + logger.debug({ fromSocketIo: true, originalLevel: 'warn' }, ...message) }, info() {}, debug() {}, @@ -60,7 +60,6 @@ const sessionSockets = new SessionSockets( ) Metrics.injectMetricsRoute(app) -app.use(Metrics.http.monitor(logger)) io.configure(function () { io.enable('browser client minification') @@ -102,7 +101,7 @@ app.get('/status', function (req, res) { app.get('/debug/events', function (req, res) { Settings.debugEvents = parseInt(req.query.count, 10) || 20 - logger.log({ count: Settings.debugEvents }, 'starting debug mode') + logger.info({ count: Settings.debugEvents }, 'starting debug mode') res.send(`debug mode will log next ${Settings.debugEvents} events`) }) @@ -137,6 +136,9 @@ app.get( app.get('/health_check/redis', healthCheck) +// log http requests for routes defined from this point onwards +app.use(Metrics.http.monitor(logger)) + const Router = require('./app/js/Router') Router.configure(app, io, sessionSockets) @@ -162,10 +164,10 @@ Error.stackTraceLimit = 10 function shutdownCleanly(signal) { const connectedClients = io.sockets.clients().length if (connectedClients === 0) { - logger.warn('no clients connected, exiting') + logger.info('no clients connected, exiting') process.exit() } else { - logger.warn( + logger.info( { connectedClients }, 'clients still connected, not shutting down yet' ) @@ -175,18 +177,18 @@ function shutdownCleanly(signal) { function drainAndShutdown(signal) { if (Settings.shutDownInProgress) { - logger.warn({ signal }, 'shutdown already in progress, ignoring signal') + logger.info({ signal }, 'shutdown already in progress, ignoring signal') } else { Settings.shutDownInProgress = true const { statusCheckInterval } = Settings if (statusCheckInterval) { - logger.warn( + logger.info( { signal }, `received interrupt, delay drain by ${statusCheckInterval}ms` ) } setTimeout(function () { - logger.warn( + logger.info( { signal }, `received interrupt, starting drain over ${shutdownDrainTimeWindow} mins` ) @@ -194,7 +196,7 @@ function drainAndShutdown(signal) { setTimeout(() => { const staleClients = io.sockets.clients() if (staleClients.length !== 0) { - logger.warn( + logger.info( { staleClients: staleClients.map(client => client.id) }, 'forcefully disconnecting stale clients' ) @@ -214,7 +216,7 @@ function drainAndShutdown(signal) { Settings.shutDownInProgress = false const shutdownDrainTimeWindow = parseInt(Settings.shutdownDrainTimeWindow, 10) if (Settings.shutdownDrainTimeWindow) { - logger.log({ shutdownDrainTimeWindow }, 'shutdownDrainTimeWindow enabled') + logger.info({ shutdownDrainTimeWindow }, 'shutdownDrainTimeWindow enabled') for (const signal of [ 'SIGINT', 'SIGHUP', @@ -255,7 +257,7 @@ if (Settings.shutdownDrainTimeWindow) { } if (Settings.continualPubsubTraffic) { - logger.warn('continualPubsubTraffic enabled') + logger.debug('continualPubsubTraffic enabled') const pubsubClient = redis.createClient(Settings.redis.pubsub) const clusterClient = redis.createClient(Settings.redis.websessions) diff --git a/services/real-time/app/js/ChannelManager.js b/services/real-time/app/js/ChannelManager.js index 81caa7dd83..ffc01cc015 100644 --- a/services/real-time/app/js/ChannelManager.js +++ b/services/real-time/app/js/ChannelManager.js @@ -31,7 +31,7 @@ module.exports = { } }) .then(function () { - logger.log({ channel }, 'subscribed to channel') + logger.debug({ channel }, 'subscribed to channel') metrics.inc(`subscribe.${baseChannel}`) }) .catch(function (err) { @@ -50,7 +50,7 @@ module.exports = { actualSubscribe ) clientChannelMap.set(channel, subscribePromise) - logger.log({ channel }, 'planned to subscribe to channel') + logger.debug({ channel }, 'planned to subscribe to channel') return subscribePromise }, @@ -67,7 +67,7 @@ module.exports = { } }) .then(function () { - logger.log({ channel }, 'unsubscribed from channel') + logger.debug({ channel }, 'unsubscribed from channel') metrics.inc(`unsubscribe.${baseChannel}`) }) .catch(function (err) { @@ -82,7 +82,7 @@ module.exports = { actualUnsubscribe ) clientChannelMap.set(channel, unsubscribePromise) - logger.log({ channel }, 'planned to unsubscribe from channel') + logger.debug({ channel }, 'planned to unsubscribe from channel') return unsubscribePromise }, diff --git a/services/real-time/app/js/ConnectedUsersManager.js b/services/real-time/app/js/ConnectedUsersManager.js index f8dd40fd6a..ac346a1f14 100644 --- a/services/real-time/app/js/ConnectedUsersManager.js +++ b/services/real-time/app/js/ConnectedUsersManager.js @@ -21,7 +21,10 @@ module.exports = { // update. This way we don't care if the connected_user key has expired when // we receive a cursor update. updateUserPosition(project_id, client_id, user, cursorData, callback) { - logger.log({ project_id, client_id }, 'marking user as joined or connected') + logger.debug( + { project_id, client_id }, + 'marking user as joined or connected' + ) const multi = rclient.multi() @@ -75,7 +78,7 @@ module.exports = { }, refreshClient(project_id, client_id) { - logger.log({ project_id, client_id }, 'refreshing connected client') + logger.debug({ project_id, client_id }, 'refreshing connected client') const multi = rclient.multi() multi.hset( Keys.connectedUser({ project_id, client_id }), @@ -97,7 +100,7 @@ module.exports = { }, markUserAsDisconnected(project_id, client_id, callback) { - logger.log({ project_id, client_id }, 'marking user as disconnected') + logger.debug({ project_id, client_id }, 'marking user as disconnected') const multi = rclient.multi() multi.srem(Keys.clientsInProject({ project_id }), client_id) multi.expire(Keys.clientsInProject({ project_id }), FOUR_DAYS_IN_S) diff --git a/services/real-time/app/js/DeploymentManager.js b/services/real-time/app/js/DeploymentManager.js index 0e6b2a7f05..6f778fbd02 100644 --- a/services/real-time/app/js/DeploymentManager.js +++ b/services/real-time/app/js/DeploymentManager.js @@ -16,10 +16,10 @@ function updateDeploymentStatus(fileContent) { if (closed && !settings.serviceIsClosed) { settings.serviceIsClosed = true serviceCloseTime = Date.now() + 60 * 1000 // delay closing by 1 minute - logger.warn({ fileContent }, 'closing service') + logger.info({ fileContent }, 'closing service') } else if (!closed && settings.serviceIsClosed) { settings.serviceIsClosed = false - logger.warn({ fileContent }, 'opening service') + logger.info({ fileContent }, 'opening service') } } @@ -45,7 +45,7 @@ function checkStatusFileSync() { module.exports = { initialise() { if (statusFile && deploymentColour) { - logger.log( + logger.info( { statusFile, deploymentColour, interval: FILE_CHECK_INTERVAL }, 'monitoring deployment status file' ) diff --git a/services/real-time/app/js/DocumentUpdaterController.js b/services/real-time/app/js/DocumentUpdaterController.js index 290882c41f..d4dcda5ccf 100644 --- a/services/real-time/app/js/DocumentUpdaterController.js +++ b/services/real-time/app/js/DocumentUpdaterController.js @@ -18,7 +18,7 @@ module.exports = DocumentUpdaterController = { rclientList: RedisClientManager.createClientList(settings.redis.pubsub), listenForUpdatesFromDocumentUpdater(io) { - logger.log( + logger.debug( { rclients: this.rclientList.length }, 'listening for applied-ops events' ) @@ -112,7 +112,7 @@ module.exports = DocumentUpdaterController = { return } // send updates to clients - logger.log( + logger.debug( { doc_id, version: update.v, @@ -127,7 +127,7 @@ module.exports = DocumentUpdaterController = { if (!seen[client.id]) { seen[client.id] = true if (client.publicId === update.meta.source) { - logger.log( + logger.debug( { doc_id, version: update.v, @@ -138,7 +138,7 @@ module.exports = DocumentUpdaterController = { client.emit('otUpdateApplied', { v: update.v, doc: update.doc }) } else if (!update.dup) { // Duplicate ops should just be sent back to sending client for acknowledgement - logger.log( + logger.debug( { doc_id, version: update.v, @@ -153,7 +153,7 @@ module.exports = DocumentUpdaterController = { } if (Object.keys(seen).length < clientList.length) { metrics.inc('socket-io.duplicate-clients', 0.1) - logger.log( + logger.debug( { doc_id, socketIoClients: clientList.map(client => client.id), diff --git a/services/real-time/app/js/DocumentUpdaterManager.js b/services/real-time/app/js/DocumentUpdaterManager.js index 9f01ed73e3..a9bd8acedc 100644 --- a/services/real-time/app/js/DocumentUpdaterManager.js +++ b/services/real-time/app/js/DocumentUpdaterManager.js @@ -23,7 +23,7 @@ const DocumentUpdaterManager = { getDocument(project_id, doc_id, fromVersion, callback) { const timer = new metrics.Timer('get-document') const url = `${settings.apis.documentupdater.url}/project/${project_id}/doc/${doc_id}?fromVersion=${fromVersion}` - logger.log( + logger.debug( { project_id, doc_id, fromVersion }, 'getting doc from document updater' ) @@ -34,7 +34,7 @@ const DocumentUpdaterManager = { return callback(err) } if (res.statusCode >= 200 && res.statusCode < 300) { - logger.log( + logger.debug( { project_id, doc_id }, 'got doc from document document updater' ) @@ -63,7 +63,7 @@ const DocumentUpdaterManager = { flushProjectToMongoAndDelete(project_id, callback) { // this method is called when the last connected user leaves the project - logger.log({ project_id }, 'deleting project from document updater') + logger.debug({ project_id }, 'deleting project from document updater') const timer = new metrics.Timer('delete.mongo.project') // flush the project in the background when all users have left const url = @@ -75,7 +75,7 @@ const DocumentUpdaterManager = { 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') + logger.debug({ project_id }, 'deleted project from document updater') callback(null) } else { callback( diff --git a/services/real-time/app/js/DrainManager.js b/services/real-time/app/js/DrainManager.js index 5f9c192afd..faa82e4206 100644 --- a/services/real-time/app/js/DrainManager.js +++ b/services/real-time/app/js/DrainManager.js @@ -10,7 +10,7 @@ module.exports = { startDrain(io, rate, callback) { // Clear out any old interval clearInterval(this.interval) - logger.log({ rate }, 'starting drain') + logger.info({ rate }, 'starting drain') if (rate === 0) { return } @@ -38,7 +38,7 @@ module.exports = { for (const client of io.sockets.clients()) { if (!this.RECONNECTED_CLIENTS[client.id]) { this.RECONNECTED_CLIENTS[client.id] = true - logger.log( + logger.debug( { client_id: client.id }, 'Asking client to reconnect gracefully' ) @@ -51,7 +51,7 @@ module.exports = { } } if (drainedCount < N) { - logger.log('All clients have been told to reconnectGracefully') + logger.info('All clients have been told to reconnectGracefully') return true } return false diff --git a/services/real-time/app/js/EventLogger.js b/services/real-time/app/js/EventLogger.js index 91f63e143c..973085e32d 100644 --- a/services/real-time/app/js/EventLogger.js +++ b/services/real-time/app/js/EventLogger.js @@ -21,7 +21,7 @@ module.exports = EventLogger = { debugEvent(channel, message) { if (settings.debugEvents > 0) { - logger.log({ channel, message, counter: COUNTER++ }, 'logging event') + logger.info({ channel, message, counter: COUNTER++ }, 'logging event') settings.debugEvents-- } }, diff --git a/services/real-time/app/js/HttpApiController.js b/services/real-time/app/js/HttpApiController.js index 625bbbf739..fdadb96df9 100644 --- a/services/real-time/app/js/HttpApiController.js +++ b/services/real-time/app/js/HttpApiController.js @@ -7,7 +7,7 @@ const logger = require('logger-sharelatex') module.exports = { sendMessage(req, res) { - logger.log({ message: req.params.message }, 'sending message') + logger.debug({ message: req.params.message }, 'sending message') if (Array.isArray(req.body)) { for (const payload of req.body) { WebsocketLoadBalancer.emitToRoom( @@ -30,7 +30,7 @@ module.exports = { const io = req.app.get('io') let rate = req.query.rate || '4' rate = parseFloat(rate) || 0 - logger.log({ rate }, 'setting client drain rate') + logger.info({ rate }, 'setting client drain rate') DrainManager.startDrain(io, rate) res.sendStatus(204) }, @@ -41,11 +41,11 @@ module.exports = { const client = io.sockets.sockets[client_id] if (!client) { - logger.info({ client_id }, 'api: client already disconnected') + logger.debug({ client_id }, 'api: client already disconnected') res.sendStatus(404) return } - logger.warn({ client_id }, 'api: requesting client disconnect') + logger.info({ client_id }, 'api: requesting client disconnect') client.on('disconnect', () => res.sendStatus(204)) client.disconnect() }, diff --git a/services/real-time/app/js/RedisClientManager.js b/services/real-time/app/js/RedisClientManager.js index 226bf91cfd..db7bb6f86e 100644 --- a/services/real-time/app/js/RedisClientManager.js +++ b/services/real-time/app/js/RedisClientManager.js @@ -12,7 +12,7 @@ module.exports = { : x.host ? 'single' : 'unknown' - logger.log({ redis: redisType }, 'creating redis client') + logger.debug({ redis: redisType }, 'creating redis client') return redis.createClient(x) }) }, diff --git a/services/real-time/app/js/RoomManager.js b/services/real-time/app/js/RoomManager.js index e030b60490..f4e9f32cdb 100644 --- a/services/real-time/app/js/RoomManager.js +++ b/services/real-time/app/js/RoomManager.js @@ -39,7 +39,7 @@ module.exports = { // explicitly, and then socket.io will just regard this as a client that // has not joined any rooms and do a final disconnection. const roomsToLeave = this._roomsClientIsIn(client) - logger.log({ client: client.id, roomsToLeave }, 'client leaving project') + logger.debug({ client: client.id, roomsToLeave }, 'client leaving project') for (const id of roomsToLeave) { const entity = IdMap.get(id) this.leaveEntity(client, entity, id) @@ -63,14 +63,14 @@ module.exports = { client.join(id) // is this a new room? if so, subscribe if (beforeCount === 0) { - logger.log({ entity, id }, 'room is now active') + logger.debug({ 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( + logger.debug( { client: client.id, entity, id, beforeCount }, 'client joined new room and subscribed to channel' ) @@ -81,7 +81,7 @@ module.exports = { // keep track of the number of listeners metrics.gauge('room-listeners', RoomEvents.eventNames().length) } else { - logger.log( + logger.debug( { client: client.id, entity, id, beforeCount }, 'client joined existing room' ) @@ -96,7 +96,7 @@ module.exports = { // This can now happen all the time, as we skip the join for clients that // disconnect before joinProject/joinDoc completed. if (!this._clientAlreadyInRoom(client, id)) { - logger.log( + logger.debug( { client: client.id, entity, id }, 'ignoring request from client to leave room it is not in' ) @@ -104,7 +104,7 @@ module.exports = { } client.leave(id) const afterCount = this._clientsInRoom(client, id) - logger.log( + logger.debug( { client: client.id, entity, id, afterCount }, 'client left room' ) @@ -114,7 +114,7 @@ module.exports = { return } if (afterCount === 0) { - logger.log({ entity, id }, 'room is now empty') + logger.debug({ entity, id }, 'room is now empty') RoomEvents.emit(`${entity}-empty`, id) IdMap.delete(id) metrics.gauge('room-listeners', RoomEvents.eventNames().length) diff --git a/services/real-time/app/js/Router.js b/services/real-time/app/js/Router.js index 9a8cd083dc..7458139285 100644 --- a/services/real-time/app/js/Router.js +++ b/services/real-time/app/js/Router.js @@ -7,6 +7,7 @@ const settings = require('@overleaf/settings') const WebsocketController = require('./WebsocketController') const HttpController = require('./HttpController') const HttpApiController = require('./HttpApiController') +const WebsocketAddressManager = require('./WebsocketAddressManager') const bodyParser = require('body-parser') const base64id = require('base64id') const { UnexpectedArgumentsError } = require('./Errors') @@ -41,7 +42,7 @@ module.exports = Router = { attrs.err = error attrs.method = method if (Joi.isError(error)) { - logger.warn(attrs, 'validation error') + logger.info(attrs, 'validation error') var message = 'invalid' try { message = error.details[0].message @@ -59,8 +60,8 @@ module.exports = Router = { const serializedError = { message: error.message, code: error.info.code } callback(serializedError) } else if (error.message === 'unexpected arguments') { - // the payload might be very large, put it on level info - logger.log(attrs, 'unexpected arguments') + // the payload might be very large; put it on level debug + logger.debug(attrs, 'unexpected arguments') metrics.inc('unexpected-arguments', 1, { status: method }) const serializedError = { message: error.message } callback(serializedError) @@ -107,6 +108,15 @@ module.exports = Router = { configure(app, io, session) { app.set('io', io) + + if (settings.behindProxy) { + app.set('trust proxy', settings.trustedProxyIps) + } + const websocketAddressManager = new WebsocketAddressManager( + settings.behindProxy, + settings.trustedProxyIps + ) + app.get('/clients', HttpController.getConnectedClients) app.get('/clients/:client_id', HttpController.getConnectedClient) @@ -180,10 +190,14 @@ module.exports = Router = { client.publicId = 'P.' + base64id.generateId() client.emit('connectionAccepted', null, client.publicId) + client.remoteIp = websocketAddressManager.getRemoteIp(client.handshake) + const headers = client.handshake && client.handshake.headers + client.userAgent = headers && headers['user-agent'] + metrics.inc('socket-io.connection', 1, { status: client.transport }) metrics.gauge('socket-io.clients', io.sockets.clients().length) - logger.log({ session, client_id: client.id }, 'client connected') + logger.debug({ session, client_id: client.id }, 'client connected') let user if (session && session.passport && session.passport.user) { diff --git a/services/real-time/app/js/WebApiManager.js b/services/real-time/app/js/WebApiManager.js index a51610ee77..15ac7525ee 100644 --- a/services/real-time/app/js/WebApiManager.js +++ b/services/real-time/app/js/WebApiManager.js @@ -15,7 +15,7 @@ const { module.exports = { joinProject(project_id, user, callback) { const user_id = user._id - logger.log({ project_id, user_id }, 'sending join project request to web') + logger.debug({ project_id, user_id }, 'sending join project request to web') const url = `${settings.apis.web.url}/project/${project_id}/join` const headers = {} if (user.anonymousAccessToken) { diff --git a/services/real-time/app/js/WebsocketAddressManager.js b/services/real-time/app/js/WebsocketAddressManager.js new file mode 100644 index 0000000000..6371640fc2 --- /dev/null +++ b/services/real-time/app/js/WebsocketAddressManager.js @@ -0,0 +1,30 @@ +const proxyaddr = require('proxy-addr') + +module.exports = class WebsocketAddressManager { + constructor(behindProxy, trustedProxyIps) { + if (behindProxy) { + // parse trustedProxyIps comma-separated list the same way as express + this.trust = proxyaddr.compile( + trustedProxyIps ? trustedProxyIps.split(/ *, */) : [] + ) + } + } + + getRemoteIp(clientHandshake) { + if (this.trust) { + // create a dummy req object using the client handshake and + // connection.remoteAddress for the proxy-addr module to parse + const addressPort = clientHandshake.address + const req = Object.create(clientHandshake, { + connection: { + value: { remoteAddress: addressPort && addressPort.address }, + }, + }) + // return the address parsed from x-forwarded-for + return proxyaddr(req, this.trust) + } else { + // return the address from the client handshake itself + return clientHandshake.address && clientHandshake.address.address + } + } +} diff --git a/services/real-time/app/js/WebsocketController.js b/services/real-time/app/js/WebsocketController.js index c1ea8d232c..4f19698cb8 100644 --- a/services/real-time/app/js/WebsocketController.js +++ b/services/real-time/app/js/WebsocketController.js @@ -32,8 +32,14 @@ module.exports = WebsocketController = { } const user_id = user._id - logger.log( - { user_id, project_id, client_id: client.id }, + logger.info( + { + user_id, + project_id, + client_id: client.id, + remote_ip: client.remoteIp, + user_agent: client.userAgent, + }, 'user joining project' ) metrics.inc('editor.join-project', 1, { status: client.transport }) @@ -45,6 +51,10 @@ module.exports = WebsocketController = { return callback(error) } if (client.disconnected) { + logger.info( + { user_id, project_id, client_id: client.id }, + 'client disconnected before joining project' + ) metrics.inc('editor.join-project.disconnected', 1, { status: 'after-web-api-call', }) @@ -72,8 +82,14 @@ module.exports = WebsocketController = { if (err) { return callback(err) } - logger.log( - { user_id, project_id, client_id: client.id }, + logger.debug( + { + user_id, + project_id, + client_id: client.id, + privilegeLevel, + isRestrictedUser, + }, 'user joined project' ) callback( @@ -114,7 +130,7 @@ module.exports = WebsocketController = { } // client did not join project metrics.inc('editor.leave-project', 1, { status: client.transport }) - logger.log( + logger.info( { project_id, user_id, client_id: client.id }, 'client leaving project' ) @@ -171,7 +187,7 @@ module.exports = WebsocketController = { if (!project_id) { return callback(new NotJoinedError()) } - logger.log( + logger.debug( { user_id, project_id, doc_id, fromVersion, client_id: client.id }, 'client joining doc' ) @@ -266,7 +282,7 @@ module.exports = WebsocketController = { } AuthorizationManager.addAccessToDoc(client, doc_id, () => {}) - logger.log( + logger.debug( { user_id, project_id, @@ -324,7 +340,7 @@ module.exports = WebsocketController = { client.joinLeaveEpoch++ metrics.inc('editor.leave-doc', 1, { status: client.transport }) const { project_id, user_id } = client.ol_context - logger.log( + logger.debug( { user_id, project_id, doc_id, client_id: client.id }, 'client leaving doc' ) @@ -346,7 +362,7 @@ module.exports = WebsocketController = { }) const { project_id, first_name, last_name, email, user_id } = client.ol_context - logger.log( + logger.debug( { user_id, project_id, client_id: client.id, cursorData }, 'updating client position' ) @@ -356,7 +372,7 @@ module.exports = WebsocketController = { cursorData.doc_id, function (error) { if (error) { - logger.info( + logger.debug( { err: error, client_id: client.id, project_id, user_id }, "silently ignoring unauthorized updateClientPosition. Client likely hasn't called joinProject yet." ) @@ -420,7 +436,7 @@ module.exports = WebsocketController = { if (!project_id) { return callback(new NotJoinedError()) } - logger.log( + logger.debug( { user_id, project_id, client_id: client.id }, 'getting connected users' ) @@ -437,7 +453,7 @@ module.exports = WebsocketController = { if (error) { return callback(error) } - logger.log( + logger.debug( { user_id, project_id, client_id: client.id }, 'got connected users' ) @@ -477,7 +493,7 @@ module.exports = WebsocketController = { update.meta.user_id = user_id metrics.inc('editor.doc-update', 0.3, { status: client.transport }) - logger.log( + logger.debug( { user_id, doc_id, diff --git a/services/real-time/app/js/WebsocketLoadBalancer.js b/services/real-time/app/js/WebsocketLoadBalancer.js index f90f28c76b..3af3d51245 100644 --- a/services/real-time/app/js/WebsocketLoadBalancer.js +++ b/services/real-time/app/js/WebsocketLoadBalancer.js @@ -40,7 +40,7 @@ module.exports = WebsocketLoadBalancer = { message, payload, }) - logger.log( + logger.debug( { room_id, message, payload, length: data.length }, 'emitting to room' ) @@ -55,7 +55,7 @@ module.exports = WebsocketLoadBalancer = { }, listenForEditorEvents(io) { - logger.log( + logger.debug( { rclients: this.rclientSubList.length }, 'listening for editor events' ) @@ -102,7 +102,7 @@ module.exports = WebsocketLoadBalancer = { message.room_id ) { const clientList = io.sockets.clients(message.room_id) - logger.log( + logger.debug( { channel, message: message.message, @@ -142,7 +142,7 @@ module.exports = WebsocketLoadBalancer = { if (clientList.length === 0) { return } - logger.log( + logger.debug( { channel, message: message.message, diff --git a/services/real-time/config/settings.defaults.js b/services/real-time/config/settings.defaults.js index 49b15e46fd..1f8e45ad2e 100644 --- a/services/real-time/config/settings.defaults.js +++ b/services/real-time/config/settings.defaults.js @@ -162,6 +162,9 @@ const settings = { catchUncaughtErrors: true, shutdownOnUncaughtError: true, }, + + behindProxy: process.env.BEHIND_PROXY === 'true', + trustedProxyIps: process.env.TRUSTED_PROXY_IPS, } // console.log settings.redis diff --git a/services/real-time/package-lock.json b/services/real-time/package-lock.json index 22d2bd13e2..f456d2ade6 100644 --- a/services/real-time/package-lock.json +++ b/services/real-time/package-lock.json @@ -2484,9 +2484,9 @@ } }, "forwarded": { - "version": "0.1.2", - "resolved": "https://registry.npmjs.org/forwarded/-/forwarded-0.1.2.tgz", - "integrity": "sha512-Ua9xNhH0b8pwE3yRbFfXJvfdWF0UHNCdeyb2sbi9Ul/M+r3PTdrz7Cv4SCfZRMjmzEM9PhraqfZFbGTIg3OMyA==" + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/forwarded/-/forwarded-0.2.0.tgz", + "integrity": "sha512-buRG0fpBtRHSTCOASe6hD258tEubFoRLb4ZNA6NxMVHNw2gOcwHo9wyablzMzOA5z9xA9L1KNjk/Nt6MT9aYow==" }, "fresh": { "version": "0.5.2", @@ -4424,11 +4424,11 @@ } }, "proxy-addr": { - "version": "2.0.6", - "resolved": "https://registry.npmjs.org/proxy-addr/-/proxy-addr-2.0.6.tgz", - "integrity": "sha512-dh/frvCBVmSsDYzw6n926jv974gddhkFPfiN8hPOi30Wax25QZyZEGveluCgliBnqmuM+UJmBErbAUFIoDbjOw==", + "version": "2.0.7", + "resolved": "https://registry.npmjs.org/proxy-addr/-/proxy-addr-2.0.7.tgz", + "integrity": "sha512-llQsMLSUDUPT44jdrU/O37qlnifitDP+ZwrmmZcoSKyLKvtZxpyV0n2/bD/N4tBAAZ/gJEdZU7KMraoK1+XYAg==", "requires": { - "forwarded": "~0.1.2", + "forwarded": "0.2.0", "ipaddr.js": "1.9.1" } }, diff --git a/services/real-time/package.json b/services/real-time/package.json index bb033d1b91..4b5a30a5ca 100644 --- a/services/real-time/package.json +++ b/services/real-time/package.json @@ -37,6 +37,7 @@ "express": "^4.17.1", "express-session": "^1.17.1", "logger-sharelatex": "^2.2.0", + "proxy-addr": "^2.0.7", "request": "^2.88.2", "socket.io": "https://github.com/overleaf/socket.io/archive/0.9.19-overleaf-5.tar.gz", "socket.io-client": "https://github.com/overleaf/socket.io-client/archive/0.9.17-overleaf-3.tar.gz", diff --git a/services/real-time/test/acceptance/js/LeaveDocTests.js b/services/real-time/test/acceptance/js/LeaveDocTests.js index 43fad7e3aa..a9e44102a7 100644 --- a/services/real-time/test/acceptance/js/LeaveDocTests.js +++ b/services/real-time/test/acceptance/js/LeaveDocTests.js @@ -30,14 +30,14 @@ describe('leaveDoc', function () { this.ops = ['mock', 'doc', 'ops'] sinon.spy(logger, 'error') sinon.spy(logger, 'warn') - sinon.spy(logger, 'log') + sinon.spy(logger, 'debug') return (this.other_doc_id = FixturesManager.getRandomId()) }) after(function () { logger.error.restore() // remove the spy logger.warn.restore() - return logger.log.restore() + return logger.debug.restore() }) return describe('when joined to a doc', function () { @@ -177,7 +177,7 @@ describe('leaveDoc', function () { return it('should trigger a low level message only', function () { return sinon.assert.calledWith( - logger.log, + logger.debug, sinon.match.any, 'ignoring request from client to leave room it is not in' ) diff --git a/services/real-time/test/acceptance/js/helpers/RealtimeServer.js b/services/real-time/test/acceptance/js/helpers/RealtimeServer.js index e964765b7a..860835ead8 100644 --- a/services/real-time/test/acceptance/js/helpers/RealtimeServer.js +++ b/services/real-time/test/acceptance/js/helpers/RealtimeServer.js @@ -42,7 +42,7 @@ module.exports = { throw error } this.running = true - logger.log('clsi running in dev mode') + logger.info('clsi running in dev mode') return (() => { const result = [] diff --git a/services/real-time/test/unit/js/DrainManagerTests.js b/services/real-time/test/unit/js/DrainManagerTests.js index 3075c647c7..9d4a41bc0e 100644 --- a/services/real-time/test/unit/js/DrainManagerTests.js +++ b/services/real-time/test/unit/js/DrainManagerTests.js @@ -116,7 +116,7 @@ describe('DrainManager', function () { }) return it('should log out that it reached the end', function () { - return this.logger.log + return this.logger.info .calledWith('All clients have been told to reconnectGracefully') .should.equal(true) })