DDoouubbllee cchhaarraacctteerr oouuttppuutt iinn ssoommee ccaasseess :-) #20132

@DHowett commented on GitHub (Jun 22, 2023):

This looks a lot like the classic threading issue of intermingling multiple concurrent outputs. Hmm

@DHowett commented on GitHub (Jun 22, 2023): This looks a lot like the classic threading issue of intermingling multiple concurrent outputs. _Hmm_

claunia commented

@levicki commented on GitHub (Jun 22, 2023):

@DHowett I hereby apologize for the (somewhat juvenile) attempt at humor in the issue title and letting you guys know that I don't mind if it gets changed because it bothers someone.

I don't think there's more than one instance of nmake.exe running, but each cl.exe instance is launched using a new cmd.exe instance so maybe that can be the issue somehow?

I have already asked OpenSSL developers to update the Windows makefiles to use batched compilation so we can take advantage of /MP flag, but so far no success on that front.

@levicki commented on GitHub (Jun 22, 2023): @DHowett I hereby apologize for the (somewhat juvenile) attempt at humor in the issue title and letting you guys know that I don't mind if it gets changed because it bothers someone. I don't think there's more than one instance of `nmake.exe` running, but each `cl.exe` instance is launched using a new `cmd.exe` instance so maybe that can be the issue somehow? I have already asked OpenSSL developers to update the Windows makefiles to use batched compilation so we can take advantage of `/MP` flag, but so far no success on that front.

claunia commented

@DHowett commented on GitHub (Jun 22, 2023):

I hereby apologize for the (somewhat juvenile) attempt at humor in the issue title and letting you guys know that I don't mind if it gets changed because it bothers someone.

Aw heck, no apology needed. This is up there with other bangers of issues on our repo like "display unfriendly!" and "WSL emjoy is ? ? ? " 😁

@DHowett commented on GitHub (Jun 22, 2023): > I hereby apologize for the (somewhat juvenile) attempt at humor in the issue title and letting you guys know that I don't mind if it gets changed because it bothers someone. Aw heck, no apology needed. This is up there with other bangers of issues on our repo like "display unfriendly!" and "WSL emjoy is ? ? ? " 😁

claunia commented

@levicki commented on GitHub (Jun 22, 2023):

@DHowett And here I was hoping that this one at least explained the issue in a nutshell :-)

@levicki commented on GitHub (Jun 22, 2023): @DHowett And here I was hoping that this one at least explained the issue in a nutshell :-)

claunia commented

@DHowett commented on GitHub (Jun 22, 2023):

So, this may help.

Can you capture a trace with the Terminal.wprp!DefTerm.Verbose profile in this repository?

Info here: https://github.com/microsoft/terminal/wiki/Toubleshooting-Tips#capturing-a-debug-etl-trace

(however, I suggest wpr -start terminal.wprp!DefTerm.Verbose -filemode so that no events get dropped!)

DISCLAIMER: This trace will contain information that is written to any console session on your machine for the captured duration. We also don't have per-process API attribution, which is... if not outright funny, at least a little bit humorous.

It looks like this in WPA:

@DHowett commented on GitHub (Jun 22, 2023): So, this may help. Can you capture a trace with the `Terminal.wprp!DefTerm.Verbose` profile in this repository? Info here: https://github.com/microsoft/terminal/wiki/Toubleshooting-Tips#capturing-a-debug-etl-trace (however, I suggest `wpr -start terminal.wprp!DefTerm.Verbose -filemode` so that no events get dropped!) DISCLAIMER: This trace will contain information that is written to _any console session on your machine for the captured duration._ We also don't have per-process API attribution, which is... if not outright funny, at least a little bit humorous. It looks like this in WPA: <img width="742" alt="image" src="https://github.com/microsoft/terminal/assets/189190/649412df-5499-4af5-88d8-6dd4a2f51318">

claunia commented

@levicki commented on GitHub (Jun 22, 2023):

I could give it a try tomorrow evening.

@levicki commented on GitHub (Jun 22, 2023): I could give it a try tomorrow evening.

claunia commented

@levicki commented on GitHub (Jun 25, 2023):

@DHowett Sorry for the delay, here is the ETL trace you requested.

terminal-trace.zip

If you want to try to reproduce it yourself, here is the batch file I use for building OpenSSL:

