Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Broken output on Windows when using Windows Terminal #16526

Open
michal-z opened this issue Jul 24, 2023 · 11 comments
Open

Broken output on Windows when using Windows Terminal #16526

michal-z opened this issue Jul 24, 2023 · 11 comments
Labels
bug Observed behavior contradicts documented or intended behavior os-windows
Milestone

Comments

@michal-z
Copy link
Contributor

Zig Version

0.11.0-dev.4195+7f3fdd2ff

Steps to Reproduce and Observed Behavior

Compiler output looks broken, it prints a message for every step.

git clone https://github.com/michal-z/zig-gamedev.git
cd zig-gamedev
zig build test
steps [4/32] zig test zmath-tests Debug native... Semantic Analysis [2053] ... ←[79D←[0Ksteps [4/32] zig test zmath-tests Debug native... LLVM Emit Object... ←[70D←[0Ksteps [4/32] zig test zjobs-tests Debug native... LLD Link... ←[62D←[0Ksteps [4/32] zig build-lib zphysics Debug native... ←[52D←[0Ksteps [4/32] zig build-lib zphysics Debug native... ←[52D←[0Ksteps [4/32] zig build-lib zphysics Debug native... ←[52D←[0Ksteps [14/32] zig test zflecs-tests Debug native... AST Lowering [388] io\tty.zig... ←[85D←[0Ksteps [14/32] zig test zglfw-tests Debug native... mingw-w64 msvcrt-os.lib... ←[78D←[0Ksteps [14/32] zig test zphysics-tests-f32 Debug native... mingw-w64 msvcrt-os.lib... ←[85D←[0Ksteps [14/32] zig test zphysics-tests-f32 Debug native... mingw-w64 mingwex.lib... ←[83D←[0Ksteps [14/32] zig test zphysics-tests-f32 Debug native... mingw-w64 mingwex.lib... ←[83D←[0Ksteps [14/32] zig test zaudio-tests Debug native... mingw-w64 uuid.lib... ←[74D←[0Ksteps [14/32] zig test zglfw-tests Debug native... Semantic Analysis [1781] ... ←[80D←[0Ksteps [14/32] zig test zstbi-tests Debug native... LLD Link... ←[63D←[0Ksteps [14/32] zig test zphysics-tests-f32 Debug native... libcxx... ←[68D←[0Ksteps [14/32] zig test zaudio-tests Debug native... LLVM Emit Object... ←[72D←[0Ksteps [14/32] zig test zglfw-tests Debug native... LLD Link... ←[63D←[0Ksteps [14/32] zig test zphysics-tests-f32 Debug native... Semantic Analysis [2791] ...
 ←[87D←[0Ksteps [14/32] zig test zphysics-tests-f32 Debug native... LLVM Emit Object... ←[78D←[0Ksteps [19/32] run zglfw-tests... ←[33D←[0Ksteps [21/32] run zflecs-tests [2/5] ←[37D←[0Ksteps [22/32] ←[14D←[0Ksteps [23/32] ←[14D←[0Ksteps [23/32] zig test zphysics-tests-f32 Debug native... LLVM Emit Object... ←[78D←[0Ksteps [23/32] zig test zphysics-tests-f32 Debug native... LLVM Emit Object... ←[78D←[0Ksteps [23/32] run zflecs-tests [5/5] ←[37D←[0Ksteps [23/32] run zaudio-tests [7/8] ←[37D←[0Ksteps [26/32] zig test zphysics-tests-f32 Debug native... LLD Link... ←[70D←[0Ksteps [26/32] zig test zphysics-tests-f32 Debug native... LLD Link... ←[70D←[0Ksteps [27/32] run zphysics-tests-f32 [1/16] ←[44D←[0Ksteps [27/32] run zphysics-tests-f32 [3/16] ←[44D←[0Ksteps [27/32] run zphysics-tests-f32 [6/16] ←[44D←[0Ksteps [27/32] run zphysics-tests-f32 [15/16] ←[45D←[0Ksteps [29/32] ←[14D←[0K

Expected Behavior

Output should look like on Linux.

@michal-z michal-z added the bug Observed behavior contradicts documented or intended behavior label Jul 24, 2023
@michal-z michal-z changed the title Broken output on Windows when using WIndows Terminal Broken output on Windows when using Windows Terminal Jul 24, 2023
@andrewrk
Copy link
Member

Hmmm, is this a regression?

@andrewrk andrewrk added this to the 0.11.0 milestone Jul 24, 2023
@michal-z
Copy link
Contributor Author

Hmmm, is this a regression?

Yes, it started to be like this from 0.11.0-dev.3771.

@andrewrk andrewrk added the regression It worked in a previous version of Zig, but stopped working. label Jul 24, 2023
@andrewrk andrewrk modified the milestones: 0.11.0, 0.11.1 Jul 24, 2023
@squeek502
Copy link
Collaborator

squeek502 commented Jul 24, 2023

My guess is that this would be caused by #16080, but will double check. If so, it would mean that GetConsoleMode is returning with the ENABLE_VIRTUAL_TERMINAL_PROCESSING flag set to true, but it's failing to actually parse/render these ANSI escape codes correctly

I'm seeing the same thing locally, so I will look more into it.

@squeek502
Copy link
Collaborator

squeek502 commented Jul 24, 2023

This is weird, but the escape codes seem to be parsed if I change the session's codepage to UTF-8 (maybe because the default code page of 437 has a glyph for \x1b, but color escape codes seem to work fine with code page 437... so it's still a mystery).

It's still buggy with the UTF-8 code page, though (the lines aren't cleared properly):

> chcp 65001
Active code page: 65001

> zig build test
steps [20/32] zig build-lib zphysics Debug native... Compile C Objects [70/132] C                                                                                                        Csteps [20/32] zig build-lib zphysics Debug native... Compile C Objects [106/132]                                                                                                         ]steps [20/32] zig build-lib zphysics Debug native... Compile C Objects [106/132                                                                                                          2steps [20/32] zig build-lib zphysics Debug native... Compile C Objects [106/132]                                                                                                         ]steps [20/32] zig build-lib zphysics Debug native... Compile C Obj                                                                                                                       jsteps [20/32] zig build-lib zphysics Debug native...                                                                                                                                     .steps [20/32] zig build-lib zphysics D                                                                                                                                                   Dsteps [20/32] zig build-                                                                                                                                                                 -steps [20/                                                                                                                                                                               /steps [20/32] zig test zmesh-tests Debug native... Compile C Objects [19/19] cxa_demang...                                                                                               ssteps [20/32] zig test zmesh-tests Debug native... Compile C Objects [19/19] cxa_d                                                                                                       dsteps [20/32] zig test zmesh-tests Debug native... Compile C Objects                                                                                                                     ssteps [20/32] zig test zmesh-tests Debug native... Com                                                                                                                                   msteps [20/32] zig test zmesh-tests Debug                                                                                                                                                 gsteps [20/32] zig test zmesh-tests De                                                                                                                                                    esteps [20/32] zig build-lib zphysics Debug                                                                                                                                                steps [29/32                                                                                                                                                                             2steps [29/32] zig                                                                                                                                                                        gsteps [29/32] zig te                                                                                                                                                                     esteps [30/32] run zphysics-tests-f32 [1/16]                                                                                                                                              4D

Some potential quick fixes until this is understood more fully:

  • Revert windows: detect ANSI support in more terminals #16080, but this would have the side-effect of making colored output in test diagnostics from things like expectEqualSlices not show up when doing zig build
  • Make Progress.zig always use the Windows Console APIs on Windows regardless of whether or not ANSI escape codes are detected as supported, since it seems like the escape codes used in the progress bar are ones that the Windows implementation struggles with

squeek502 added a commit to squeek502/zig that referenced this issue Jul 24, 2023
…them is detected

The particular escape code sequences used by the progress bar do not seem to get parsed if the code page is set to 437 (the default code page for a console session), and even if the escape sequences are parsed, the Windows implementation does not render them correctly (it only partially clears the line so the output just ends up mangled).

Until this is more understood, we just force the Windows Console APIs to be used on Windows no matter what.

See ziglang#16526
@squeek502
Copy link
Collaborator

squeek502 commented Jul 24, 2023

This actually seems to be zig build test-specific. Taking the test code from std.Progress and running it in a standalone exe works fine on master.

EDIT: I can't seem to get a minimal reproduction outside of the zig-gamedev build.zig

@squeek502
Copy link
Collaborator

Found what's causing it. Commenting out these lines:

https://github.com/michal-z/zig-gamedev/blob/5b715c68d996eba97b8737cdfbf4471f586dad2e/build.zig#L33-L43

fixes the output.

So, it seems like the spawned git submodule update --init --remote child process is somehow interfering with the console output in some way...

@michal-z
Copy link
Contributor Author

I see, but please note that on Linux output looks fine.

@squeek502
Copy link
Collaborator

squeek502 commented Jul 24, 2023

Right, Windows has a lot of session-global state involved in its console sessions. Doing something like setting the code page (SetConsoleOutputCP) or altering the console output mode (SetConsoleMode) affects every process in that session, not just the current process, so it's possible that on Windows git is doing something that helps it do whatever it's doing, but that inadvertently affects the build.exe environment.

Will test more to see if I can narrow down what's changed after git is invoked.

EDIT: Seems to be related to running git commands that are implemented as bash scripts. git-core/git-submodule is a bash script, but git-submodule--helper.exe is not. Doing git submodule within build.zig causes the problem, but git submodule--helper does not. Confirmed this by trying another command that's implemented as a bash script (git svn) and seeing that it also breaks the output.

EDIT#2: Can reproduce it by running sh.exe -c exit with the sh.exe included with git, which is what the commands-implemented-as-bash-scripts are executed with.

@squeek502
Copy link
Collaborator

squeek502 commented Jul 24, 2023

Looks to be a Git for Windows bug:

For whatever reason, it disables the ENABLE_VIRTUAL_TERMINAL_PROCESSING flag at some point and fails to restore it when running certain commands (seems to be anything that uses sh.exe as I mentioned)

Minimal reproduction code

Outputs:

> rm -rf zig-cache && zig build test
before:
 mode: 7
fatal: not a git repository (or any of the parent directories): .git
after:
 mode: 3
steps [2/3] run test [1/1] ←[27D←[0K

(ENABLE_VIRTUAL_TERMINAL_PROCESSING is 0x4 so that's the difference between the modes)

Because Zig gets the TTY config upfront once, it never realizes that ENABLE_VIRTUAL_TERMINAL_PROCESSING has been disabled during the git child process. Unsure what the fix here should be (or if there should be a fix on Zig's end at all), but #16532 is not a complete workaround since this would break all escape codes, not just the ones used by std.Progress.


You can workaround it in your build.zig with something like this:

pub extern "kernel32" fn SetConsoleMode(in_hConsoleHandle: std.os.windows.HANDLE, in_Mode: std.os.windows.DWORD) callconv(std.os.windows.WINAPI) std.os.windows.BOOL;

// ...
    // before the spawnAndWait call
    // `git submodule` fails to restore the console mode, so we need to do it manually
    // This is a Git for Windows bug: https://github.com/git-for-windows/git/issues/1121#issuecomment-323047927
    var stderr_mode: u32 = undefined;
    _ = std.os.windows.kernel32.GetConsoleMode(std.io.getStdErr().handle, &stderr_mode);
    var stdout_mode: u32 = undefined;
    _ = std.os.windows.kernel32.GetConsoleMode(std.io.getStdOut().handle, &stdout_mode);

    // ...

    // after the spawnAndWait call
    _ = SetConsoleMode(std.io.getStdErr().handle, stderr_mode);
    _ = SetConsoleMode(std.io.getStdOut().handle, stdout_mode);
// ...

EDIT: Another possible workaround is use to cmd /c when spawning git, since it seems like the console mode is restored by the terminal in that case. For this one, the only change you'd have to make is (with a os.tag == .windows check around it):

- var child = std.ChildProcess.init(&.{ "git", "submodule", "update", "--init", "--remote" }, b.allocator);
+ var child = std.ChildProcess.init(&.{ "cmd", "/c", "git", "submodule", "update", "--init", "--remote" }, b.allocator);

@squeek502
Copy link
Collaborator

squeek502 commented Jul 24, 2023

@michal-z updating my git install to the latest version also seemed to fix this for me without any build.zig modifications, so try that as well.

@andrewrk andrewrk removed the regression It worked in a previous version of Zig, but stopped working. label Jul 24, 2023
@andrewrk andrewrk modified the milestones: 0.11.1, 0.12.0 Jul 24, 2023
@michal-z
Copy link
Contributor Author

@squeek502 Great info, thanks! I will go with {Get/Set}ConsoleMode() workaround for now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Observed behavior contradicts documented or intended behavior os-windows
Projects
None yet
Development

No branches or pull requests

3 participants