console.log() crashes Nvim or exits node

[saidelike]

problem

Calling console.log() from the node plugin sends the data to nvim process. Because of this, it actually crashes the nvim process.

expected behavior

Calling console.log() from the node plugin should just log.

details

for instance with the code:

  const client = (await plugin.nvim) as NeovimClient;
  const ret = client.isApiReady;
  console.warn("isApiReady ", ret); // true
  console.log("This is sent to neovim");

I attach to nvim and set a breakpoint on the following line https://github.com/neovim/neovim/blob/a4290f462ed7dc81e17b09bd27877b106b24b6bd/src/nvim/msgpack_rpc/channel.c#L304

.text:00000001403190A1 ; 32:     size = 0i64;
.text:00000001403190A1                 mov     [rsp+1B8h+size], 0
.text:00000001403190AD ; 33:     read_ptr = rbuffer_read_ptr(rbuf, &size);
.text:00000001403190AD                 lea     rdx, [rsp+1B8h+size] ; read_count
.text:00000001403190B5                 mov     rcx, [rsp+1B8h+rbuf] ; buf
.text:00000001403190BD                 call    rbuffer_read_ptr
.text:00000001403190C2 ; 34:     p->read_ptr = read_ptr;
.text:00000001403190C2                 mov     rcx, [rsp+1B8h+p]
.text:00000001403190CA                 mov     [rcx+Unpacker.read_ptr], rax
.text:00000001403190D1 ; 35:     p->read_size = size;
.text:00000001403190D1                 mov     rax, [rsp+1B8h+p]
.text:00000001403190D9                 mov     rcx, [rsp+1B8h+size]
.text:00000001403190E1                 mov     [rax+Unpacker.read_size], rcx
.text:00000001403190E8 ; 36:     parse_msgpack(channel);
.text:00000001403190E8                 mov     rcx, [rsp+1B8h+channel] ; channel          <----- breakpoint here
.text:00000001403190ED                 call    parse_msgpack

for instance I use this breakpoint on Windows. we can see below that nvim receives the data that we try to log with console.log. Also note that it doesn't receive the data that we log with console.warn:

0:000> bp nvim!receive_msgpack+0x168 ".printf \"size: 0x%lx\\n\", poi(rax+6c0); db poi(rax+6b8); g"
size: 0x17
000001e4`a907b8d0  54 68 69 73 20 69 73 20-73 65 6e 74 20 74 6f 20  This is sent to 
000001e4`a907b8e0  6e 65 6f 76 69 6d 0a 6e-65 91 b4 30 35 2f 30 33  neovim.ne..05/03

Debug Error!

Program: C:\neovim\build\bin\nvim.exe

abort() has been called

