From 5b5086469b4cb95c1793bb36bb18ca49007fedc1 Mon Sep 17 00:00:00 2001 From: Anna Henningsen Date: Fri, 13 Oct 2023 18:17:27 +0200 Subject: [PATCH] chore(ssh-tunnel): add logging and improve displayed error message COMPASS-7336 (#4983) --- package-lock.json | 60 ++++++--- packages/compass-logging/package.json | 3 +- .../data-service/src/connect-mongo-client.ts | 11 ++ packages/ssh-tunnel/package.json | 3 +- packages/ssh-tunnel/src/index.ts | 123 +++++++++++++----- 5 files changed, 150 insertions(+), 50 deletions(-) diff --git a/package-lock.json b/package-lock.json index 128f34fc6b3..7205efb93b8 100644 --- a/package-lock.json +++ b/package-lock.json @@ -13276,9 +13276,9 @@ "dev": true }, "node_modules/@types/debug": { - "version": "4.1.7", - "resolved": "https://registry.npmjs.org/@types/debug/-/debug-4.1.7.tgz", - "integrity": "sha512-9AonUzyTjXXhEOa0DnqpzZi6VHlqKMswga9EXjpXnnqxwLtdvPPtlO8evrI5D9S6asFRCQ6v+wpiUKbw+vKqyg==", + "version": "4.1.9", + "resolved": "https://registry.npmjs.org/@types/debug/-/debug-4.1.9.tgz", + "integrity": "sha512-8Hz50m2eoS56ldRlepxSBa6PWEVCtzUo/92HgLc2qTMnotJNIm7xP+UZhyWoYsyOdd5dxZ+NZLb24rsKyFs2ow==", "dev": true, "dependencies": { "@types/ms": "*" @@ -13512,9 +13512,9 @@ "dev": true }, "node_modules/@types/ms": { - "version": "0.7.31", - "resolved": "https://registry.npmjs.org/@types/ms/-/ms-0.7.31.tgz", - "integrity": "sha512-iiUgKzV9AuaEkZqkOLDIvlQiL6ltuZd9tGcW3gwpnX8JbuiuhFlEGmmFXEXkN50Cvq7Os88IY2v0dkDqXYWVgA==", + "version": "0.7.32", + "resolved": "https://registry.npmjs.org/@types/ms/-/ms-0.7.32.tgz", + "integrity": "sha512-xPSg0jm4mqgEkNhowKgZFBNtwoEwF6gJ4Dhww+GFpm3IgtNseHQZ5IqdNwnquZEoANxyDAKDRAdVo4Z72VvD/g==", "dev": true }, "node_modules/@types/node": { @@ -46667,7 +46667,7 @@ "version": "1.2.2", "license": "SSPL", "dependencies": { - "debug": "^4.2.0", + "debug": "^4.3.4", "is-electron-renderer": "^2.0.1", "mongodb-log-writer": "^1.3.0" }, @@ -46677,6 +46677,7 @@ "@mongodb-js/prettier-config-compass": "^1.0.1", "@mongodb-js/tsconfig-compass": "^1.0.3", "@types/chai": "^4.2.21", + "@types/debug": "^4.1.9", "@types/mocha": "^9.0.0", "@types/sinon-chai": "^3.2.5", "chai": "^4.3.4", @@ -46693,6 +46694,22 @@ "hadron-ipc": "^3.2.2" } }, + "packages/compass-logging/node_modules/debug": { + "version": "4.3.4", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz", + "integrity": "sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ==", + "dependencies": { + "ms": "2.1.2" + }, + "engines": { + "node": ">=6.0" + }, + "peerDependenciesMeta": { + "supports-color": { + "optional": true + } + } + }, "packages/compass-logging/node_modules/sinon": { "version": "9.2.4", "resolved": "https://registry.npmjs.org/sinon/-/sinon-9.2.4.tgz", @@ -52300,7 +52317,7 @@ "version": "2.1.0", "license": "Apache-2.0", "dependencies": { - "debug": "^4.2.0", + "@mongodb-js/compass-logging": "^1.2.2", "socksv5": "0.0.6", "ssh2": "^1.12.0" }, @@ -52311,7 +52328,6 @@ "@mongodb-js/tsconfig-compass": "^1.0.3", "@types/chai": "^4.2.21", "@types/chai-as-promised": "^7.1.4", - "@types/debug": "^4.1.7", "@types/mocha": "^9.0.0", "@types/node-fetch": "^2.5.8", "@types/sinon-chai": "^3.2.5", @@ -59538,10 +59554,11 @@ "@mongodb-js/prettier-config-compass": "^1.0.1", "@mongodb-js/tsconfig-compass": "^1.0.3", "@types/chai": "^4.2.21", + "@types/debug": "^4.1.9", "@types/mocha": "^9.0.0", "@types/sinon-chai": "^3.2.5", "chai": "^4.3.4", - "debug": "^4.2.0", + "debug": "^4.3.4", "depcheck": "^1.4.1", "eslint": "^7.25.0", "hadron-ipc": "^3.2.2", @@ -59554,6 +59571,14 @@ "typescript": "^5.0.4" }, "dependencies": { + "debug": { + "version": "4.3.4", + "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz", + "integrity": "sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ==", + "requires": { + "ms": "2.1.2" + } + }, "sinon": { "version": "9.2.4", "resolved": "https://registry.npmjs.org/sinon/-/sinon-9.2.4.tgz", @@ -63145,20 +63170,19 @@ "@mongodb-js/ssh-tunnel": { "version": "file:packages/ssh-tunnel", "requires": { + "@mongodb-js/compass-logging": "^1.2.2", "@mongodb-js/eslint-config-compass": "^1.0.9", "@mongodb-js/mocha-config-compass": "^1.3.1", "@mongodb-js/prettier-config-compass": "^1.0.1", "@mongodb-js/tsconfig-compass": "^1.0.3", "@types/chai": "^4.2.21", "@types/chai-as-promised": "^7.1.4", - "@types/debug": "^4.1.7", "@types/mocha": "^9.0.0", "@types/node-fetch": "^2.5.8", "@types/sinon-chai": "^3.2.5", "@types/ssh2": "^1.11.8", "chai": "^4.3.4", "chai-as-promised": "^7.1.1", - "debug": "^4.2.0", "depcheck": "^1.4.1", "eslint": "^7.25.0", "gen-esm-wrapper": "^1.1.0", @@ -67343,9 +67367,9 @@ "dev": true }, "@types/debug": { - "version": "4.1.7", - "resolved": "https://registry.npmjs.org/@types/debug/-/debug-4.1.7.tgz", - "integrity": "sha512-9AonUzyTjXXhEOa0DnqpzZi6VHlqKMswga9EXjpXnnqxwLtdvPPtlO8evrI5D9S6asFRCQ6v+wpiUKbw+vKqyg==", + "version": "4.1.9", + "resolved": "https://registry.npmjs.org/@types/debug/-/debug-4.1.9.tgz", + "integrity": "sha512-8Hz50m2eoS56ldRlepxSBa6PWEVCtzUo/92HgLc2qTMnotJNIm7xP+UZhyWoYsyOdd5dxZ+NZLb24rsKyFs2ow==", "dev": true, "requires": { "@types/ms": "*" @@ -67580,9 +67604,9 @@ "dev": true }, "@types/ms": { - "version": "0.7.31", - "resolved": "https://registry.npmjs.org/@types/ms/-/ms-0.7.31.tgz", - "integrity": "sha512-iiUgKzV9AuaEkZqkOLDIvlQiL6ltuZd9tGcW3gwpnX8JbuiuhFlEGmmFXEXkN50Cvq7Os88IY2v0dkDqXYWVgA==", + "version": "0.7.32", + "resolved": "https://registry.npmjs.org/@types/ms/-/ms-0.7.32.tgz", + "integrity": "sha512-xPSg0jm4mqgEkNhowKgZFBNtwoEwF6gJ4Dhww+GFpm3IgtNseHQZ5IqdNwnquZEoANxyDAKDRAdVo4Z72VvD/g==", "dev": true }, "@types/node": { diff --git a/packages/compass-logging/package.json b/packages/compass-logging/package.json index 5eb127c1b4f..199fc007ced 100644 --- a/packages/compass-logging/package.json +++ b/packages/compass-logging/package.json @@ -48,7 +48,7 @@ "reformat": "npm run prettier -- --write . && npm run eslint . --fix" }, "dependencies": { - "debug": "^4.2.0", + "debug": "^4.3.4", "is-electron-renderer": "^2.0.1", "mongodb-log-writer": "^1.3.0" }, @@ -57,6 +57,7 @@ "@mongodb-js/mocha-config-compass": "^1.3.1", "@mongodb-js/prettier-config-compass": "^1.0.1", "@mongodb-js/tsconfig-compass": "^1.0.3", + "@types/debug": "^4.1.9", "@types/chai": "^4.2.21", "@types/mocha": "^9.0.0", "@types/sinon-chai": "^3.2.5", diff --git a/packages/data-service/src/connect-mongo-client.ts b/packages/data-service/src/connect-mongo-client.ts index c156bd24c32..39ecf3560f2 100644 --- a/packages/data-service/src/connect-mongo-client.ts +++ b/packages/data-service/src/connect-mongo-client.ts @@ -161,6 +161,10 @@ export async function connectMongoClientDataService({ connectionOptions.sshTunnel, logger ); + const tunnelForwardingErrors: Error[] = []; + tunnel?.on('forwardingError', (err: Error) => + tunnelForwardingErrors.push(err) + ); if (socks5Options) { Object.assign(options, socks5Options); @@ -280,6 +284,13 @@ export async function connectMongoClientDataService({ ]).catch(() => { /* ignore errors */ }); + if (tunnelForwardingErrors.length > 0) { + err.message = `${ + err.message + } [SSH Tunnel errors: ${tunnelForwardingErrors.map( + (err) => err.message + )}]`; + } throw err; } } diff --git a/packages/ssh-tunnel/package.json b/packages/ssh-tunnel/package.json index bea889f0a9d..a7566a3cba4 100644 --- a/packages/ssh-tunnel/package.json +++ b/packages/ssh-tunnel/package.json @@ -55,7 +55,6 @@ "@mongodb-js/tsconfig-compass": "^1.0.3", "@types/chai": "^4.2.21", "@types/chai-as-promised": "^7.1.4", - "@types/debug": "^4.1.7", "@types/mocha": "^9.0.0", "@types/node-fetch": "^2.5.8", "@types/sinon-chai": "^3.2.5", @@ -74,7 +73,7 @@ "typescript": "^5.0.4" }, "dependencies": { - "debug": "^4.2.0", + "@mongodb-js/compass-logging": "^1.2.2", "socksv5": "0.0.6", "ssh2": "^1.12.0" } diff --git a/packages/ssh-tunnel/src/index.ts b/packages/ssh-tunnel/src/index.ts index 7189a4d727d..e7910edea94 100644 --- a/packages/ssh-tunnel/src/index.ts +++ b/packages/ssh-tunnel/src/index.ts @@ -3,7 +3,7 @@ import { EventEmitter, once } from 'events'; import type { Socket } from 'net'; import type { ClientChannel, ConnectConfig } from 'ssh2'; import { Client as SshClient } from 'ssh2'; -import createDebug from 'debug'; +import { createLoggerAndTelemetry } from '@mongodb-js/compass-logging'; // The socksv5 module is not bundle-able by itself, so we get the // subpackages directly @@ -11,7 +11,8 @@ import socks5Server from 'socksv5/lib/server'; import socks5AuthNone from 'socksv5/lib/auth/None'; import socks5AuthUserPassword from 'socksv5/lib/auth/UserPassword'; -const debug = createDebug('mongodb:ssh-tunnel'); +const { log, mongoLogId, debug } = + createLoggerAndTelemetry('COMPASS-SSH-TUNNEL'); type LocalProxyServerConfig = { localAddr: string; @@ -49,6 +50,7 @@ function getSshTunnelConfig(config: Partial): SshTunnelConfig { }; } +let idCounter = 0; export class SshTunnel extends EventEmitter { private connected = false; private closed = false; @@ -65,6 +67,7 @@ export class SshTunnel extends EventEmitter { dstIP: string, dstPort: number ) => Promise; + private logCtx = `tunnel-${idCounter++}`; constructor(config: Partial = {}) { super(); @@ -74,7 +77,7 @@ export class SshTunnel extends EventEmitter { this.sshClient = new SshClient(); this.sshClient.on('close', () => { - debug('sshClient closed'); + log.info(mongoLogId(1_001_000_252), this.logCtx, 'sshClient closed'); this.connected = false; }); @@ -89,13 +92,18 @@ export class SshTunnel extends EventEmitter { const success = this.rawConfig.socks5Username === user && this.rawConfig.socks5Password === pass; - debug('validating auth parameters', success); + log.info( + mongoLogId(1_001_000_253), + this.logCtx, + 'Validated auth parameters', + { success } + ); queueMicrotask(() => cb(success)); } ) ); } else { - debug('skipping auth setup for this server'); + log.info(mongoLogId(1_001_000_254), this.logCtx, 'Skipping auth setup'); this.server.useAuth(socks5AuthNone()); } @@ -121,14 +129,19 @@ export class SshTunnel extends EventEmitter { async listen(): Promise { const { localPort, localAddr } = this.rawConfig; - debug('starting to listen', { localAddr, localPort }); + log.info( + mongoLogId(1_001_000_255), + this.logCtx, + 'Listening for Socks5 connections', + { localAddr, localPort } + ); await this.serverListen(localPort, localAddr); await this.connectSsh(); } async close(): Promise { - debug('closing SSH tunnel'); + log.info(mongoLogId(1_001_000_256), this.logCtx, 'Closing SSH tunnel'); const [maybeError] = await Promise.all([ // If we catch anything, just return the error instead of throwing, we // want to await on closing the connections before re-throwing server @@ -159,7 +172,11 @@ export class SshTunnel extends EventEmitter { throw new Error('Disconnected.'); } - debug('creating SSH connection'); + log.info( + mongoLogId(1_001_000_257), + this.logCtx, + 'Establishing new SSH connection' + ); this.connectingPromise = Promise.race([ once(this.sshClient, 'error').then(([err]) => { @@ -175,7 +192,13 @@ export class SshTunnel extends EventEmitter { try { await this.connectingPromise; } catch (err) { - debug('failed to establish SSH connection', err); + this.emit('forwardingError', err); + log.error( + mongoLogId(1_001_000_258), + this.logCtx, + 'Failed to establish new SSH connection', + { error: (err as any)?.stack ?? String(err) } + ); delete this.connectingPromise; await this.serverClose(); throw err; @@ -183,7 +206,11 @@ export class SshTunnel extends EventEmitter { delete this.connectingPromise; this.connected = true; - debug('created SSH connection'); + log.info( + mongoLogId(1_001_000_259), + this.logCtx, + 'Finished establishing new SSH connection' + ); } private async closeSshClient() { @@ -214,7 +241,16 @@ export class SshTunnel extends EventEmitter { accept: (intercept: true) => Socket, deny: () => void ): Promise { - debug('receiving socks5 forwarding request', info); + const { srcAddr, srcPort, dstAddr, dstPort } = info; + const logMetadata = { srcAddr, srcPort, dstAddr, dstPort }; + log.info( + mongoLogId(1_001_000_260), + this.logCtx, + 'Received Socks5 fowarding request', + { + ...logMetadata, + } + ); let socket: Socket | null = null; try { @@ -222,47 +258,76 @@ export class SshTunnel extends EventEmitter { let channel; try { - channel = await this.forwardOut( - info.srcAddr, - info.srcPort, - info.dstAddr, - info.dstPort - ); + channel = await this.forwardOut(srcAddr, srcPort, dstAddr, dstPort); } catch (err) { if ((err as Error).message === 'Not connected') { this.connected = false; - debug('error forwarding. retrying..', info, err); - await this.connectSsh(); - channel = await this.forwardOut( - info.srcAddr, - info.srcPort, - info.dstAddr, - info.dstPort + log.error( + mongoLogId(1_001_000_261), + this.logCtx, + 'Error forwarding Socks5 request, retrying', + { + ...logMetadata, + error: (err as Error).stack, + } ); + await this.connectSsh(); + channel = await this.forwardOut(srcAddr, srcPort, dstAddr, dstPort); } else { throw err; } } - debug('channel opened, accepting socks5 request', info); + log.info( + mongoLogId(1_001_000_262), + this.logCtx, + 'Opened SSH channel and accepting socks5 request', + { + ...logMetadata, + } + ); socket = accept(true); this.connections.add(socket); socket.on('error', (err: ErrorWithOrigin) => { - debug('error on socksv5 socket', info, err); + log.error( + mongoLogId(1_001_000_263), + this.logCtx, + 'Error on Socks5 stream socket', + { + ...logMetadata, + error: (err as Error).stack, + } + ); err.origin = err.origin ?? 'connection'; - this.server.emit('error', err); + this.emit('forwardingError', err); }); socket.once('close', () => { - debug('socksv5 socket closed, removing from set'); + log.info( + mongoLogId(1_001_000_264), + this.logCtx, + 'Socks5 stream socket closed', + { + ...logMetadata, + } + ); this.connections.delete(socket as Socket); }); socket.pipe(channel).pipe(socket); } catch (err) { - debug('caught error, rejecting socks5 request', info, err); + this.emit('forwardingError', err); + log.error( + mongoLogId(1_001_000_265), + this.logCtx, + 'Error establishing SSH channel for Socks5 request', + { + ...logMetadata, + error: (err as Error).stack, + } + ); deny(); if (socket) { (err as any).origin = 'ssh-client';