feat(logger): timestamp, pretty-print objects #337

BEFORE:

    info: [object Object]
    debug: request -> nvim_command
    debug: request -> nvim_list_wins
    debug: response -> nvim_command: null
    debug: response -> nvim_list_wins: [object Object],[object Object],[object Object],[object Object]
    ...

AFTER:

    2024-03-20 11:37:25 INF {
      matches: [
        {
          nvimVersion: '0.10.0-dev-2657+g9765efb40f57',
          path: '/usr/local/bin/nvim',
          buildType: 'RelWithDebInfo',
          luaJitVersion: '2.1.1710088188'
        }
      ],
      invalid: []
    }
    2024-03-20 11:37:25 DBG request  -> nvim_command
    2024-03-20 11:37:25 DBG request  -> nvim_list_wins
    2024-03-20 11:37:25 DBG response -> nvim_command: null
    2024-03-20 11:37:25 DBG response -> nvim_list_wins: [
      {
        _events: [Object: null prototype] {},
        _eventsCount: 0,
        _maxListeners: undefined,
        transport: '[Object]',
        data: 1003,
        logger: '[Object]',
        client: '[Object]',
        prefix: 'nvim_win_'
      },
      {
        _events: [Object: null prototype] {},
        _eventsCount: 0,
        _maxListeners: undefined,
        transport: '[Object]',
        data: 1002,
        logger: '[Object]',
        client: '[Object]',
        prefix: 'nvim_win_'
      },
      ...
    ]
    ...
    2024-03-20 11:37:25 DBG request  -> nvim_buf_get_lines
    2024-03-20 11:37:25 DBG response -> nvim_buf_get_lines: [ 'line1', 'line2' ]

Author: justinmk

.eslintrc.js

@@ -48,6 +48,8 @@ module.exports = {
         functions: 'ignore',
       },
     ],
+    // airbnb discourages "for..of", wtf? https://github.com/airbnb/javascript/issues/1271#issuecomment-548688952
+    'no-restricted-syntax': 'off',
     'no-case-declarations': 'off',
     'no-prototype-builtins': 'off',
     'no-underscore-dangle': 'off',

.github/workflows/ci.yml

@@ -10,7 +10,7 @@ on:
 
 env:
   CODECOV_TOKEN: ${{ secrets.CODECOV_TOKEN }}
-  # Purpose of this (currently) is to exercise related codepaths.
+  # Set NVIM_NODE_LOG_FILE to exercise related codepaths.
   NVIM_NODE_LOG_FILE: 'node-client.test.log'
 
 # A workflow run is made up of one or more jobs that can run sequentially or in parallel

CHANGELOG.md

@@ -5,7 +5,8 @@
 - fix: console.log() writes to RPC channel #202 #329
 - feat: eliminate `which` dependency
 - feat: improve logs + error messages
-- fix: always use custom logger if one is given
+- fix: always use custom logger if one is given #336
+- feat(logger): timestamp, pretty-print objects #337
 
 ## [5.0.1](https://github.com/neovim/node-client/compare/v4.11.0...v5.0.1) (2024-03-01)
 

README.md

@@ -59,8 +59,8 @@ Following is a complete, working example.
        const found = findNvim({ orderBy: 'desc', minVersion: '0.9.0' })
        console.log(found);
        const nvim_proc = child_process.spawn(found.matches[0].path, ['--clean', '--embed'], {});
-
        const nvim = attach({ proc: nvim_proc });
+
        nvim.command('vsp | vsp | vsp');
 
        const windows = await nvim.windows;
@@ -81,7 +81,6 @@ Following is a complete, working example.
        const newLines = await buf.lines;
        assert.deepStrictEqual(newLines, ['line1', 'line2']);
 
-       // console.log('%O', nvim_proc);
        if (nvim_proc.disconnect) {
          nvim_proc.disconnect();
        }

packages/neovim/src/api/Base.ts

@@ -1,6 +1,7 @@
 import { EventEmitter } from 'node:events';
 
 import { Transport } from '../utils/transport';
