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: 33e6559
• You already are aware, but for reference, node-client seems to monkeypatch console with winston logger:

  node-client/README.md

  Line 68 in c4ba031

  `console` has been replaced by a `winston` interface and `console.log` will call `winston.info`.

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:

node-client/packages/neovim/src/utils/logger.ts

Lines 21 to 27 in c4ba031

	if (process.env.ALLOW_CONSOLE) {
	logger.add(
	new winston.transports.Console({
	format: winston.format.simple(),
	})
	);
	}

[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.<anonymous> (C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\NvimPlugin.js:156:41)\n    at Generator.next (<anonymous>)\n    at C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\NvimPlugin.js:8:71\n    at new Promise (<anonymous>)\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.<anonymous> (C:\\Users\\User\\AppData\\Roaming\\npm\\node_modules\\neovim\\lib\\host\\index.js:88:27)\n    at Generator.next (<anonymous>)\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:

node-client/README.md

Line 95 in 053a222

The host replaces `console` with a `winston` interface, so `console.log` will call `winston.info`.

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. #202 (comment)