fix: console.log() writes to RPC channel

.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/README.md

@@ -0,0 +1 @@
+TODO: why is this a separate project? move this to packages/neovim

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

@@ -4,13 +4,13 @@ import * as fs from 'fs';
 import * as path from 'path';
 import * as http from 'http';
 
-import { attach } from 'neovim';
+import { NeovimClient, attach, findNvim } from 'neovim';
 
 describe('Node host', () => {
   const testdir = process.cwd();
-  let proc;
+  let proc: cp.ChildProcessWithoutNullStreams;
   let args;
-  let nvim;
+  let nvim: NeovimClient;
 
   beforeAll(async () => {
     const plugdir = path.resolve(__dirname);
@@ -36,10 +36,18 @@ describe('Node host', () => {
     let g:node_host_prog = '${path.resolve(plugdir, '../../neovim/bin/cli')}'
       `
     );
-    cp.spawnSync('nvim', args);
+
+    const minVersion = '0.9.5'
+    const nvimInfo = findNvim({ minVersion: minVersion });
+    const nvimPath = nvimInfo.matches[0]?.path;
+    if (!nvimPath) {
+      throw new Error(`nvim ${minVersion} not found`)
+    }
+
+    cp.spawnSync(nvimPath, args);
 
     proc = cp.spawn(
-      'nvim',
+      nvimPath,
       ['-u', nvimrc, '-i', 'NONE', '--headless', '--embed', '-n'],
       {}
     );
@@ -65,6 +73,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/package.json

@@ -59,14 +59,12 @@
     "@babel/preset-typescript": "^7.23.3",
     "@types/jest": "^29.5.12",
     "@types/node": "16.9.x",
-    "@types/which": "^3.0.3",
     "babel-jest": "^29.7.0",
     "jest": "^29.7.0",
     "jest-haste-map": "^29.7.0",
     "jest-resolve": "^29.6.1",
     "typedoc": "^0.25.7",
-    "typescript": "^5.3.3",
-    "which": "^4.0.0"
+    "typescript": "^5.3.3"
   },
   "scripts": {
     "doc": "typedoc --out doc --exclude '**/*.test.ts' src",
@@ -88,6 +86,9 @@
       "json",
       "node"
     ],
+    "setupFilesAfterEnv": [
+      "<rootDir>/src/testSetup.ts"
+    ],
     "testEnvironment": "node",
     "testRegex": "(/__tests__/.*|(\\.|/)(test|spec))\\.ts$",
     "coverageDirectory": "./coverage/",