+import { partialClone } from '../utils/util';
 import { Logger, getLogger } from '../utils/logger';
 import { VimValue } from '../types/VimValue';
 
@@ -22,8 +23,8 @@ const DO_REQUEST = Symbol('DO_REQUEST');
 // i.e. a plugin that detaches will affect all plugins registered on host
 // const EXCLUDED = ['nvim_buf_attach', 'nvim_buf_detach'];
 
-// Instead of dealing with multiple inheritance (or lackof), just extend EE
-// Only the Neovim API class should use EE though
+// Instead of dealing with multiple inheritance (or lackof), just extend EventEmitter
+// Only the Neovim API class should use EventEmitter though
 export class BaseApi extends EventEmitter {
   protected transport: Transport;
 
@@ -49,7 +50,6 @@ export class BaseApi extends EventEmitter {
 
     this.setTransport(transport);
     this.data = data;
-    // eslint-disable-next-line global-require, @typescript-eslint/no-var-requires
     this.logger = logger || getLogger();
     this.client = client;
 
@@ -73,7 +73,25 @@ export class BaseApi extends EventEmitter {
   [DO_REQUEST] = (name: string, args: any[] = []): Promise<any> =>
     new Promise((resolve, reject) => {
       this.transport.request(name, args, (err: any, res: any) => {
-        this.logger.debug(`response -> ${name}: ${res}`);
+        if (this.logger.level === 'debug') {
+          // Avoid noisy logging of entire Buffer/Window/Tabpage.
+          let logData: any;
+          try {
+            logData =
+              res && typeof res === 'object'
+                ? partialClone(
+                    res,
+                    2,
+                    ['logger', 'transport', 'client'],
+                    '[Object]'
+                  )
+                : res;
+          } catch {
+            logData = String(res);
+          }
+          this.logger.debug(`response -> ${name}: %O`, logData);
+        }
+
         if (err) {
           reject(new Error(`${name}: ${err[1]}`));
         } else {
@@ -89,7 +107,7 @@ export class BaseApi extends EventEmitter {
     // Not possible for ExtType classes since they are only created after transport is ready
     await this._isReady;
 
-    this.logger.debug(`request -> ${name}`);
+    this.logger.debug(`request  -> ${name}`);
 
     return this[DO_REQUEST](name, args).catch(err => {
       // XXX: Get a `*.ts stacktrace. If we re-throw `err` we get a `*.js` trace. tsconfig issue?

packages/neovim/src/attach/attach.ts

@@ -37,7 +37,6 @@ export function attach({
   }
 
   if (writer && reader) {
-    // eslint-disable-next-line global-require, @typescript-eslint/no-var-requires
     const loggerInstance = options.logger || getLogger(); // lazy load to winston only if needed
     const neovim = new NeovimClient({ logger: loggerInstance });
     neovim.attach({

packages/neovim/src/plugin/autocmd.ts

@@ -29,9 +29,7 @@ export function autocmd(name: string, options?: AutocmdOptions) {
       }
     });
 
-    const nameWithPattern = `${name}${
-      options.pattern ? `:${options.pattern}` : ''
-    }`;
+    const nameWithPattern = `${name}${options.pattern ? `:${options.pattern}` : ''}`;
     Object.defineProperty(f, NVIM_METHOD_NAME, {
       value: `autocmd:${nameWithPattern}`,
     });

packages/neovim/src/testUtil.ts

@@ -34,7 +34,6 @@ export function startNvim(
 ): [cp.ChildProcessWithoutNullStreams, NeovimClient | undefined] {
   const testFile = jest.expect.getState().testPath?.replace(/.*[\\/]/, '');
   const msg = `startNvim in test: ${testFile}`;
-  // console.log(msg);
   if (process.env.NVIM_NODE_LOG_FILE) {
     const logfile = path.resolve(process.env.NVIM_NODE_LOG_FILE);
     fs.writeFileSync(logfile, `${msg}\n`, { flag: 'a' });

packages/neovim/src/utils/logger.ts

@@ -1,8 +1,35 @@
 import * as winston from 'winston';
+import { inspect } from 'node:util';
 
 const level = process.env.NVIM_NODE_LOG_LEVEL || 'debug';
 
-export type Logger = Pick<winston.Logger, 'info' | 'warn' | 'error' | 'debug'>;
+export type Logger = Pick<
+  winston.Logger,
+  'info' | 'warn' | 'error' | 'debug' | 'level'
+>;
+
+function getFormat(colorize: boolean) {
+  return winston.format.combine(
+    winston.format.splat(),
+    winston.format.timestamp({
+      format: 'YYYY-MM-DD HH:mm:ss',
+    }),
+    winston.format.printf(info => {
+      let msg: string;
+      try {
+        msg =
+          typeof info.message === 'object'
+            ? inspect(info.message, false, 2, colorize)
+            : info.message;
+      } catch {
+        msg = info.message;
+      }
+      const lvl =
+        info.level === 'debug' ? 'DBG' : info.level.slice(0, 3).toUpperCase();
+      return `${info.timestamp} ${lvl} ${msg}`;
+    })
+  );
+}
 
 function setupWinstonLogger(): Logger {
   const logger = winston.createLogger({
@@ -14,31 +41,15 @@ function setupWinstonLogger(): Logger {
       new winston.transports.File({
         filename: process.env.NVIM_NODE_LOG_FILE,
         level,
-        format: winston.format.combine(
-          winston.format.splat(),
-          winston.format.timestamp({
-            format: 'YYYY-MM-DD HH:mm:ss',
-          }),
-          winston.format.errors({ stack: true }),
-          winston.format.printf(info => {
-            if (info.raw) {
-              return info.message;
-            }
-            const lvl =
-              info.level === 'debug'
-                ? 'DBG'
-                : info.level.slice(0, 3).toUpperCase();
-            return `${info.timestamp} ${lvl} ${info.message}`;
-          })
-        ),
+        format: getFormat(false),
       })
     );
   }
 
   if (process.env.ALLOW_CONSOLE) {
     logger.add(
       new winston.transports.Console({
-        format: winston.format.simple(),
+        format: getFormat(true),
       })
     );
   }

packages/neovim/src/utils/util.ts

@@ -0,0 +1,52 @@
+/**
+ * Clones an object (copies "own properties") until `depth`, where:
+ * - depth=0 returns non-object value, or empty object (`{}` or `[]`).
+ * - depth=1 returns `obj` with its immediate children (but not their children).
+ * - depth=2 returns `obj` with its children and their children.
+ * - and so on...
+ *
+ * TODO: node's `util.inspect()` function is better, but doesn't work in web browser?
+ *
+ * @param obj Object to clone.
+ * @param depth
+ * @param omitKeys Omit properties matching these names (at any depth).
+ * @param replacement Replacement for object whose fields extend beyond `depth`, and properties matching `omitKeys`.
+ */
+export function partialClone(
+  obj: any,
+  depth: number = 3,
+  omitKeys: string[] = [],
+  replacement: any = undefined
+): any {
+  // Base case: If input is not an object or has no children, return it.
+  if (
+    typeof obj !== 'object' ||
+    obj === null ||
+    Object.getOwnPropertyNames(obj).length === 0
+  ) {
+    return obj;
+  }
+
+  // Create a new object of the same type as the input object.
+  const clonedObj = Array.isArray(obj) ? [] : {};
+
+  if (depth === 0) {
+    return replacement || clonedObj;
+  }
+
+  // Recursively clone properties of the input object
+  for (const key of Object.keys(obj)) {
+    if (omitKeys.includes(key)) {
+      (clonedObj as any)[key] = replacement || (Array.isArray(obj) ? [] : {});
+    } else if (Object.prototype.hasOwnProperty.call(obj, key)) {
+      (clonedObj as any)[key] = partialClone(
+        obj[key],
+        depth - 1,
+        omitKeys,
+        replacement
+      );
+    }
+  }
+
+  return clonedObj;
+}