1744340 - Improve Mach/build output formatting (color) on Windows

Status: RESOLVED FIXED

(Firefox Build System :: Mach Core, enhancement, P3)

Description

[Mitchell Hentges [:mhentges] 🦀]

• For logging colouring: blessings doesn't work on Windows, but blessed is a fork that does.
• On *nix platforms, there's a helpful TUI-like behaviour where the current "phase" of the build is shown at the bottom
• Compiler (clang, cargo) warnings should be coloured
• Python-test output should be coloured

Comment 3

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Enable colored output on Windows - r?#build

Comment 4

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

ENABLE_VIRTUAL_TERMINAL_PROCESSING is the flag that we can set so that the console correctly parses ANSI color escape sequences in the output.

I came across this response in a ticket that describes the problem very well. ENABLE_VIRTUAL_TERMINAL_PROCESSING is a global state of the console. Anything invoked in that console (or by a subprocess of something invoked) can change it (Either intentionally for backwards compatibility reasons, or unwittingly because it's old code unaware that flag exists and blowing it away with how the setters are coded).

This is what our problem is. I tried setting ENABLE_VIRTUAL_TERMINAL_PROCESSING right at the early stages of ./mach being invoked, and color works briefly until a process is invoked that disables it, then colors stop working again unless ENABLE_VIRTUAL_TERMINAL_PROCESSING is set again (and then again it only works until some other process disables it again. (In this case the first process the disables it is perl as shown by my test output):

ENABLE_VIRTUAL_TERMINAL_PROCESSING: SET! WOOT
 0:10.78 checking for perl... C:/mozilla-build/msys/bin/perl.exe
ENABLE_VIRTUAL_TERMINAL_PROCESSING: NOT SET! =( colors disabled

One solution, as discovered by Adam Gashlin in 1417003 He found out where in MSYS this flag was being set to off, then patched the DLL. (Relevant code section in MSYS2 Repo where this happens, but it may already be fixed there?) This is one solution, but it's a large amount of work doing it the proper way of getting the fix in upstream, then updating all our toolchains/deps.

Thankfully I came up with a 'dumb' solution that was a trivial amount of work to implement: Setting ENABLE_VIRTUAL_TERMINAL_PROCESSING right before we write with our loggers. This (mostly) works because all of our output goes through a logger. So if we enable colors write before we write, we almost always get colors.

The almost always is because of a race condition. Since we're in a multithreaded context, and it's a global variable, right after we set ENABLE_VIRTUAL_TERMINAL_PROCESSING in the logger, but before we right, some other culprit application can run its code the disables it, then when the write happens, colors won't be displayed again. I have no solution for this that makes sense (Blocking to guarantee colors is obviously wrong since colors aren't as important as build times).

Thankfully hammering the windows API with ENABLE_VIRTUAL_TERMINAL_PROCESSING does not add any noticeable amount of time to the build (I think we end up doing a few thousand of these calls).

Full disclosure: I did not profile the build, but before/after my changes both took around 7 minutes on my machine.

Comment 5

[Mitchell Hentges [:mhentges] 🦀]

(Relevant code section in MSYS2 Repo where this happens, but it may already be fixed there?)

Hmm, there must be somewhere else where it isn't fixed, because I bet you that the part of perl unsetting virtual terminal processing is the MSYS/Cygwin core dll itself.

This is one solution, but it's a large amount of work doing it the proper way of getting the fix in upstream, then updating all our toolchains/deps.

I think this is worthwhile so that in a future MozillaBuild 4.1 release, we can capitalize on our fixes once they get upstream.
In the short term, we're still going to want to either use a workaround or keep the old behaviour - I don't think that patching Cygwin is a good idea, fwiw.

Thankfully I came up with a 'dumb' solution that was a trivial amount of work to implement: Setting ENABLE_VIRTUAL_TERMINAL_PROCESSING right before we write with our loggers. This (mostly) works because all of our output goes through a logger. So if we enable colors write before we write, we almost always get colors.

Thanks for checking the performance characteristics of this change, as that was my first concern.
I'm still nervous about other impacts of this, including:

• As you mentioned, race conditions around intermittent colouring - perhaps, depending on timings, sometimes ANSI sequences may still be printed raw to the screen instead of being interpreted. This could degrade usability.
• With how much we'd be hammering the API and setting/unsetting virtual terminal processing, I'm nervous about this having funky, hard-to-reproduce issues on some build machines.

I think that my stance here is that we should:

• Get :glandium's thoughts here on whether we should land this
• If we do land this, then make it opt-in, due to usability regressions around escape sequences being uninterpreted sometimes.

Comment 6

[Kagami Rosylight [:saschanaz] (they/them)]

I tried setting ENABLE_VIRTUAL_TERMINAL_PROCESSING right at the early stages of ./mach being invoked

As far as I can tell, this flag is initially already set. What's super weird is that it becomes unset during get_base_mozconfig_info(), specifically during sandbox._value_for(sandbox["mozconfig_options"]).

For some reason the flag remains set right before that line and then is already unset at the first line of mozconfig_options(), and this makes me believe something in the sandbox is manipulating it.

Comment 7

[Kagami Rosylight [:saschanaz] (they/them)]

Actually no, it's unset during read_mozconfig(), after subprocess.check_output() with command:

['C:/mozilla-build/msys2/usr/bin/sh.exe', 'c:/users/sasch/documents/github/gecko-dev/python/mozbuild/mozbuild/mozconfig_loader', 'C:/Users/sasch/Documents/GitHub/gecko-dev', 'C:/Users/sasch/Documents/GitHub/gecko-dev/mozconfig', 'C:\\Users\\sasch\\.mozbuild\\srcdirs\\gecko-dev-1a7eab949d3b\\_virtualenvs\\mach\\Scripts\\python.exe', 'c:/users/sasch/documents/github/gecko-dev/python/mozbuild/mozbuild/action/dump_env.py']

Meh, I just rediscovered comment #4 🙂

Edit: MSYS=enable_pcon doesn't seem to help, even when updating MSYS to the current latest version (20220904).

Comment 8

[Kagami Rosylight [:saschanaz] (they/them)]

Okay, getting the latest MSYS installation and running pacmac -Suy solves comment #7. What's still broken is that:

1. import blessings fails:

   Traceback (most recent call last):
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\mach", line 111, in <module>
       main(sys.argv[1:])
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\mach", line 103, in main
       mach = check_and_get_mach(os.path.dirname(os.path.realpath(__file__)))
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\mach", line 35, in check_and_get_mach
       return load_mach(dir_path, mach_path)
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\mach", line 21, in load_mach
       return mach_initialize.initialize(dir_path)
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\build/mach_initialize.py", line 177, in initialize
       import mach.main
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\python\mach\mach\main.py", line 34, in <module>
       from .logging import LoggingManager
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\python\mach\mach\logging.py", line 15, in <module>
       raise e
     File "C:\Users\sasch\Documents\GitHub\gecko-dev\python\mach\mach\logging.py", line 12, in <module>
       import blessings
     File "c:\users\sasch\documents\github\gecko-dev\third_party\python\blessings\blessings\__init__.py", line 5, in <module>
       import curses
     File "C:\Users\sasch\AppData\Local\Programs\Python\Python310\lib\curses\__init__.py", line 13, in <module>
       from _curses import *
   ModuleNotFoundError: No module named '_curses'
   

   Seemingly windows-curses should be installed together as a dependency. Investigating how to add a dependency to moz-central...

2. Something still turns off virtual terminal somewhere, but doesn't seem to always happen? GetConsoleMode returns 0 right after writing config.status but this doesn't seem to affect anything. Only 3 is problematic AFAICT.

Comment 9

[Kagami Rosylight [:saschanaz] (they/them)]

Hi Alex, based on my findings, do you want to retry with latest MSYS bits?

What I did:

1. Replace mozilla-build/msys2 with the latest MSYS2 installation (because pacman -Suy failed on bundled msys2)
2. Run pacman -Suy. (It requires restarting the terminal after updating core modules, so you need to run it twice)
3. Run pacman -S m4 diffutils for missing dependencies
4. Apply your patch, except the greedy enable_virtual_terminal_processing(). This is nowhere needed!

One problem is that blessings is not Windows compatible at all because of curse and fcntl dependency. We fortunately already have colorama and it provides sufficient features to replace blessings at least in logging.py and hopefully also in machformatter.py (via mozterm/terminal.py). Then we can probably use StructuredTerminalFormatter for Windows too.

So I think the work item here is:

1. Get a new MozillaBuild release (solely because of pacman failure. Can we do the pacman update as a mach command btw?)
2. Apply your patch!
   • with colorama usage as I described above.
   • Probably need to keep backward compatibility with older MozillaBuild for some time. Checking ENABLE_VIRTUAL_TERMINAL_PROCESSING should be sufficient I guess.

I can also try at least the python side if you have no time right now, just say it!

Comment 10

[Kagami Rosylight [:saschanaz] (they/them)]

Attachment: Colored terminal on VSCode on Windows

Comment 11

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Are you sure it works 100% in the MSYS2 terminal? That's all that really matters. It probably works fine in the VS Code terminal with what you propose, but if it doesn't work with the recommended default path that we push users down I maintain that we shouldn't land it.

In line with what Mitch said, it should be opt-in if it doesn't work correctly for the MSYS2 terminal. We could add a config value to enable the color escape sequences, so people using other terminals that can correctly interpret them can see colored output.

Comment 12

[Kagami Rosylight [:saschanaz] (they/them)]

Attachment: Colors in start-shell.bat

Yes, this is what I'm seeing via mozilla-build/start-shell.bat which should be the current recommended way.

You're in? 🙂

Comment 13

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Could you do a full build and pipe the log to a file, then search for [31m, [32m, and [31m? If there's no hits on any unescaped sequences then I'm in.

Next week I should be able to put some time towards this.

(In reply to Kagami :saschanaz from comment #9)

(Can we do the pacman update as a mach command btw?)

The MozillaBuild update/upgrade is not trivial.

Comment 14

[Kagami Rosylight [:saschanaz] (they/them)]

Could you do a full build and pipe the log to a file, then search for [31m, [32m, and [31m? If there's no hits on any unescaped sequences then I'm in.

I had to disable the change in logging.py since that was unconditionally adding color codes, and then nothing matched \[\d+m from the piped log.

The MozillaBuild update/upgrade is not trivial.

I mean only the pacman components updates rather than full MozillaBuild upgrade. That's probably only useful for mach-outside-mozillabuild users, though.

Comment 15

[Marco Bonardo [:mak]]

(In reply to Kagami :saschanaz from comment #9)

One problem is that blessings is not Windows compatible at all because of curse and fcntl dependency. We fortunately already have colorama and it provides sufficient features to replace blessings at least in logging.py and hopefully also in machformatter.py (via mozterm/terminal.py).

blessed is a blessings fork with Windows support https://github.com/jquast/blessed (not sure how well it works)

Comment 16

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Kagami, I think your fix is basically the same as this abandoned changeset of mine from Bug 1447096. There's no documented reason why I abandoned it (and I scoured my meeting minutes with Mitch), but if I recall correctly the 'problem' (and reason why this wasn't landed) was that this doesn't work for the output from the Rust build.

The rationale being that we should fix it the 'correct' way so that it works for everything, rather than just slapping a bandage on it that partially fixes it. That was what was decided at the time, but I'm not entirely against landing a small win (I do think colorama would need to be added to the mozharness.zip though, otherwise I think unescaped sequences will show up in the logs).

That being said, I don't quite understand why you needed to upgrade your MSYS2 libs for this approach to work. Care to elaborate?

In regards to adding a mach command to upgrade the MSYS2 libs, I don't think that's a good idea. The main idea with bundling the libs with MozillaBuild is so that everyone has the same libs, and rules out a random lib upgrade on one of the libs being the problem. If there's a problem with a bundled lib and an upgrade can fix it, then once that's identified we can roll out a new MozillaBuild release and fix it for everyone. If someone is already circumventing MozillaBuild, it's up to them to manage the state of their environment (It's also not guaranteed that that environment is even MSYS2), so I don't think it makes sense to add a command to help with that.

Comment 17

[Kagami Rosylight [:saschanaz] (they/them)]

Attachment: Output from Rust

Kagami, I think your fix is basically the same as this abandoned changeset of mine from Bug 1447096.

I don't think colorama.init() is required, both Clang and Rust just does what it should do without the colorama AnsiToWin32 wrapper.

Oh, I retried and it seems it's actually needed. (No, I was just confused by the initial .idl build which is not done by clang and is never colored. It's not needed on MSYS2 shell nor on mach-outside-mozillabuild with PowerShell, both on the Windows 11 default Windows Terminal.)

but if I recall correctly the 'problem' (and reason why this wasn't landed) was that this doesn't work for the output from the Rust build.

AFAICT this works with newer MSYS bits. 🚀

That being said, I don't quite understand why you needed to upgrade your MSYS2 libs for this approach to work. Care to elaborate?

It seems updating via pacman also updates the core MSYS components (including mingw32/mingw64/msys). Updating them fixed comment #7 for me, in other words, running msys-backed executables do not turn off the virtual terminal flag anymore.

In regards to adding a mach command to upgrade the MSYS2 libs, I don't think that's a good idea.

Agreed. 👍

Comment 18

[Kagami Rosylight [:saschanaz] (they/them)]

Oh btw, just found that we still needs to turn on ENABLE_VIRTUAL_TERMINAL_PROCESSING at startup for the traditional Windows Console host. Windows Terminal, which is the default in Windows 11, has it by default though.

Comment 19

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

(In reply to Kagami :saschanaz from comment #17)

but if I recall correctly the 'problem' (and reason why this wasn't landed) was that this doesn't work for the output from the Rust build.

AFAICT this works with newer MSYS bits. 🚀

Nice, somebody else found and fixed the problem upstream: https://github.com/cygwin/cygwin/commit/fdbd1539329ad669606767ab5a63a16f825b4c45

I did a quick test run with the updated MSYS libs and a subset of my previous patch, but it doesn't look like everything I expected to be colored was. I'll do a comparison with it and with the additional colorama.init() and compare.

(In reply to Kagami :saschanaz from comment #18)

Oh btw, just found that we still needs to turn on ENABLE_VIRTUAL_TERMINAL_PROCESSING at startup for the traditional Windows Console host.
Are you proposing we do that in Python (same as my previous method) in the mach file, or via a different method?

Either way, this all looks very promising. We should have colored output on Windows soon(TM). I'll get the new MozillaBuild release rolling while I work out the last few kinks.

Comment 20

[Kagami Rosylight [:saschanaz] (they/them)]

(In reply to Alex Hochheiden [:ahochheiden] from comment #19)

but it doesn't look like everything I expected to be colored was.

May I ask what those are? I only know Clang and Rust support colored output and ignored everything else 😛

Are you proposing we do that in Python (same as my previous method) in the mach file, or via a different method?

In the mach file, but at add_terminal_logging rather than at format so that it can happen once while initialization.

Comment 21

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

I think I was expecting the warnings/underlines (^~~~~~~~) to also have colors, but I just ran it with the colorama patch and they also didn't. Let me see what the Linux build does to compare. I think they are supposed to have color, but it's being interpreted early, then lost before it's actually printed, but there might not be a way of avoiding that.

Comment 22

[Kagami Rosylight [:saschanaz] (they/them)]

It worked for me in comment #12, weird.

Comment 23

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

I figured it out.

My old patch was unreachable code on the up-to-date central, so it wasn't enabling color for clang-cl.

old:

    elif info.type == "clang":
        return "-fcolor-diagnostics"
    elif info.type == "clang-cl":
        return "-fcolor-diagnostics -fansi-escape-codes"
    else:
        return ""

What I had (mix of my old patch + current central):

    elif info.type in ["clang", "clang-cl"]:
        return "-fcolor-diagnostics"
    elif info.type == "clang-cl":
        return "-fcolor-diagnostics -fansi-escape-codes"
    else:
        return ""

Everything looks good and as I expected now. Thanks!

Comment 24

[Phabricator Automation]

Comment on attachment 9263002 [details]
Bug 1744340 - Enable colored output on Windows - r?#build

Revision D138256 was moved to bug 138256. Setting attachment 9263002 [details] to obsolete.

Comment 25

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Vendor `blessed` at `1.19.1` r?#build

• Removed blessings
• Also vendored various blessed dependencies

Depends on D138256

Comment 26

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Swap uses of `blessings` to `blessed` r?#build

Depends on D160405

Comment 27

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Correctly disable only the footer if `MACH_NO_TERMINAL_FOOTER` is set r?#build

• The old implementation also disabled the terminal handler and
  formatter, which also removed certain colored output and we don't want
  that.

Depends on D160406

Comment 28

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Removed the unused `blessings` module r?#build

Depends on D160406

Comment 29

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Improved 'exclusion list' code in `./mach vendor python` to also prevent a package from being vendored, rather than just 'not purged' r?#build

Depends on D138256

Comment 30

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Only enable colored output on Windows if the MozillaBuild version is recent enough r?#build

This should allow us to land this stack prior to the MozillaBuild
release without causing grief. It will also prevent an eyesore to anyone
who does not upgrade their MozillaBuild version to 4.0.2 on release day.

Depends on D160440

Comment 31

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/42a0a61583f0
Improved 'exclusion list' code in `./mach vendor python` to also prevent a package from being vendored, rather than just 'not purged' r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/3024fff68f6c
Vendor `blessed` at `1.19.1` r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/8a873505f17d
Swap uses of `blessings` to `blessed` r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/8efafab5495f
Removed the unused `blessings` module r=firefox-build-system-reviewers,nalexander
https://hg.mozilla.org/integration/autoland/rev/5d6aabaf72c4
Enable colored output on Windows - r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/ebff36a14737
Correctly disable only the footer if `MACH_NO_TERMINAL_FOOTER` is set r=firefox-build-system-reviewers,glandium

Comment 32

[Atila Butkovits]

Backed out for causing mach failures at test_commands.py.

Backout link: https://hg.mozilla.org/integration/autoland/rev/b5ae3cd325549ca7822be9bc86fef27d6351bccd

Push with failures: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=R5KmBAKpSmGHRKqrA_4PVw.0&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunning%2Cpending%2Crunnable&revision=9cb83a8d1f28ec8eb201721275c165fb72d0982d

Failure log: https://treeherder.mozilla.org/logviewer?job_id=396002872&repo=autoland&lineNumber=2381

Comment 33

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Sorry about that! Should be fixed now: https://treeherder.mozilla.org/jobs?repo=try&revision=aad1863eeeda9e642c8d3991aeb06738d01ecc44&selectedTaskRun=ao3Y_eLbSnKaeX8byaC7yg.0

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/510fbe9160df
Improved 'exclusion list' code in `./mach vendor python` to also prevent a package from being vendored, rather than just 'not purged' r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/7e0951a4a0df
Vendor `blessed` at `1.19.1` r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/0f19d9d5f3e0
Swap uses of `blessings` to `blessed` r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/794302e7ab5a
Removed the unused `blessings` module r=firefox-build-system-reviewers,nalexander
https://hg.mozilla.org/integration/autoland/rev/0729df453dca
Enable colored output on Windows - r=firefox-build-system-reviewers,glandium
https://hg.mozilla.org/integration/autoland/rev/df08e2c6cff1
Correctly disable only the footer if `MACH_NO_TERMINAL_FOOTER` is set r=firefox-build-system-reviewers,glandium

Comment 35

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

Attachment: Bug 1744340 - Disable colored output from cargo if `NO_ANSI` is set r?#build

Comment 36

[Marco Bonardo [:mak]]

I'm testing on Autoland, and this is awesome. I can't tell you how much happy I am to finally get colorized logs on Windows. Thank you very much.

Comment 37

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/510fbe9160df
https://hg.mozilla.org/mozilla-central/rev/7e0951a4a0df
https://hg.mozilla.org/mozilla-central/rev/0f19d9d5f3e0
https://hg.mozilla.org/mozilla-central/rev/794302e7ab5a
https://hg.mozilla.org/mozilla-central/rev/0729df453dca
https://hg.mozilla.org/mozilla-central/rev/df08e2c6cff1

Comment 38

[Kagami Rosylight [:saschanaz] (they/them)]

This is a big breakthrough for Windows dev experience, thank you!

Comment 39

[Emilio Cobos Álvarez (:emilio)]

Indeed, this is awesome!

Comment 40

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6f70a19f499c
Disable colored output from cargo if `NO_ANSI` is set r=sheehan

Comment 41

[Alex Hochheiden [:ahochheiden] (needinfo? me)]

I'm glad you're all excited for it! 😁

Comment 42

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/6f70a19f499c