Escape sequences sometimes do not work on Windows since Ninja 1.11

mbs-c commented 2 years ago

Since upgrading to Ninja 1.11, I sometimes see output like the following when building with ninja in a Powershell in Windows Terminal:

[58/26320] [...] Compiling C:/some/folder/something.c←[Ksome_incomplete_path/foo.cpp←[Kbar.cpp←[K←[KK

This does not happen for all builds and unfortunately, since our project is quite large and complicated, I have not yet been able to reproduce the circumstances that cause escape sequences to misbehave. As a consequence, I am also not sure whether this is a bug in Windows Terminal or ninja. What I do know, however, is that this issue does not occur in 1.10.2, ~which suggests it may be related to the following change: https://github.com/ninja-build/ninja/pull/2085~

mbs-c commented 2 years ago

After looking into the problem for a bit, I can now reproduce it reliably in our build. (I am still far away from being able to share a sane sample project that reproduces the problem, though.) Consequently, I was able to use git bisect. The actual culprit seems to be ec8de9c247dde02c447cff23cb826a7524110e79.

mbs-c commented 2 years ago

Some more information:

The problem is only triggered when a specific rule is being run. Said rule happens to produce a lot of console output (ASCII-only).
Not sure if this is relevant, but the trigger is the rule that re-generates build.ninja.
The generated build.ninja file does not contain any non-ASCII characters.
No other build target which produces console output seems to trigger the bug. Colors and re-writing the current line work perfectly fine in most builds.
After setting [console]::InputEncoding and [console]::OutputEncoding to UTF-8 in pwsh, colors work in all cases and re-writing the current line mostly works (there are still weird output artifacts occasionally, but not nearly as bad).

Is using ninja 1.11 on Windows with the code page set to anything else than 65001 (or using the default values for [console]::InputEncoding and [console]::OutputEncoding) now officially unsupported?

jhasse commented 2 years ago

The commit is right, but I don't think it has anything to do with UTF-8. Ninja uses ENABLE_VIRTUAL_TERMINAL_PROCESSING on Windows to enable overriding the current line using \x1B[K. Somehow it gets turned off by the large output and you're seeing the raw ←[K in your terminal.

Is this only happening with the Windows Terminal?

mbs-c commented 2 years ago

The commit is right, but I don't think it has anything to do with UTF-8. Ninja uses ENABLE_VIRTUAL_TERMINAL_PROCESSING on Windows to enable overriding the current line using \x1B[K. Somehow it gets turned off by the large output and you're seeing the raw ←[K in your terminal.

It is worth noting that colors, which I'm guessing always used escape codes on Windows, work just fine in 1.10.2, even when the large output is present. To sum up the results of my tests in a table:

Ninja version	Code page	Generator output present	Escape codes work
1.10.2	non-UTF-8	no	yes
1.10.2	non-UTF-8	yes	yes
1.11	non-UTF-8	no	yes
1.11	non-UTF-8	yes	no
1.11	UTF-8	no	yes
1.11	UTF-8	yes	yes

(As mentioned above, I never actually changed my code page system-wide, only [console]::InputEncoding and [console]::OutputEncoding.)

Is this only happening with the Windows Terminal?

I didn't even know virtual terminal sequences worked anywhere else, so it didn't occur to me to try that. Now that I did, I can reproduce the behavior in a regular PowerShell 7 window.

mbs-c commented 2 years ago

I did some more experiments, in the hope that they are helpful:

The original issue described above is reproducible in both PowerShell Core (7.2) and Windows PowerShell (5.1)
There is another, related issue, which occurs in both versions of ninja: If you pipe the output of ninja into a cmdlet which uses escape codes to highlight text (e.g. by executing ninja all | sls 'FAILED:' in PowerShell Core), then those escape codes are also broken if the generator output is present. Surprisingly, [console]::InputEncoding = [console]::OutputEncoding = New-Object System.Text.UTF8Encoding fixes the escape codes + pipe scenario for both versions of ninja.

jonesmz commented 2 years ago

have you considered doing a git-bisection to find the specific commit that causes the issue?

you know that i was some point between 1.10.2 and 1.11.0, so you can go through the commits between those two versions to determine which commit caused the issue.

mbs-c commented 2 years ago

have you considered doing a git-bisection to find the specific commit that causes the issue?

I did, see https://github.com/ninja-build/ninja/issues/2158#issuecomment-1160388059.

The actual culprit seems to be ec8de9c247dde02c447cff23cb826a7524110e79.

The commit contains two changes:

Escape codes are now used for clearing the line on Windows as well. This only makes the problem more visible.
A manifest that sets to process code page to UTF-8 was added, which seems to be the root cause of the behavior change.

jonesmz commented 2 years ago

Ah you're absolutely right. Reading comprehension fail on my part.

jonesmz commented 2 years ago

You know, I've observed the [K behavior myself.

Are you saying that reverting only the manifest file change fixes this behavior? I can attempt to reproduce the "fix" on my work machine next week if you'd like?

mbs-c commented 2 years ago

Are you saying that reverting only the manifest file change fixes this behavior?

I am certain that this is the case based on my analysis.

I can attempt to reproduce the "fix" on my work machine next week if you'd like?

That would be very welcome.

jonesmz commented 2 years ago

Sure. I can't promise I'll remember and/or have the time, but if no fires pop up, I'll see if I can confirm. At the very least I'll patch my works version of ninja to fix the bug....

Not sure how to have our cake and eat it too though. Any idea on what code changes we can make to fix the bug before reverting the manifest file?

jhasse commented 2 years ago

Report to Microsoft.

jonesmz commented 2 years ago

What, specifically, is the bug, and which windows api function is it in?

mbs-c commented 2 years ago

I would say that the bug in Windows is VT sequences occasionally breaking if the terminal input/output encoding is not set to UTF-8. As mentioned above, the manifest change only made the problem more frequent, in the versions before this change you run into a similar (identical?) problem when piping a large ninja output into the Select-String cmdlet.

kinke commented 9 months ago

I've also seen weird output issues with ninja v1.11 on Windows, caused by #2085.

One testcase:

rule _phony
  command = cmd.exe /c "$cmd"

build dummy: _phony
  cmd = echo Hi there
  pool = console

default dummy

ninja v1.11.1, in a cmd.exe shell, Win10 20H2:

[0/1] cmd.exe /c "echo Hi there"Hi there

ninja v1.11.1 + #2085 reverted:

[0/1] cmd.exe /c "echo Hi there"
Hi there

mbs-c commented 9 months ago

@kinke Do [console]::InputEncoding and [console]::OutputEncoding affect your test case as well?

ninja-build / ninja

Escape sequences sometimes do not work on Windows since Ninja 1.11 #2158