feat!: consistent logging messages see #286

app/client/src/js/index.ts

@@ -62,6 +62,7 @@ const socket = io({
 // reauthenticate
 function reauthSession () { // eslint-disable-line
   debug('re-authenticating');
+  socket.emit('control', 'reauth');
   window.location.href = '/ssh/reauth';
   return false;
 }

app/server/logging.js

@@ -0,0 +1,47 @@
+/* eslint no-unused-expressions: ["error", { "allowShortCircuit": true, "allowTernary": true }],
+   no-console: ["error", { allow: ["warn", "error", "info"] }] */
+/* jshint esversion: 6, asi: true, node: true */
+// logging.js
+// private
+
+const debug = require('debug');
+const util = require('util');
+
+/**
+ * generate consistent prefix for log messages
+ * with epress session id and socket session id
+ * @param {object} socket Socket information
+ */
+function prefix(socket) {
+  return `(${socket.request.sessionID}/${socket.id})`;
+}
+
+// public
+function webssh2debug(socket, msg) {
+  debug('WebSSH2')(`${prefix(socket)} ${msg}`);
+}
+
+/**
+ * audit log to console
+ * @param {object} socket Socket information
+ * @param {object} msg    log message
+ */
+function auditLog(socket, msg) {
+  console.info(`WebSSH2 ${prefix(socket)} AUDIT: ${msg}`);
+}
+
+/**
+ * logs error to socket client (if connected)
+ * and console.
+ * @param {object} socket Socket information
+ * @param {string} myFunc Function calling this function
+ * @param {object} err    error object or error message
+ */
+function logError(socket, myFunc, err) {
+  console.error(`WebSSH2 ${prefix(socket)} ERROR: ${myFunc}: ${err}`);
+  webssh2debug(socket, `logError: ${myFunc}: ${util.inspect(err)}`);
+  if (!socket.request.session) return;
+  socket.emit('ssherror', `SSH ${myFunc}: ${err}`);
+}
+
+module.exports = { logError, auditLog, webssh2debug };

app/server/socket.js

@@ -6,58 +6,47 @@
 
 // private
 const debug = require('debug');
-const debugWebSSH2 = require('debug')('WebSSH2');
 const SSH = require('ssh2').Client;
 const CIDRMatcher = require('cidr-matcher');
 const validator = require('validator');
 const dnsPromises = require('dns').promises;
+const util = require('util');
+const { webssh2debug, auditLog, logError } = require('./logging');
 
 let termCols;
 let termRows;
 
 /**
- * Error handling for various events. Outputs error to client, logs to
+ * parse conn errors
- * server, destroys session and disconnects socket.
+ * @param {object} socket Socket object
- * @param {object} socket Socket information
+ * @param {object} err    Error object
- * @param {string} myFunc Function calling this function
- * @param {object} err    error object or error message
  */
-// eslint-disable-next-line complexity
+function connError(socket, err) {
-function SSHerror(socket, myFunc, err) {
+  if (err?.level === 'client-authentication') {
-  let theError;
+    logError(
-  if (socket.request.session) {
+      socket,
-    // we just want the first error of the session to pass to the client
+      'CONN ERROR',
-    const firstError = socket.request.session.error || (err ? err.message : undefined);
+      `Authentication failure user=${socket.request.session.username} from=${socket.handshake.address}`
-    theError = firstError ? `: ${firstError}` : '';
+    );
-    // log unsuccessful login attempt
+    socket.emit('allowreauth', socket.request.session.ssh.allowreauth);
-    if (err && err.level === 'client-authentication') {
+    socket.emit('reauth');
-      console.error(
+    return;
-        `WebSSH2 ${'error: Authentication failure'.red.bold} user=${
-          socket.request.session.username.yellow.bold.underline
-        } from=${socket.handshake.address.yellow.bold.underline}`
-      );
-      socket.emit('allowreauth', socket.request.session.ssh.allowreauth);
-      socket.emit('reauth');
-    } else {
-      // eslint-disable-next-line no-console
-      console.log(
-        `WebSSH2 Logout: user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host} port=${socket.request.session.ssh.port} sessionID=${socket.request.sessionID}/${socket.id} allowreplay=${socket.request.session.ssh.allowreplay} term=${socket.request.session.ssh.term}`
-      );
-      if (err) {
-        theError = err ? `: ${err.message}` : '';
-        console.error(`WebSSH2 error${theError}`);
-      }
-    }
-    socket.emit('ssherror', `SSH ${myFunc}${theError}`);
-    socket.request.session.destroy();
-    socket.disconnect(true);
-  } else {
-    theError = err ? `: ${err.message}` : '';
-    socket.disconnect(true);
   }
-  debugWebSSH2(`SSHerror ${myFunc}${theError}`);
+  if (err?.code === 'ENOTFOUND') {
+    logError(socket, 'CONN ERROR', `Host not found: ${err.hostname}`);
+    return;
+  }
+  if (err?.level === 'client-timeout') {
+    logError(socket, 'CONN ERROR', `Connection Timeout: ${socket.request.session.ssh.host}`);
+    return;
+  }
+  logError(socket, 'CONN ERROR', util.inspect(err));
 }
 
+/**
+ * check ssh host is in allowed subnet
+ * @param {object} socket Socket information
+ */
 async function checkSubnet(socket) {
   let ipaddress = socket.request.session.ssh.host;
   if (!validator.isIP(`${ipaddress}`)) {
@@ -65,8 +54,10 @@ async function checkSubnet(socket) {
       const result = await dnsPromises.lookup(socket.request.session.ssh.host);
       ipaddress = result.address;
     } catch (err) {
-      console.error(
+      logError(
-        `WebSSH2 error: ${err.code} ${err.hostname} user=${socket.request.session.username.yellow.bold.underline} from=${socket.handshake.address.yellow.bold.underline}`
+        socket,
+        'CHECK SUBNET',
+        `${err.code}: ${err.hostname} user=${socket.request.session.username} from=${socket.handshake.address}`
       );
       socket.emit('ssherror', '404 HOST IP NOT FOUND');
       socket.disconnect(true);
@@ -76,12 +67,10 @@ async function checkSubnet(socket) {
 
   const matcher = new CIDRMatcher(socket.request.session.ssh.allowedSubnets);
   if (!matcher.contains(ipaddress)) {
-    console.error(
+    logError(
-      `WebSSH2 ${
+      socket,
-        `error: Requested host ${ipaddress} outside configured subnets / REJECTED`.red.bold
+      'CHECK SUBNET',
-      } user=${socket.request.session.username.yellow.bold.underline} from=${
+      `Requested host ${ipaddress} outside configured subnets / REJECTED user=${socket.request.session.username} from=${socket.handshake.address}`
-        socket.handshake.address.yellow.bold.underline
-      }`
     );
     socket.emit('ssherror', '401 UNAUTHORIZED');
     socket.disconnect(true);
@@ -90,11 +79,29 @@ async function checkSubnet(socket) {
 
 // public
 module.exports = function appSocket(socket) {
+  let login = false;
+  socket.once('geometry', (cols, rows) => {
+    termCols = cols;
+    termRows = rows;
+    webssh2debug(socket, `SOCKET GEOMETRY: termCols = ${cols}, termRows = ${rows}`);
+  });
+
+  socket.once('disconnecting', (reason) => {
+    webssh2debug(socket, `SOCKET DISCONNECTING: ${reason}`);
+    if (login === true) {
+      auditLog(
+        socket,
+        `LOGOUT user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host}:${socket.request.session.ssh.port}`
+      );
+      login = false;
+    }
+  });
+
   async function setupConnection() {
     // if websocket connection arrives without an express session, kill it
     if (!socket.request.session) {
       socket.emit('401 UNAUTHORIZED');
-      debugWebSSH2('SOCKET: No Express Session / REJECTED');
+      webssh2debug(socket, 'SOCKET: No Express Session / REJECTED');
       socket.disconnect(true);
       return;
     }
@@ -105,19 +112,22 @@ module.exports = function appSocket(socket) {
     }
 
     const conn = new SSH();
-    socket.on('geometry', (cols, rows) => {
+
-      termCols = cols;
-      termRows = rows;
-    });
     conn.on('banner', (data) => {
       // need to convert to cr/lf for proper formatting
       socket.emit('data', data.replace(/\r?\n/g, '\r\n').toString('utf-8'));
     });
 
     conn.on('ready', () => {
-      debugWebSSH2(
+      webssh2debug(
-        `WebSSH2 Login: user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host} port=${socket.request.session.ssh.port} sessionID=${socket.request.sessionID}/${socket.id} mrhsession=${socket.request.session.ssh.mrhsession} allowreplay=${socket.request.session.ssh.allowreplay} term=${socket.request.session.ssh.term}`
+        socket,
+        `CONN READY: LOGIN: user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host} port=${socket.request.session.ssh.port} allowreplay=${socket.request.session.ssh.allowreplay} term=${socket.request.session.ssh.term}`
       );
+      auditLog(
+        socket,
+        `LOGIN user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host}:${socket.request.session.ssh.port}`
+      );
+      login = true;
       socket.emit('menu');
       socket.emit('allowreauth', socket.request.session.ssh.allowreauth);
       socket.emit('setTerminalOpts', socket.request.session.ssh.terminal);
@@ -141,42 +151,61 @@ module.exports = function appSocket(socket) {
         },
         (err, stream) => {
           if (err) {
-            SSHerror(socket, `EXEC ERROR`, err);
+            logError(socket, `EXEC ERROR`, err);
             conn.end();
+            socket.disconnect(true);
             return;
           }
-          socket.on('data', (data) => {
+          socket.once('disconnect', (reason) => {
-            stream.write(data);
+            webssh2debug(socket, `SOCKET DISCONNECT: ${reason}`);
+            const errMsg = { message: reason };
+            // logError(socket, 'CLIENT SOCKET DISCONNECT', util.inspect(errMsg));
+            conn.end();
+            socket.request.session.destroy();
+          });
+          socket.on('error', (errMsg) => {
+            webssh2debug(socket, `SOCKET ERROR: ${errMsg}`);
+            logError(socket, 'SOCKET ERROR', errMsg);
+            conn.end();
+            socket.disconnect(true);
           });
           socket.on('control', (controlData) => {
             if (controlData === 'replayCredentials' && socket.request.session.ssh.allowreplay) {
               stream.write(`${socket.request.session.userpassword}\n`);
             }
-            debugWebSSH2(`controlData: ${controlData}`);
+            if (controlData === 'reauth' && socket.request.session.username && login === true) {
+              auditLog(
+                socket,
+                `LOGOUT user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host}:${socket.request.session.ssh.port}`
+              );
+              login = false;
+              conn.end();
+              socket.disconnect(true);
+            }
+            webssh2debug(socket, `SOCKET CONTROL: ${controlData}`);
           });
           socket.on('resize', (data) => {
             stream.setWindow(data.rows, data.cols);
+            webssh2debug(socket, `SOCKET RESIZE: ${JSON.stringify([data.rows, data.cols])}`);
           });
-          socket.on('disconnecting', (reason) => {
+          socket.on('data', (data) => {
-            debugWebSSH2(`SOCKET DISCONNECTING: ${reason}`);
+            stream.write(data);
           });
-          socket.on('disconnect', (reason) => {
-            debugWebSSH2(`SOCKET DISCONNECT: ${reason}`);
-            const errMsg = { message: reason };
-            SSHerror(socket, 'CLIENT SOCKET DISCONNECT', errMsg);
-            conn.end();
-            // socket.request.session.destroy()
-          });
-          socket.on('error', (errMsg) => {
-            SSHerror(socket, 'SOCKET ERROR', errMsg);
-            conn.end();
-          });
-
           stream.on('data', (data) => {
             socket.emit('data', data.toString('utf-8'));
           });
           stream.on('close', (code, signal) => {
-            SSHerror(socket, 'STREAM CLOSE', { message: code, signal });
+            webssh2debug(socket, `STREAM CLOSE: ${util.inspect([code, signal])}`);
+            if (socket.request.session?.username && login === true) {
+              auditLog(
+                socket,
+                `LOGOUT user=${socket.request.session.username} from=${socket.handshake.address} host=${socket.request.session.ssh.host}:${socket.request.session.ssh.port}`
+              );
+              login = false;
+            }
+            if (code !== 0 && typeof code !== 'undefined')
+              logError(socket, 'STREAM CLOSE', util.inspect({ message: [code, signal] }));
+            socket.disconnect(true);
             conn.end();
           });
           stream.stderr.on('data', (data) => {
@@ -187,16 +216,19 @@ module.exports = function appSocket(socket) {
     });
 
     conn.on('end', (err) => {
-      SSHerror(socket, 'CONN END BY HOST', err);
+      if (err) logError(socket, 'CONN END BY HOST', err);
+      webssh2debug(socket, 'CONN END BY HOST');
+      socket.disconnect(true);
     });
     conn.on('close', (err) => {
-      SSHerror(socket, 'CONN CLOSE', err);
+      if (err) logError(socket, 'CONN CLOSE', err);
-    });
+      webssh2debug(socket, 'CONN CLOSE');
-    conn.on('error', (err) => {
+      socket.disconnect(true);
-      SSHerror(socket, 'CONN ERROR', err);
     });
+    conn.on('error', (err) => connError(socket, err));
+
     conn.on('keyboard-interactive', (_name, _instructions, _instructionsLang, _prompts, finish) => {
-      debugWebSSH2("conn.on('keyboard-interactive')");
+      webssh2debug(socket, 'CONN keyboard-interactive');
       finish([socket.request.session.userpassword]);
     });
     if (
@@ -205,24 +237,16 @@ module.exports = function appSocket(socket) {
       socket.request.session.ssh
     ) {
       // console.log('hostkeys: ' + hostkeys[0].[0])
-      conn.connect({
+      const { ssh } = socket.request.session;
-        host: socket.request.session.ssh.host,
+      ssh.username = socket.request.session.username;
-        port: socket.request.session.ssh.port,
+      ssh.password = socket.request.session.userpassword;
-        localAddress: socket.request.session.ssh.localAddress,
+      ssh.tryKeyboard = true;
-        localPort: socket.request.session.ssh.localPort,
+      ssh.debug = debug('ssh2');
-        username: socket.request.session.username,
+      conn.connect(ssh);
-        password: socket.request.session.userpassword,
-        privateKey: socket.request.session.privatekey,
-        tryKeyboard: true,
-        algorithms: socket.request.session.ssh.algorithms,
-        readyTimeout: socket.request.session.ssh.readyTimeout,
-        keepaliveInterval: socket.request.session.ssh.keepaliveInterval,
-        keepaliveCountMax: socket.request.session.ssh.keepaliveCountMax,
-        debug: debug('ssh2'),
-      });
     } else {
-      debugWebSSH2(
+      webssh2debug(
-        `Attempt to connect without session.username/password or session varialbles defined, potentially previously abandoned client session. disconnecting websocket client.\r\nHandshake information: \r\n  ${JSON.stringify(
+        socket,
+        `CONN CONNECT: Attempt to connect without session.username/password or session varialbles defined, potentially previously abandoned client session. disconnecting websocket client.\r\nHandshake information: \r\n  ${util.inspect(
           socket.handshake
         )}`
       );