(Press Retry to debug the application)
ModLoad: 00007ffb`26a30000 00007ffb`26a42000   C:\Windows\SYSTEM32\kernel.appcore.dll
ModLoad: 00007ffb`1ac50000 00007ffb`1acfc000   C:\Windows\SYSTEM32\TextShaping.dll
ModLoad: 00007ffa`fa4e0000 00007ffa`fa502000   C:\Users\Cedric\AppData\Local\Temp\8D05.tmp
ModLoad: 00007ffb`083f0000 00007ffb`08508000   C:\Program Files (x86)\Stardock\Groupy\groupy_64.dll
ModLoad: 00007ffb`2a300000 00007ffb`2a414000   C:\Windows\System32\MSCTF.dll
ModLoad: 00007ffb`29ab0000 00007ffb`29b7d000   C:\Windows\System32\OLEAUT32.dll
ModLoad: 00007ffb`19f20000 00007ffb`1a019000   C:\Windows\SYSTEM32\textinputframework.dll
ModLoad: 00007ffb`24890000 00007ffb`24beb000   C:\Windows\System32\CoreUIComponents.dll
ModLoad: 00007ffb`29500000 00007ffb`295ad000   C:\Windows\System32\SHCORE.dll
ModLoad: 00007ffb`254e0000 00007ffb`255d2000   C:\Windows\System32\CoreMessaging.dll
ModLoad: 00007ffb`27340000 00007ffb`27373000   C:\Windows\SYSTEM32\ntmarta.dll
ModLoad: 00007ffb`23e80000 00007ffb`23fd5000   C:\Windows\SYSTEM32\wintypes.dll
ModLoad: 00007ffb`25ae0000 00007ffb`25b0f000   C:\Windows\SYSTEM32\dwmapi.dll
(3128.8bf8): Break instruction exception - code 80000003 (first chance)
ucrtbased!issue_debug_notification+0x45:
00007ffa`f0017475 cc              int     3
0:000> k
 # Child-SP          RetAddr               Call Site
00 00000069`dad2e600 00007ffa`f0017613     ucrtbased!issue_debug_notification+0x45 [minkernel\crts\ucrt\src\appcrt\internal\report_runtime_error.cpp @ 28] 
01 00000069`dad2e650 00007ffa`f002d86d     ucrtbased!__acrt_report_runtime_error+0x13 [minkernel\crts\ucrt\src\appcrt\internal\report_runtime_error.cpp @ 154] 
02 00000069`dad2e6b0 00007ffa`f00334b5     ucrtbased!abort+0x1d [minkernel\crts\ucrt\src\appcrt\startup\abort.cpp @ 61] 
03 00000069`dad2e6f0 00007ffa`f0033027     ucrtbased!common_assert_to_stderr_direct+0xe5 [minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 161] 
04 00000069`dad2ebd0 00007ffa`f00310b8     ucrtbased!common_assert_to_stderr<wchar_t>+0x27 [minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 179] 
05 00000069`dad2ec30 00007ffa`f0033a1f     ucrtbased!common_assert<wchar_t>+0x68 [minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 420] 
06 00000069`dad2ec70 00007ff6`26af54b1     ucrtbased!_wassert+0x2f [minkernel\crts\ucrt\src\appcrt\startup\assert.cpp @ 444] 
07 00000069`dad2eca0 00007ff6`26af55ee     nvim!rbuffer_consumed+0x41 [C:\neovim\src\nvim\rbuffer.c @ 126] 
08 00000069`dad2ece0 00007ff6`26a5912c     nvim!rbuffer_consumed_compact+0x4e [C:\neovim\src\nvim\rbuffer.c @ 149] 
09 00000069`dad2ed10 00007ff6`26915f0e     nvim!receive_msgpack+0x1ac [C:\neovim\src\nvim\msgpack_rpc\channel.c @ 311] 
0a 00000069`dad2eed0 00007ff6`26916099     nvim!read_event+0xbe [C:\neovim\src\nvim\event\rstream.c @ 193] 
0b 00000069`dad2ef30 00007ff6`26915c23     nvim!invoke_read_cb+0x139 [C:\neovim\src\nvim\event\rstream.c @ 204] 
0c 00000069`dad2f090 00007ff6`26d774fb     nvim!read_cb+0x153 [C:\neovim\src\nvim\event\rstream.c @ 134] 
0d 00000069`dad2f110 00007ff6`26d729fd     nvim!uv__pipe_read_data+0x15b [C:\neovim\.deps\build\src\libuv\src\win\pipe.c @ 1929] 
0e 00000069`dad2f1d0 00007ff6`26d69a5d     nvim!uv__process_pipe_read_req+0x26d [C:\neovim\.deps\build\src\libuv\src\win\pipe.c @ 2053] 
0f 00000069`dad2f280 00007ff6`26d68ccb     nvim!uv__process_reqs+0x11d [C:\neovim\.deps\build\src\libuv\src\win\req-inl.h @ 159] 
10 00000069`dad2f2f0 00007ff6`26911d68     nvim!uv_run+0x16b [C:\neovim\.deps\build\src\libuv\src\win\core.c @ 658] 
11 00000069`dad2f330 00007ff6`26911df1     nvim!loop_uv_run+0xb8 [C:\neovim\src\nvim\event\loop.c @ 65] 
12 00000069`dad2f380 00007ff6`26ac025a     nvim!loop_poll_events+0x21 [C:\neovim\src\nvim\event\loop.c @ 86] 
13 00000069`dad2f3c0 00007ff6`26abf377     nvim!inbuf_poll+0x18a [C:\neovim\src\nvim\os\input.c @ 467] 
14 00000069`dad2f440 00007ff6`26ba7d66     nvim!os_inchar+0x1c7 [C:\neovim\src\nvim\os\input.c @ 150] 
15 00000069`dad2f490 00007ff6`26a643f9     nvim!state_enter+0x106 [C:\neovim\src\nvim\state.c @ 82] 
16 00000069`dad2f500 00007ff6`269e80a6     nvim!normal_enter+0xe9 [C:\neovim\src\nvim\normal.c @ 517] 
17 00000069`dad2f640 00007ff6`26db3179     nvim!wmain+0xf36 [C:\neovim\src\nvim\main.c @ 654] 
18 00000069`dad2f990 00007ff6`26db301e     nvim!invoke_main+0x39 [d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 91] 
19 00000069`dad2f9e0 00007ff6`26db2ede     nvim!__scrt_common_main_seh+0x12e [d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 288] 
1a 00000069`dad2fa50 00007ff6`26db320e     nvim!__scrt_common_main+0xe [d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 331] 
1b 00000069`dad2fa80 00007ffb`29997344     nvim!wmainCRTStartup+0xe [d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\startup\exe_wmain.cpp @ 17] 
1c 00000069`dad2fab0 00007ffb`2ab626b1     KERNEL32!BaseThreadInitThunk+0x14
1d 00000069`dad2fae0 00000000`00000000     ntdll!RtlUserThreadStart+0x21

At the end the problem I was describing in neovim/neovim#23781 (comment) was due to me using console.log...

[saidelike]

console.info and console.debug have the same problem as console.log.

console.error and console.warn don't have that problem.

[justinmk]

console.error and console.warn don't have that problem.

Those write to stderr, not stdout, so they don't interfere with the RPC channel.

expected behavior: Calling console.log() from the node plugin should just log.

So our "monkey patching" of console.log isn't working? #202 (comment)

[saidelike]

So our "monkey patching" of console.log isn't working? #202 (comment)

That's my guess too.

[justinmk]

const client = (await plugin.nvim) as NeovimClient;
const ret = client.isApiReady;
console.warn("isApiReady ", ret); // true
console.log("This is sent to neovim");

Does the demo code in the readme also trigger the issue for you?

I don't see anywhere in our code where we're patching console.log, so I think this hasn't worked for awhile. Unless winston does it implicitly (but doesn't seem so: winstonjs/winston#309).

[justinmk]

2d47447 removed "sandboxing" and looks like it accidentally also removed the console.log patching:

// Redirect console calls into logger
Object.keys(console).forEach((k: keyof Console) => {
  if (k === 'log') {
    sandbox.console.log = createDebugFunction(filename);
  } else if (k in logger) {
    sandbox.console[k] = logger[k];
  }
});

[justinmk]

Can you see if this patch fixes the issue?

diff --git a/packages/neovim/src/utils/logger.ts b/packages/neovim/src/utils/logger.ts
index 8461e96b222f..e3f7580eccdb 100644
--- a/packages/neovim/src/utils/logger.ts
+++ b/packages/neovim/src/utils/logger.ts
@@ -31,6 +31,19 @@ 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;
 }

[justinmk]

Can you try #332 ?