fix: console.log() writes to RPC channel

Problem:
2d47447 removed "sandboxing" and
accidentally also removed the console.log monkey-patching. This means
a random call to `console.log` can write to stdout, which breaks the RPC
channel.

Solution:
Re-implement the patching.

fix #202
fix #329

Author: justinmk

.github/workflows/ci.yml

@@ -10,6 +10,8 @@ on:
 
 env:
   CODECOV_TOKEN: ${{ secrets.CODECOV_TOKEN }}
+  # Purpose of this (currently) is 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
 jobs:

README.md

@@ -21,8 +21,19 @@ See below for a quickstart example that you can copy and run immediately.
 
 The `neovim` package provides these functions:
 
-- `findNvim`: Tries to find a usable `nvim` binary on the current system.
-- `attach`: The primary interface. Takes a process, socket, or pair of write/read streams and returns a `NeovimClient` connected to an `nvim` process.
+- `attach()`: The primary interface. Takes a process, socket, or pair of write/read streams and returns a `NeovimClient` connected to an `nvim` process.
+- `findNvim()`: Tries to find a usable `nvim` binary on the current system.
+
+### Logging
+
+- At load-time, the `neovim` module replaces ("monkey patches") `console` with its `logger`
+  interface, so `console.log` will call `logger.info` instead of writing to stdout (which would
+  break the stdio RPC channel).
+    - To skip this patching of `console.log`, pass a custom `logger` to `attach()`.
+    - Best practice in any case is to use the `logger` available from the `NeovimClient` returned by
+      `attach()`, instead of `console` logging functions.
+- Set the `$NVIM_NODE_LOG_FILE` env var to (also) write logs to a file.
+- Set the `$ALLOW_CONSOLE` env var to (also) write logs to stdout.
 
 ### Quickstart: connect to Nvim
 
@@ -34,53 +45,54 @@ Following is a complete, working example.
    ```
 2. Paste the script below into a `demo.mjs` file and run it!
    ```
