Rare hang / infinite loop writing line containing emoji unicode characters

[adamwalling]

Windows Terminal version

1.22.11141.0

Windows build number

10.0.26100.3775

Other Software

Output coming from a node.js script

Steps to reproduce

Unfortunately I cannot reproduce this consistently. I had noticed this hanging on occasion, and would have to close the window, and OpenConsole.exe would remain spinning a core until I terminated the process. Eventually I decided to grab a full memory dump file next time it occurred, though I have not been able to reproduce again. I do still have the full memory dump available.

The underlying node.js script is simply logging operations to the console.

In this case, it is writing the text: "countByTag 🎵 Oblivion - Grimes [1]: 0.215ms\r\n"

Expected Behavior

Text should output without hanging the console.

Actual Behavior

The console hangs and becomes unresponsive. A simple analysis of the memory dump follows:

OpenConsole!WriteCharsLegacy is writing the text "countByTag 🎵 Oblivion - Grimes [1]: 0.215ms\r\n"

this calls _writeCharsLegacyUnprocessed which appears to get stuck in the while loop while (!state.text.empty())

Presumably the first textBuffer.Replace call in this loop succeeds, because by the time there is a hang the state has advanced to the first emoji character in the string; that is, state.text is now pointing to the first emoji / unicode character in the text: "🎵 Oblivion - Grimes [1]: 0.215ms\r\n"

Note that the emoji is made of two unicode chars, which I have a hunch is the underlying issue.

state.columnBegin is 126, .columnLimit is 127, columnEnd is 127, columnBeginDirty is 126, columnEndDirty is 127 (all decimal numbers here). The TextBuffer.width is also 127

I grabbed two dumps a few seconds apart and both are in pretty much the same area, one was in ROW::WriteHelper::Finish and one was ROW::ReplaceText, but notably there does not seem to be any change/progress in the state variable.

I think somehow textBuffer.Replace is not advancing the text for some reason due to an edge case here, which causes it to never be empty, and therefore spin forever.

I can provide a dump file securely if desired.

stack trace:

 # Child-SP          RetAddr               Call Site
00 (Inline Function) --------`--------     OpenConsole!ROW::WriteHelper::Finish(void)+0x3c [C:\__w\1\s\src\buffer\out\Row.cpp @ 860] 
01 0000003f`b86ff0a0 00007ff7`e129e447     OpenConsole!ROW::ReplaceText(
			struct RowWriteState * state = 0x00000000`00000000)+0x188 [C:\__w\1\s\src\buffer\out\Row.cpp @ 620] 
02 0000003f`b86ff160 00007ff7`e1294e0a     OpenConsole!TextBuffer::Replace(
			int row = 0n26, 
			class TextAttribute * attributes = 0x000001de`0311adec, 
			struct RowWriteState * state = 0x0000003f`b86ff1e8)+0x37 [C:\__w\1\s\src\buffer\out\textBuffer.cpp @ 531] 
03 0000003f`b86ff1b0 00007ff7`e1294ffa     OpenConsole!_writeCharsLegacyUnprocessed(
			class SCREEN_INFORMATION * screenInfo = 0x000001de`03110430, 
			class std::basic_string_view<wchar_t,std::char_traits<wchar_t> > * text = <Value unavailable error>, 
			<Unimplemented error> psScrollY = <Unimplemented error>)+0x9a [C:\__w\1\s\src\host\_stream.cpp @ 133] 
04 0000003f`b86ff250 00007ff7`e12957f6     OpenConsole!WriteCharsLegacy(
			class SCREEN_INFORMATION * screenInfo = 0x000001de`03110430, 
			class std::basic_string_view<wchar_t,std::char_traits<wchar_t> > * text = 0x0000003f`b86ff378 "countByTag 🎵 Oblivion - Grimes [1]: 0.215ms
", 
			<Unimplemented error> psScrollY = <Unimplemented error>)+0x14a [C:\__w\1\s\src\host\_stream.cpp @ 195] 
05 0000003f`b86ff350 00007ff7`e129588c     OpenConsole!DoWriteConsole(
			wchar_t * pwchBuffer = 0x000001de`03166510 "countByTag ???", 
			unsigned int64 * pcbBuffer = 0x0000003f`b86ff3f0, 
			class SCREEN_INFORMATION * screenInfo = 0x000001de`03110430, 
			class std::unique_ptr<WriteData,std::default_delete<WriteData> > * waiter = 0x0000003f`b86ff460 empty)+0xe6 [C:\__w\1\s\src\host\_stream.cpp @ 436] 
06 0000003f`b86ff3d0 00007ff7`e129618a     OpenConsole!WriteConsoleWImplHelper(
			class SCREEN_INFORMATION * context = 0x000001de`03110430, 
			class std::basic_string_view<wchar_t,std::char_traits<wchar_t> > * buffer = 0x0000003f`b86ff450 "countByTag 🎵 Oblivion - Grimes [1]: 0.215ms
", 
			unsigned int64 * read = 0x0000003f`b86ff510, 
			class std::unique_ptr<WriteData,std::default_delete<WriteData> > * waiter = 0x0000003f`b86ff460 empty)+0x5c [C:\__w\1\s\src\host\_stream.cpp @ 478] 
07 0000003f`b86ff430 00007ff7`e12d6b89     OpenConsole!ApiRoutines::WriteConsoleWImpl(
			class SCREEN_INFORMATION * context = <Value unavailable error>, 
			class std::basic_string_view<wchar_t,std::char_traits<wchar_t> > * buffer = 0x0000003f`b86ff500 "countByTag 🎵 Oblivion - Grimes [1]: 0.215ms
", 
			unsigned int64 * read = 0x0000003f`b86ff510, 
			class std::unique_ptr<IWaitRoutine,std::default_delete<IWaitRoutine> > * waiter = 0x0000003f`b86ff4f0 empty)+0x8a [C:\__w\1\s\src\host\_stream.cpp @ 705] 
