Not seeing logs from my plugin

[ChristianChiarulli]

I set NVIM_NODE_LOG_FILE="$HOME/nvim_node_log" and I see logging from the node client but not from any of the log statements in my plugin.

Example logs I'm seeing:

{"level":"debug","message":"getPlugin.alwaysInit"}
{"level":"debug","message":"request -> neovim.api.nvim_out_write"}
{"level":"debug","message":"response -> neovim.api.nvim_out_write: null"}
{"level":"debug","message":"host.disconnected"}
{"level":"debug","message":"host.start"}
{"level":"info","message":"handleRequest: "}
{"level":"debug","message":"request received: "}
{"level":"info","message":"handleRequest: "}
{"level":"debug","message":"host.start"}

I would expect to see the log statements defined in the plugin as well. To reproduce just check if the logs are working in the example bundled with this repo: https://github.com/neovim/node-client/tree/master/examples/rplugin/node/nvim-example

I'm also not sure if ALLOW_CONSOLE has anything to do with this but whenever I set it to 1 for instance but that doesn't seem to do anything either.

[justinmk]

Just some notes:

• I recently updated the winston dep, maybe it's worth trying again: https://github.com/neovim/node-client/commit/33e6559d032c29c13206a8cfdcb9a8f64b46ed65
• You already are aware, but for reference, node-client seems to monkeypatch console with winston logger: https://github.com/neovim/node-client/blob/c4ba03108dbf5360d17205f43f17a717de95cfa7/README.md?plain=1#L68

not sure if ALLOW_CONSOLE has anything to do with this but whenever I set it to 1 for instance but that doesn't seem to do anything either.

For reference: https://github.com/neovim/node-client/blob/c4ba03108dbf5360d17205f43f17a717de95cfa7/packages/neovim/src/utils/logger.ts#L21-L27

[ChristianChiarulli]

This is what I'm seeing now:

Log:

ERR 2023-07-27T00:03:39.147 nvim.40391.0 chan_close_with_error:626: RPC: failed to decode msgpack

Code:

module.exports = plugin => {
  plugin.setOptions({ dev: false });

  plugin.registerCommand('EchoMessage', async () => {
    try {
      console.log('EchoMessage'); // <---- this is what is causing the error
      await plugin.nvim.outWrite('Dayman (ah-ah-ah) \n');
    } catch (err) {
      console.error(err);
    }
  }, { sync: false });
};

Node version: v16.18.0 Neovim version: NVIM v0.10.0-dev-722+g7668f89d5 Node Client from checkhealth:

Node.js provider (optional) ~
- Node.js: v16.18.0
- Nvim node.js host: /Users/chris/Library/Application Support/fnm/node-versions/v16.18.0/installation/lib/node_modules/neovim/bin/cli.js
- OK Latest "neovim" npm/yarn/pnpm package is installed: 4.10.1

[justinmk]

chan_close_with_error:626: RPC: failed to decode msgpack

That sounds like something is writing to the channel, which can happen if code prints to stdout while you are using a stdio channel (as opposed to unix socket / named pipe / TCP). If console isn't actually getting patched, I guess it would write to stdout? Can you confirm whether console is actually getting monkeypatched?

[saidelike]

I think I have the same problem with the latest version and on Windows

• console.log crashes neovim
• console.error and console.info do nothing

details

I have tried to set NVIM_NODE_LOG_LEVEL to info/debug and NVIM_NODE_LOG_FILE to a valid path. I get logs, but none of the thing I try to log are actually there: ``` {"level":"debug","message":"host.start"} {"level":"info","message":"handleRequest: "} {"level":"debug","message":"request received: "} {"level":"info","message":"handleNotification: "} {"level":"debug","message":"host.handlePlugin: "} {"level":"debug","message":"createPlugin.C:/Users/User/AppData/Local/nvim/rplugin/node/nvim-example.clearCache: true"} {"level":"debug","message":"getPlugin.alwaysInit"} {"level":"info","message":"handleNotification: "} {"level":"debug","message":"host.handlePlugin: "} {"level":"debug","message":"createPlugin.C:/Users/User/AppData/Local/nvim/rplugin/node/nvim-example.clearCache: true"} {"level":"debug","message":"getPlugin.alwaysInit"} {"level":"debug","message":"host.disconnected"} {"level":"info","message":"handleRequest: "} {"level":"info","message":"handleNotification: "} {"level":"info","message":"handleNotification: "} {"level":"info","message":"handleNotification: "} {"level":"info","message":"handleNotification: "} {"level":"info","message":"handleRequest: "} {"level":"info","message":"handleRequest: "} {"level":"info","message":"handleRequest: "} {"level":"info","message":"handleRequest: "} {"level":"info","message":"handleNotification: "} {"level":"info","message":"handleNotification: "} {"level":"error","message":"Error in plugin for function:GetLines: winston is not defined (file: C:/Users/User/AppData/Local/nvim/rplugin/node/nvim-example, stack: ReferenceError: winston is not defined\n at plugin.registerFunction.sync [as fn] (C:\\Users\\User\\AppData\\Local\\nvim\\rplugin\\node\\nvim-example\\index.js:34:5)\n at NvimPlugin. (C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\NvimPlugin.js:156:41)\n at Generator.next ()\n at C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\NvimPlugin.js:8:71\n at new Promise ()\n at __awaiter (C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\NvimPlugin.js:4:12)\n at NvimPlugin.handleRequest (C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\NvimPlugin.js:134:16)\n at Host. (C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\index.js:88:27)\n at Generator.next ()\n at C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\index.js:31:71)"} {"level":"info","message":"Unhandled Rejection at:"} {"level":"info","message":"handleNotification: "} ``` I have tried different things ``` // this crashes neovim-qt // console.log('Line:'); // this it does not crash but I don't see the log yet // console.error('Line:'); // console.error(plugin.nvim.getLine()); // console.warn(plugin.nvim.getLine()); console.error("hello"); // Error in plugin for function:GetLines: winston is not defined.... // winston.info(plugin.nvim.getLine()); // winston.info('Line:'); // this crashes neovim-qt // console.info(plugin.nvim.getLine()); ```

[justinmk]

The readme mentions: https://github.com/neovim/node-client/blob/053a222b474c21217a0d96cc8d87c44792101d9c/README.md#L95

I'm guessing this isn't working or it's happening too late.

console.log crashes neovim

That's another hint that the console monkey-patching isn't in effect, thus it writes to the msgpack-RPC channel. https://github.com/neovim/node-client/issues/202#issuecomment-1656430295