1748070 - `mach show-log` fails on Windows

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Mike Hommey [:glandium]]

The details of the failure are as follows:

TypeError: environment can only contain strings

  File "c:\Users\glandium\gecko\python/mozbuild/mozbuild/mach_commands.py", line 357, in show_log
    less = subprocess.Popen(["less"], stdin=subprocess.PIPE, env=env)
  File "c:\mozilla-build\python3\lib\subprocess.py", line 775, in __init__
    restore_signals, start_new_session)
  File "c:\mozilla-build\python3\lib\subprocess.py", line 1178, in _execute_child
    startupinfo)

Comment 1

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

Attachment: Bug 1748070 - rewrote `show_log` to resolve various bugs on Windows (While still maintaining current behavior on POSIX systems) r?#build

• Changed byte strings being set in env to just strings
  as byte strings were only necessaery in Python2 and
  strings work fine in POSIX and Windows as of Python3.
  (Byte strings no longer work on Windows in Python3)

• Replaced all the file descriptor logic used to pipe
  to less with more Pythonic stream manipulation.
  (There was a change in Windows console IO in Python 3.6
  that broke the file descriptor logic we were using here)

  See: https://www.python.org/dev/peps/pep-0528/#add-io-windowsconsoleio

Comment 2

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

As mentioned in the commit message, code using os.dup2 no longer works as expected as of Python3.6 on Windows.

The official documentation on the change can be found here, but I think this Stackoverflow answer does a better job of explaining it.

In short, the write function isn't correct, and the handle for the file descriptor is invalidated.

Fortunately for this patch, there was a simple workaround by avoiding sys.stdout altogether and just making stream directly to the stdin for the less process.

It should be noted that there is an additional way to access the legacy behavior on Windows while still in Python3.6 or greater. You can set the environment variable PYTHONLEGACYWINDOWSSTDIO to 1 for the Python process and the old file descriptor stuff using os.dup2 will still work. I mention this just so that it's not lost information. I believe this same underlying issue is what Mitch encountered here. It may not be as trivial to replace the os.dup2 logic there as it was for me here, so that is a potential workaround.

Though, as discussed with Mitch, there is potential to cause other problems/regressions by enabling this flag (either immediately, or in the future) so we should keep that in mind.

Additionally, we have various uses os.dup2 in the codebase. If they were problematic, I would expect them to be causing hard errors, and we would have noticed by now, but I just wanted to make a note of it.

Comment 3

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

While testing the ./mach show-log command I noticed that there are additional errors spewed to the command line if the user manual terminates less before the entire logfile is piped to it. These errors do not happen if the user scrolls down far enough in less so that all of the log file is piped. This behavior is present in both my implementation and the previous implementation, and on Linux and Windows.

I believe this is due to some sort buffering of the stdin to less and I tried several workarounds, (set the buffer of stdin to infinite, set the buffer or less to infinite) but none worked.

I discussed options with Glandium, and he recommended I raise a separate bug and just catch the exception to hide it. I'll go ahead with that link that bug with this one here.

Comment 4

[Mitchell Hentges [:mhentges] 🦀]

Phenomenal writeup, this is great description on why the existing functionality stopped working, with sources, as well as the direction towards the solution. Extremely well done my friend 👏

Additionally, we have various uses os.dup2 in the codebase. If they were problematic, I would expect them to be causing hard errors, and we would have noticed by now, but I just wanted to make a note of it.

Looks like the other usages:

• Are 3rd-party tests (gyp's TestCmd.py), which we never run
• Are unix-specific (tests/lib/tasks_unix.py), in which they should still work IIUC
• Are handling files instead of console (_pytest/capture.py), which IIUC is when it's still OK?
• (this pytest usage is a little suspicious, but I guess that that happens right at the end of the standalone pytest process and is closing stdout, so perhaps it's OK).

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/69c784bb261b
rewrote `show_log` to resolve various bugs on Windows (While still maintaining current behavior on POSIX systems) r=firefox-build-system-reviewers,glandium,mhentges

Comment 6

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/69c784bb261b