08 0000003f`b86ff4a0 00007ff7`e12de4cd     OpenConsole!ApiDispatchers::ServerWriteConsole(
			struct _CONSOLE_API_MSG * m = 0x0000003f`b86ff670, 
			int * pbReplyPending = 0x0000003f`b86ff5b8)+0x229 [C:\__w\1\s\src\server\ApiDispatchers.cpp @ 392] 
09 0000003f`b86ff570 00007ff7`e12d4607     OpenConsole!ApiSorter::ConsoleDispatchRequest(
			struct _CONSOLE_API_MSG * Message = 0x0000003f`b86ff670)+0xbd [C:\__w\1\s\src\server\ApiSorter.cpp @ 174] 
0a (Inline Function) --------`--------     OpenConsole!IoDispatchers::ConsoleDispatchRequest(void)+0x8 [C:\__w\1\s\src\server\IoDispatchers.cpp @ 582] 
0b 0000003f`b86ff5e0 00007ff7`e126f136     OpenConsole!IoSorter::ServiceIoOperation(
			struct _CONSOLE_API_MSG * pMsg = <Value unavailable error>, 
			struct _CONSOLE_API_MSG ** ReplyMsg = <Value unavailable error>)+0x67 [C:\__w\1\s\src\server\IoSorter.cpp @ 100] 
0c 0000003f`b86ff630 00007ff9`1aede8d7     OpenConsole!ConsoleIoThread(
			void * lpParameter = <Value unavailable error>)+0x1f6 [C:\__w\1\s\src\host\srvinit.cpp @ 990] 
0d 0000003f`b86ff8b0 00007ff9`1c2b14fc     kernel32!BaseThreadInitThunk+0x17
0e 0000003f`b86ff8e0 00000000`00000000     ntdll!RtlUserThreadStart+0x2c

[lhecker]

We rarely get such detailed reports. Thank you so much already!

Would you be able to send the dump to my personal mail address (you find it on my GitHub profile)? Last time someone tried to send me a dump to <my username>@microsoft.com it seemingly never got through the corporate filter. You can try it of course, if you'd like.

I'm asking because I'm interested in the exact cursor position and text buffer state. My gut instinct is telling me that this bug occurs because your string gets split up in 2 or more write calls and the second one doesn't properly join with the preceding one.

[adamwalling]

Not a problem; I sent you a link to it on my personal site since it was too large for email. Hopefully you get it! And if I encounter it again and get another I'll make sure to grab it.

[lhecker]

While I haven't found the exact location of the bug yet, I can already tell you what triggers it:
The application you're running (or some application before it) called SetConsoleMode() on the output handle without specifying ENABLE_PROCESSED_OUTPUT. When you do that, escape sequences, etc., are written literally into the text buffer instead of being interpreted.

You can see that the flag is not set, because the WriteCharsLegacy call is on line 195. If you correlate that with the corresponding source code you land here: https://github.com/microsoft/terminal/blob/v1.22.11141.0/src/host/_stream.cpp#L195

If you go up in the callstack to WriteHelper::Finish(), you look into this->_chars and you'll see that the buffer is already filled with literal VT sequences (= they weren't interpreted).

In short, check where ENABLE_PROCESSED_OUTPUT gets reset and it should be "fixed". If it's not obvious where it's coming from, you can set a breakpoint on ApiDispatchers::ServerSetConsoleMode. Let me know if you need any help!

[adamwalling]

Thanks for the info! The console output is actually coming from a node.js project, basically a simple electron music app, though it may be doing things concurrently and/or sharing the output handle among processes perhaps. Or could be something with both stderr and stdout going to the console at once. That said, these are console.log() calls for debug output which normally are colored so this would make sense. Looks like node.js is using libuv for its tty stuff and certainly looks like a complicated issue. Regardless, if I ever figure out a way to reproduce it I'll let you know and/or the relevant projects.