1750153 - `mach show-log` throws many errors if the pager (less) is manually terminated before everything has been piped through the input buffer

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[Alex Hochheiden [:ahochheiden] [he/him]]

If the user manually terminates less (via q) before the entire log file is piped, there are tons of subsequent errors, because the logger will still try to stream to less.stdin but the process was terminated, so less.stdin doesn't exist anymore. Thus, every subsequent line attempted to streamed causes an error of this nature:

--- Logging error ---
Traceback (most recent call last):
  File "c:\mozilla-build\python3\lib\logging\__init__.py", line 1029, in emit
    self.flush()
  File "c:\mozilla-build\python3\lib\logging\__init__.py", line 1009, in flush
    self.stream.flush()
OSError: [Errno 22] Invalid argument
Call stack:
  File "./mach", line 126, in <module>
    main(sys.argv[1:])
  File "./mach", line 122, in main
    sys.exit(mach.run(args))
  File "c:\mozilla-source\mozilla-unified\python\mach\mach\main.py", line 371, in run
    return self._run(argv)
  File "c:\mozilla-source\mozilla-unified\python\mach\mach\main.py", line 493, in _run
    **vars(args.command_args),
  File "c:\mozilla-source\mozilla-unified\python\mach\mach\registrar.py", line 107, in _run_command_handler
    result = fn(instance, **kwargs)
  File "c:\mozilla-source\mozilla-unified\python/mozbuild/mozbuild/mach_commands.py", line 373, in show_log
    handle_log_file(command_context, log_file)
  File "c:\mozilla-source\mozilla-unified\python/mozbuild/mozbuild/mach_commands.py", line 404, in handle_log_file
    command_context._logger.handle(record)
  File "c:\mozilla-build\python3\lib\logging\__init__.py", line 1524, in handle
    self.callHandlers(record)
  File "c:\mozilla-source\mozilla-unified\third_party\python\sentry_sdk\sentry_sdk\integrations\logging.py", line 77, in sentry_patched_callhandlers
    return old_callhandlers(self, record)
Message: '{line}'
Arguments: ()

Comment 1

[Alex Hochheiden [:ahochheiden] [he/him]]

I tried various methods to eliminate the buffering on the pipe, but was not successful.

• Setting Popen(bufsize=-1 (infinite) and Popen(bufsize=999999 (Much larger than my test file) yielded no change.
• Passing the command line argument --buffers=-1 to less (buffer space is unlimited) https://man7.org/linux/man-pages/man1/less.1.html
• Setting PYTHONUNBUFFERED for the Python environment prior to launch (did nothing, but caused a bunch of errors with other commands as I later found out...)

I discussed with Glandium and he recommended I catch the exceptions to hide them. After some trial and error (Needed to temporarily disable raising errors inside of logging itself so that it could propagate up to my try/catch), I got that solution to work, so that's what I'll go with here.

Comment 2

[Mike Hommey [:glandium]]

Note: I doubt it's buffer-related. What happens is that less quits, which leaves the pipe hanging on the reading end, but the mach process is still trying to write to the pipe's writing end because it doesn't know that less died, so it gets an error.

Comment 3

[BugBot [:suhaib / :marco]]

The Bugbug bot thinks this bug should belong to the 'Firefox Build System::Mach Core' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Comment 4

[Alex Hochheiden [:ahochheiden] [he/him]]

(In reply to Mike Hommey [:glandium] from comment #2)

Note: I doubt it's buffer-related. What happens is that less quits, which leaves the pipe hanging on the reading end, but the mach process is still trying to write to the pipe's writing end because it doesn't know that less died, so it gets an error.

I'm not familiar with how to attach a debugger to the terminal (Currently just use PyCharm, but I can't debug the 'piping' path there), but what it seems like to me is it's blocking the main thread (that's doing the piping) at <python3>\Lib\logging\__init__.py#1028. The stream.write(msg + self.terminator). That's why I thought it was buffer related. It pipes what it can into the buffer, then blocks until there's space again. My thinking is that the time to pipe should be miniscule for a 28kb log file, and I did a test where I waited a minute to see if I was being too quick and the error still happened.

I'm still pretty sure the thread is blocking there, I just don't know why.

Comment 5

[Alex Hochheiden [:ahochheiden] [he/him]]

Attachment: Bug 1750153 - Prevent unwanted errors from showing up in `./mach show-log` after closing `less` before the entire log file has been piped to it r?#build

The main thread is blocking (for an unknown reason) without piping the entirety of the log
file to less (unless the user manually scrolls to almost the bottom). Since the piping
cannot always complete without a user terminating, we must hide the errors that arise
from using the stdin stream for the less process after the process is terminated.

Depends on D135969

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b88172da7bde
Prevent unwanted errors from showing up in `./mach show-log` after closing `less` before the entire log file has been piped to it r=firefox-build-system-reviewers,mhentges

Comment 7

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/b88172da7bde