logging: ALLOW_CONSOLE should write to stderr instead of stdout, to avoid breaking stdio RPC channel

[saidelike]

As detailed in #342, there is still a problem of node-client sending data to nvim.exe in some scenarios with node-client 5.1.0. The problem described here is that after the #329 patch, when data is sent to nvim.exe, it does not crash nvim.exe anymore, however node.exe is terminated instead.

environment

neovim version (nightly from
https://github.com/neovim/neovim/releases/):

NVIM v0.10.0-dev-2698+g00e71d3da
Build type: RelWithDebInfo
LuaJIT 2.1.1710088188

node-client version: 5.1.0

Environment variable defined: ALLOW_CONSOLE=1 (without it, it does not trigger)

node: https://nodejs.org/dist/latest-v21.x/node-v21.7.1-x64.msi

nvim.exe receiving the data but not crashing

0:008> bp nvim!receive_msgpack+0xad ".printf \"size: 0x%lx\\n\", poi(rsi+6c0); db poi(rsi+6b8); g"
0:008> g
size: 0x16
00000000`00000000  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000010  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000020  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000030  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000040  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000050  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000060  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
00000000`00000070  ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ??  ????????????????
size: 0x17
00000105`39fe8e76  0a 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8e86  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8e96  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8ea6  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8eb6  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8ec6  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8ed6  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
00000105`39fe8ee6  00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00  ................
(f84.4b74): Unknown exception - code e24c4a02 (first chance)

then breaking manually into debugger:

ntdll!DbgBreakPoint:
00007ffa`199b0b10 cc              int     3
0:001> k
 # Child-SP          RetAddr               Call Site
00 00000004`027ffb68 00007ffa`199dca0e     ntdll!DbgBreakPoint
01 00000004`027ffb70 00007ffa`18f17344     ntdll!DbgUiRemoteBreakin+0x4e
02 00000004`027ffba0 00007ffa`199626b1     KERNEL32!BaseThreadInitThunk+0x14
03 00000004`027ffbd0 00000000`00000000     ntdll!RtlUserThreadStart+0x21

node.exe terminated

0:000> k
 # Child-SP          RetAddr               Call Site
00 000000de`cc7ff788 00007ffa`1996da98     ntdll!NtTerminateProcess+0x14
01 000000de`cc7ff790 00007ffa`18f1e3bb     ntdll!RtlExitUserProcess+0xb8
02 000000de`cc7ff7c0 00007ff6`30c19ff9     KERNEL32!FatalExit+0xb
03 000000de`cc7ff7f0 00007ff6`30c19fc4     node_exe!exit_or_terminate_process+0x31 [minkernel\crts\ucrt\src\appcrt\startup\exit.cpp @ 137] 
04 000000de`cc7ff820 00007ff6`30c046b7     node_exe!common_exit+0xc4 [minkernel\crts\ucrt\src\appcrt\startup\exit.cpp @ 274] 
05 000000de`cc7ff880 00007ffa`18f17344     node_exe!__scrt_common_main_seh+0x173 [D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 295] 
06 000000de`cc7ff8c0 00007ffa`199626b1     KERNEL32!BaseThreadInitThunk+0x14
07 000000de`cc7ff8f0 00000000`00000000     ntdll!RtlUserThreadStart+0x21

[justinmk]

Not sure how this is different from #342

ALLOW_CONSOLE=1 by definition will break a RPC channel because the "console" is stdout, which is also the RPC channel.

It's documented at https://github.com/neovim/node-client?tab=readme-ov-file#logging but I'll make it clearer.

Proposal

We could try writing to stderr instead of stdout.