@echo off
set OPENSSL_DIR=C:\BUILD\OpenSSL
set GIT_HASH=2cf4e90eaaf7402bf038b158dbdacd0a15561fb7
IF EXIST "%OPENSSL_DIR%-source" RD /S /Q "%OPENSSL_DIR%-source"
IF EXIST "%OPENSSL_DIR%-build" RD /S /Q "%OPENSSL_DIR%-build"
git clone https://github.com/openssl/openssl.git "%OPENSSL_DIR%-source"
cd "%OPENSSL_DIR%-source"
git checkout %GIT_HASH%
mkdir "%OPENSSL_DIR%-build"
cd "%OPENSSL_DIR%-build"
perl "%OPENSSL_DIR%-source\Configure" VC-WIN32 --release --prefix="C:\Program Files (x86)\OpenSSL" --openssldir="C:\Program Files (x86)\OpenSSL" enable-static-engine
nmake
nmake test
nmake install
cd "%OPENSSL_DIR%"
rd /s /q "%OPENSSL_DIR%-source"
rd /s /q "%OPENSSL_DIR%-build"
rd /s /q "C:\Program Files (x86)\OpenSSL\certs"
rd /s /q "C:\Program Files (x86)\OpenSSL\html"
rd /s /q "C:\Program Files (x86)\OpenSSL\misc"
rd /s /q "C:\Program Files (x86)\OpenSSL\private"
rd /s /q "C:\Program Files (x86)\OpenSSL\lib\engines-3"
rd /s /q "C:\Program Files (x86)\OpenSSL\lib\ossl-modules"
del /f /q "C:\Program Files (x86)\OpenSSL\bin\c_rehash.pl"
del /f /q "C:\Program Files (x86)\OpenSSL\openssl.*"
del /f /q "C:\Program Files (x86)\OpenSSL\ct_log_list.*"
set OPENSSL_DIR=
:SKIP

You can interrupt it once you see nmake running the compiler. Note however that you need to have Perl (I use Strawberry Perl), and nasm (both should be in PATH).

No idea if that has anything to do with it, but the way I discovered this issue is that I mistakenly run my 32-bit OpenSSL build batch file (reproduced above) in a 64-bit Visual Studio environment, and naturally I wanted to stop it so I hit Ctrl+C.

I was worried that I might have to try a couple of times (i.e. that it might be timing-sensitive), but oddly enough I was able to reproduce it for the ETL trace on the first try.

