Merge #345 logging: cleanup

Author: justinmk

.github/workflows/ci.yml

@@ -20,15 +20,15 @@ jobs:
       fail-fast: false
       matrix:
         node: ['14', '16', '18']
-        os: ['ubuntu-latest', 'macos-11', 'windows-latest']
+        os: ['ubuntu-latest', 'macos-latest', 'windows-latest']
         include:
         - os: ubuntu-latest
           NIGHTLY: nvim-linux64.tar.gz
           NVIM_BIN_PATH: nvim-linux64/bin
           EXTRACT: tar xzf
-        - os: macos-11
-          NIGHTLY: nvim-macos.tar.gz
-          NVIM_BIN_PATH: nvim-macos/bin
+        - os: macos-latest
+          NIGHTLY: nvim-macos-x86_64.tar.gz
+          NVIM_BIN_PATH: nvim-macos-x86_64/bin
           EXTRACT: tar xzf
         - os: windows-latest
           NIGHTLY: nvim-win64.zip

README.md

@@ -33,7 +33,8 @@ The `neovim` package provides these functions:
     - 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.
+- Set the `$ALLOW_CONSOLE` env var to (also) write logs to stdout. **This will break any (stdio) RPC
+  channel** because logs written to stdout are invalid RPC messages.
 
 ### Quickstart: connect to Nvim
 
@@ -48,6 +49,9 @@ Following is a complete, working example.
    ALLOW_CONSOLE=1 node demo.mjs
    ```
     - `$ALLOW_CONSOLE` env var must be set, because logs are normally not printed to stdout.
+        - Note: `$ALLOW_CONSOLE` is only for demo purposes. It cannot be used for remote plugins or
+          whenever stdio is an RPC channel, because writing logs to stdout would break the RPC
+          channel.
     - Script:
      ```js
      import * as child_process from 'node:child_process'

packages/neovim/src/api/client.ts

@@ -67,25 +67,26 @@ export class NeovimClient extends Neovim {
     resp: any,
     ...restArgs: any[]
   ) {
-    this.logger.info('handleRequest: ', method);
     // If neovim API is not generated yet and we are not handle a 'specs' request
     // then queue up requests
     //
     // Otherwise emit as normal
     if (!this.isApiReady && method !== 'specs') {
+      this.logger.info('handleRequest (queued): %s', method);
       this.requestQueue.push({
         type: 'request',
         args: [method, args, resp, ...restArgs],
       });
     } else {
+      this.logger.info('handleRequest: %s', method);
       this.emit('request', method, args, resp);
     }
   }
 
   emitNotification(method: string, args: any[]) {
     if (method.endsWith('_event')) {
       if (!method.startsWith('nvim_buf_')) {
-        this.logger.error('Unhandled event: ', method);
+        this.logger.error('Unhandled event: %s', method);
         return;
       }
       const shortName = method.replace(REGEX_BUF_EVENT, '$1');
@@ -112,7 +113,7 @@ export class NeovimClient extends Neovim {
   }
 
   handleNotification(method: string, args: VimValue[], ...restArgs: any[]) {
-    this.logger.info('handleNotification: ', method);
+    this.logger.info('handleNotification: %s', method);
     // If neovim API is not generated yet then queue up requests
     //
     // Otherwise emit as normal
@@ -198,9 +199,13 @@ export class NeovimClient extends Neovim {
 
         return true;
       } catch (err) {
-        this.logger.error(`Could not dynamically generate neovim API: ${err}`, {
-          error: err,
-        });
+        this.logger.error(
+          `Could not dynamically generate neovim API: %s: %O`,
+          err.name,
+          {
+            error: err,
+          }
+        );
         this.logger.error(err.stack);
         return null;
       }

packages/neovim/src/host/index.ts

@@ -1,4 +1,3 @@
-import * as util from 'node:util';
 import { attach } from '../attach';
 import { loadPlugin, LoadPluginOptions } from './factory';
 import { NvimPlugin } from './NvimPlugin';
@@ -52,7 +51,7 @@ export class Host {
   async handlePlugin(method: string, args: any[]) {
     // ignore methods that start with nvim_ prefix (e.g. when attaching to buffer and listening for notifications)
     if (method.startsWith('nvim_')) return null;
-    this.nvim?.logger.debug('host.handlePlugin: ', method);
+    this.nvim?.logger.debug('host.handlePlugin: %s', method);
 
     // Parse method name
     const procInfo = method.split(':');
@@ -90,11 +89,11 @@ export class Host {
     const specs = (plugin && plugin.specs) || [];
     this.nvim?.logger.debug(JSON.stringify(specs));
     res.send(specs);
-    this.nvim?.logger.debug(`specs: ${util.inspect(specs)}`);
+    this.nvim?.logger.debug('specs: %O', specs);
   }
 
   async handler(method: string, args: any[], res: Response) {
-    this.nvim?.logger.debug('request received: ', method);
+    this.nvim?.logger.debug('request received: %s', method);
     // 'poll' and 'specs' are requests by neovim,
     // otherwise it will
     if (method === 'poll') {