-   node demo.mjs
+   ALLOW_CONSOLE=1 node demo.mjs
    ```
-
-```js
-import * as child_process from 'node:child_process'
-import * as assert from 'node:assert'
-import { attach, findNvim } from 'neovim'
-
-// Find `nvim` on the system and open a channel to it.
-(async function() {
-  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;
-  assert.deepStrictEqual(windows.length, 4);
-  assert.ok(windows[0] instanceof nvim.Window);
-
-  nvim.window = windows[2];
-  const win = await nvim.window;
-  assert.ok(win.id !== windows[0].id);
-  assert.deepStrictEqual(win.id, windows[2].id);
-
-  const buf = await nvim.buffer;
-  assert.ok(buf instanceof nvim.Buffer);
-  const lines = await buf.lines;
-  assert.deepStrictEqual(lines, []);
-
-  await buf.replace(['line1', 'line2'], 0);
-  const newLines = await buf.lines;
-  assert.deepStrictEqual(newLines, ['line1', 'line2']);
-
-  // console.log('%O', nvim_proc);
-  if (nvim_proc.disconnect) {
-    nvim_proc.disconnect();
-  }
-  nvim.quit();
-  while (nvim_proc.exitCode === null) {
-    await new Promise(resolve => setTimeout(resolve, 100))
-    console.log('waiting for Nvim (pid %d) to exit', nvim_proc.pid);
-  }
-  console.log('Nvim exit code: %d', nvim_proc.exitCode);
-})();
-```
+    - `$ALLOW_CONSOLE` env var must be set, because logs are normally not printed to stdout.
+    - Script:
+     ```js
+     import * as child_process from 'node:child_process'
+     import * as assert from 'node:assert'
+     import { attach, findNvim } from 'neovim'
+
+     // Find `nvim` on the system and open a channel to it.
+     (async function() {
+       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;
+       assert.deepStrictEqual(windows.length, 4);
+       assert.ok(windows[0] instanceof nvim.Window);
+
+       nvim.window = windows[2];
+       const win = await nvim.window;
+       assert.ok(win.id !== windows[0].id);
+       assert.deepStrictEqual(win.id, windows[2].id);
+
+       const buf = await nvim.buffer;
+       assert.ok(buf instanceof nvim.Buffer);
+       const lines = await buf.lines;
+       assert.deepStrictEqual(lines, []);
+
+       await buf.replace(['line1', 'line2'], 0);
+       const newLines = await buf.lines;
+       assert.deepStrictEqual(newLines, ['line1', 'line2']);
+
+       // console.log('%O', nvim_proc);
+       if (nvim_proc.disconnect) {
+         nvim_proc.disconnect();
+       }
+       nvim.quit();
+       while (nvim_proc.exitCode === null) {
+         await new Promise(resolve => setTimeout(resolve, 100))
+         console.log('waiting for Nvim (pid %d) to exit', nvim_proc.pid);
+       }
+       console.log('Nvim exit code: %d', nvim_proc.exitCode);
+     })();
+     ```
 
 ### Create a remote plugin
 
@@ -94,8 +106,6 @@ The plugin must export a function which takes a `NvimPlugin` object as its only
 **Avoid heavy initialisation or async functions at this stage,** because Nvim may only be collecting information about your plugin without wishing to actually use it.
 Instead, wait for one of your autocmds, commands or functions to be called before starting any processing.
 
-The host replaces `console` with a `winston` interface, so `console.log` will call `winston.info`.
-
 ### Remote plugin examples
 
 See [`examples/`](https://github.com/neovim/node-client/tree/master/examples) for remote plugin examples.
@@ -169,7 +179,7 @@ For debugging and configuring logging, you can set the following environment var
 
 - `NVIM_NODE_HOST_DEBUG`: Spawns the node process that calls `neovim-client-host` with `--inspect-brk` so you can have a debugger.
   Pair that with this [Node Inspector Manager Chrome plugin](https://chrome.google.com/webstore/detail/nodejs-v8-inspector-manag/gnhhdgbaldcilmgcpfddgdbkhjohddkj?hl=en)
-- Logging: Logging is done using `winston` through the `logger` module. Plugins have `console` replaced with this interface.
+- Logging: Logging is done using `winston` through the `logger` module. This package replaces `console` with this interface.
     - `NVIM_NODE_LOG_LEVEL`: Sets the logging level for winston. Default is `debug`.
       Available levels: `{ error: 0, warn: 1, info: 2, verbose: 3, debug: 4, silly: 5 }`
     - `NVIM_NODE_LOG_FILE`: Sets the log file path.
@@ -190,6 +200,14 @@ For debugging and configuring logging, you can set the following environment var
 
 See the tests and [`scripts`](https://github.com/neovim/node-client/tree/master/packages/neovim/scripts) for more examples.
 
+## Develop
+
+After cloning the repo, run `npm install` to install dev dependencies. The main `neovim` library is in `packages/neovim`.
+
+### Run tests
+
+    npm run build && NVIM_NODE_LOG_FILE=log npm run test
+
 ## Maintain
 
 ### Release
@@ -232,11 +250,7 @@ git commit -m 'publish docs'
 git push origin HEAD:gh-pages
 ```
 