@levicki commented on GitHub (Jun 25, 2023): @DHowett Sorry for the delay, here is the ETL trace you requested. [terminal-trace.zip](https://github.com/microsoft/terminal/files/11859558/terminal-trace.zip) If you want to try to reproduce it yourself, here is the batch file I use for building OpenSSL: ``` @echo off set OPENSSL_DIR=C:\BUILD\OpenSSL set GIT_HASH=2cf4e90eaaf7402bf038b158dbdacd0a15561fb7 IF EXIST "%OPENSSL_DIR%-source" RD /S /Q "%OPENSSL_DIR%-source" IF EXIST "%OPENSSL_DIR%-build" RD /S /Q "%OPENSSL_DIR%-build" git clone https://github.com/openssl/openssl.git "%OPENSSL_DIR%-source" cd "%OPENSSL_DIR%-source" git checkout %GIT_HASH% mkdir "%OPENSSL_DIR%-build" cd "%OPENSSL_DIR%-build" perl "%OPENSSL_DIR%-source\Configure" VC-WIN32 --release --prefix="C:\Program Files (x86)\OpenSSL" --openssldir="C:\Program Files (x86)\OpenSSL" enable-static-engine nmake nmake test nmake install cd "%OPENSSL_DIR%" rd /s /q "%OPENSSL_DIR%-source" rd /s /q "%OPENSSL_DIR%-build" rd /s /q "C:\Program Files (x86)\OpenSSL\certs" rd /s /q "C:\Program Files (x86)\OpenSSL\html" rd /s /q "C:\Program Files (x86)\OpenSSL\misc" rd /s /q "C:\Program Files (x86)\OpenSSL\private" rd /s /q "C:\Program Files (x86)\OpenSSL\lib\engines-3" rd /s /q "C:\Program Files (x86)\OpenSSL\lib\ossl-modules" del /f /q "C:\Program Files (x86)\OpenSSL\bin\c_rehash.pl" del /f /q "C:\Program Files (x86)\OpenSSL\openssl.*" del /f /q "C:\Program Files (x86)\OpenSSL\ct_log_list.*" set OPENSSL_DIR= :SKIP ``` You can interrupt it once you see `nmake` running the compiler. Note however that you need to have Perl (I use [Strawberry Perl](https://strawberryperl.com/download/5.32.1.1/strawberry-perl-5.32.1.1-64bit.msi)), and [nasm](https://www.nasm.us/pub/nasm/releasebuilds/2.16.01/win64/nasm-2.16.01-win64.zip) (both should be in `PATH`). No idea if that has anything to do with it, but the way I discovered this issue is that I mistakenly run my 32-bit OpenSSL build batch file (reproduced above) in a 64-bit Visual Studio environment, and naturally I wanted to stop it so I hit `Ctrl+C`. I was worried that I might have to try a couple of times (i.e. that it might be timing-sensitive), but oddly enough I was able to reproduce it for the ETL trace on the first try.

claunia commented

@levicki commented on GitHub (Jun 26, 2023):

@DHowett Here is another trace, this one is with -filemode:

terminal-trace.zip

The first trace was following the instructions on the link so it was Terminal.Verbose instead of DefTerm.Verbose. This one was done using the exact command you provided.

@levicki commented on GitHub (Jun 26, 2023): @DHowett Here is another trace, this one is with `-filemode`: [terminal-trace.zip](https://github.com/microsoft/terminal/files/11867483/terminal-trace.zip) The first trace was following the instructions on the link so it was `Terminal.Verbose` instead of `DefTerm.Verbose`. This one was done using the exact command you provided.

claunia commented

@DHowett commented on GitHub (Jun 26, 2023):

Thanks!

I've got some good news and some bad news.

The good news:

We can check the console off the list of culprits, because somebody is calling WriteConsole with that exact data!

The bad news:

I can't tell you what processes are doing that, because we don't capture that information in our traces (booo) 😄

@DHowett commented on GitHub (Jun 26, 2023): Thanks! I've got some good news and some bad news. The good news: <img width="525" alt="image" src="https://github.com/microsoft/terminal/assets/189190/79d59bc2-343f-4b9b-b53e-cb48887653ed"> We can check the console off the list of culprits, because somebody is calling `WriteConsole` with that exact data! The bad news: I can't tell you what processes are doing that, because we don't capture that information in our traces (booo) :smile:

claunia commented

@DHowett commented on GitHub (Jun 26, 2023):

(I'll try to reproduce it later today so I can get you some more info!)

@DHowett commented on GitHub (Jun 26, 2023): (I'll try to reproduce it later today so I can get you some more info!)

claunia commented

@levicki commented on GitHub (Jun 26, 2023):

@DHowett

Thanks for taking a look.

(I'll try to reproduce it later today so I can get you some more info!)

For me it's fully reproducible (I could reproduce it 2 out of 2 tries after the inital encounter).

However, even if you do manage to reproduce it, I have no way of reaching nmake team (assuming it's nmake.exe doing it) and submitting the bug report to them (please don't tell me to use Visual Studio feedback, never had any luck with that so far).

@levicki commented on GitHub (Jun 26, 2023): @DHowett Thanks for taking a look. > (I'll try to reproduce it later today so I can get you some more info!) For me it's fully reproducible (I could reproduce it 2 out of 2 tries after the inital encounter). However, even if you do manage to reproduce it, I have no way of reaching nmake team (assuming it's nmake.exe doing it) and submitting the bug report to them (please don't tell me to use Visual Studio feedback, never had any luck with that so far).

claunia commented

@levicki commented on GitHub (Jun 26, 2023):

@DHowett

We can check the console off the list of culprits, because somebody is calling WriteConsole with that exact data!

Same behavior in the old conhost.exe:

Googling the message finds exactly one mention on Twitter dated Jan 7, 2018:

If anything, that suggests it must be a "known issue" or perhaps even a "won't fix" whoever is the culprit if it was out there for 5 years now.

What I don't get is why they (or anyone else for that matter) would WriteConsole char by char?!?

@levicki commented on GitHub (Jun 26, 2023): @DHowett > We can check the console off the list of culprits, because somebody is calling `WriteConsole` with that exact data! Same behavior in the old `conhost.exe`: ![image](https://github.com/microsoft/terminal/assets/16415478/87d60d36-0be6-4cf1-95f0-faee73b3a9e3) Googling the message finds exactly one mention on Twitter dated **Jan 7, 2018**: ![image](https://github.com/microsoft/terminal/assets/16415478/74bba475-ddb4-4f50-8b71-b96d3a4eb221) If anything, that suggests it must be a "known issue" or perhaps even a "won't fix" whoever is the culprit if it was out there for 5 years now. What I don't get is why they (or anyone else for that matter) would `WriteConsole` char by char?!?

claunia commented

@DHowett commented on GitHub (Jun 26, 2023):

What I don't get is why they (or anyone else for that matter) would WriteConsole char by char?!?

Seriously! That shit is expensive! Even though we try to keep condrv as minimal as possible, the context switches alone dwarf any time spent actually processing output!

I'll see if I can track down an owner for nmake in the meantime. Good find with the birdsite post! 😄

@DHowett commented on GitHub (Jun 26, 2023): > What I don't get is why they (or anyone else for that matter) would `WriteConsole` char by char?!? _Seriously!_ That shit is expensive! Even though we try to keep condrv as minimal as possible, the context switches alone dwarf any time spent actually processing output! I'll see if I can track down an owner for nmake in the meantime. Good find with the birdsite post! :smile:

claunia commented

@levicki commented on GitHub (Jun 26, 2023):

@DHowett Don't rush to conclusions just yet — I took a quick look at current nmake.exe disassembly and I can't spot any issue here:

It is using C runtime (UCRT) imports which would cause other apps to misbehave as well if that was the problem.

I think the issue here is the OpenSSL build process.

Namely, makefile is not invoking cl.exe itself, but cmd.exe which in turn invokes cl.exe and that multiple command outputs get interleaved if you interrupt the build process. I am not exactly sure how that could duplicate only nmake output though but there are indeed two instances of nmake running during build (even though only one of them appears to be doing anything):

EDIT: First nmake is the one called by a batch file, and the second one is the one actually doing the build. Other errors during build are not output twice, only Ctrl+C.

@levicki commented on GitHub (Jun 26, 2023): @DHowett Don't rush to conclusions just yet — I took a quick look at current `nmake.exe` disassembly and I can't spot any issue here: ![image](https://github.com/microsoft/terminal/assets/16415478/3ce6b213-1eb5-49e9-86de-ecdc5cc60f87) ![image](https://github.com/microsoft/terminal/assets/16415478/3b3d307d-237f-4641-8207-3949b664d025) It is using C runtime (UCRT) imports which would cause other apps to misbehave as well if that was the problem. I think the issue here is the OpenSSL build process. Namely, makefile is not invoking `cl.exe` itself, but `cmd.exe` which in turn invokes `cl.exe` and that multiple command outputs get interleaved if you interrupt the build process. I am not exactly sure how that could duplicate only nmake output though but there are indeed two instances of nmake running during build (even though only one of them appears to be doing anything): ![image](https://github.com/microsoft/terminal/assets/16415478/4ac58f81-b026-423f-b134-2df2c1bb3bef) **EDIT:** First nmake is the one called by a batch file, and the second one is the one actually doing the build. Other errors during build are not output twice, only Ctrl+C.

claunia commented

@lhecker commented on GitHub (Jun 26, 2023):

The reason it prints character by character is likely because it uses wprintf with _O_U16TEXT. The Windows CRT (C stdlib) will then print all text character by character via _putwch_nolock (the same happens with _O_U8TEXT, etc.).

Edit: FYI this occurs in write_double_translated_unicode_nolock in

C:\Program Files (x86)\Windows Kits\10\Source\10.0.22621.0\ucrt\lowio\write.cpp

I don't know why the CRT does that and I wish they didn't. It just says:

We just need to print each character to the console, one-by-one [...]

which is kind of self-explanatory since that's exactly what the code does. There's no mention why it has this weird behavior. The string is already UTF-16LE and the Console W APIs accept exactly that. -> No translation needed.

@lhecker commented on GitHub (Jun 26, 2023): The reason it prints character by character is likely because it uses `wprintf` with `_O_U16TEXT`. The Windows CRT (C stdlib) will then print all text character by character via `_putwch_nolock` (the same happens with `_O_U8TEXT`, etc.). --- Edit: FYI this occurs in `write_double_translated_unicode_nolock` in ``` C:\Program Files (x86)\Windows Kits\10\Source\10.0.22621.0\ucrt\lowio\write.cpp ``` I don't know why the CRT does that and I wish they didn't. It just says: > We just need to print each character to the console, one-by-one [...] which is kind of self-explanatory since that's exactly what the code does. There's no mention why it has this weird behavior. The string is already UTF-16LE and the Console W APIs accept exactly that. -> No translation needed.

claunia commented

@levicki commented on GitHub (Jun 26, 2023):

@lhecker Thanks for clarification and welcome to our little mistery club here :-)

@levicki commented on GitHub (Jun 26, 2023): @lhecker Thanks for clarification and welcome to our little mistery club here :-)

claunia commented