-## Contributing
-
-After cloning the repo, run `npm install` to install dev dependencies. The main `neovim` library is in `packages/neovim`.
-
-### Contributors
+## Contributors
 
 * [@billyvg](https://github.com/billyvg) for rewrite
 * [@mhartington](https://github.com/mhartington) for TypeScript rewrite

packages/integration-tests/__tests__/integration.test.ts

@@ -65,6 +65,14 @@ describe('Node host', () => {
   // done();
   // });
 
+  it('console.log is monkey-patched to logger.info #329', async () => {
+    const spy = jest.spyOn(nvim.logger, 'info');
+    console.log('log message');
+    expect(spy).toHaveBeenCalledWith('log message');
+    // Still alive?
+    expect(await nvim.eval('1+1')).toEqual(2);
+  });
+
   it('can run a command from plugin', async () => {
     await nvim.command('JSHostTestCmd');
     const line = await nvim.line;

packages/neovim/src/attach/attach.test.ts

@@ -3,6 +3,8 @@ import * as cp from 'node:child_process';
 // eslint-disable-next-line import/no-extraneous-dependencies
 import * as which from 'which';
 import { attach } from './attach';
+import { Logger, logger } from '../utils/logger';
+import { NeovimClient } from '../api/client';
 
 try {
   which.sync('nvim');
@@ -15,17 +17,29 @@ try {
   process.exit(1);
 }
 
-describe('Nvim Promise API', () => {
+describe('Nvim API', () => {
   let proc;
   let nvim;
   let requests;
   let notifications;
 
+  function startNvim() {
+    return cp.spawn('nvim', ['-u', 'NONE', '--embed', '-n', '--noplugin'], {
+      cwd: __dirname,
+    });
+  }
+
+  function stopNvim(proc_: cp.ChildProcessWithoutNullStreams | NeovimClient) {
+    if (proc_ instanceof NeovimClient) {
+      proc_.command('qa!');
+    } else if (proc_ && proc_.connected) {
+      proc_.disconnect();
+    }
+  }
+
   beforeAll(async () => {
     try {
-      proc = cp.spawn('nvim', ['-u', 'NONE', '--embed', '-n', '--noplugin'], {
-        cwd: __dirname,
-      });
+      proc = startNvim();
 
       nvim = attach({ proc });
       nvim.on('request', (method, args, resp) => {
@@ -42,16 +56,55 @@ describe('Nvim Promise API', () => {
   });
 
   afterAll(() => {
-    if (proc && proc.connected) {
-      proc.disconnect();
-    }
+    stopNvim(nvim);
+    stopNvim(proc);
   });
 
   beforeEach(() => {
     requests = [];
     notifications = [];
   });
 
+  it('console.log is monkey-patched to logger.info #329', async () => {
+    const spy = jest.spyOn(nvim.logger, 'info');
+    console.log('log message');
+    expect(spy).toHaveBeenCalledWith('log message');
+    // Still alive?
+    expect(await nvim.eval('1+1')).toEqual(2);
+  });
+
+  it('console.log NOT monkey-patched if custom logger passed to attach()', async () => {
+    const proc2 = startNvim();
+    const logged: string[] = [];
+    const fakeLog = (msg: any) => {
+      logged.push(msg);
+      return logger2;
+    }
+    const logger2 = {
+      info: fakeLog,
+      warn: fakeLog,
+      debug: fakeLog,
+      error: fakeLog,
+    } as Logger;
+    const nvim2 = attach({ proc: proc2, options: { logger: logger2 } });
+
+    const spy = jest.spyOn(nvim2.logger, 'info');
+    console.log('message 1');
+    // console.log was NOT patched.
+    expect(spy).toHaveBeenCalledTimes(0);
+    // Custom logger did NOT get the message.
+    expect(logged).toEqual([])
+
+    // Custom logger can be called explicitly.
+    nvim2.logger.info('message 2')
+    expect(logged).toEqual(['message 2'])
+
+    // Still alive?
+    expect(await nvim2.eval('1+1')).toEqual(2);
+
+    stopNvim(nvim2);
+  });
+
   it('can send requests and receive response', async () => {
     const result = await nvim.eval('{"k1": "v1", "k2": 2}');
     expect(result).toEqual({ k1: 'v1', k2: 2 });

packages/neovim/src/utils/logger.ts

@@ -31,6 +31,13 @@ function setupWinstonLogger(): Logger {
     logger.add(new winston.transports.Console({ silent: true }));
   }
 
+  // Monkey-patch `console` so that it does not write to the RPC (stdio) channel.
+  Object.keys(console).forEach((k: keyof Console) => {
+    (console as any)[k] = function () {
+      (logger as any)[k === 'log' ? 'info' : k].apply(logger, arguments);
+    };
+  });
+
   return logger;
 }