bug#71299: Better handle "updating substitutes" messages in CI pipelines and dumb terminals

bug#71299: Better handle "updating substitutes" messages in CI pipelines and dumb terminals

[Richard Sent]

Hi Guix!

Due to it's nature as an incremental counter (from 0% to 100%), Guix
prints many messages to the terminal when it is updating substitutes.
This hurts CI log files because large portions of the output is filled
with cruft [1]. This problem is made worse because Guix updates
substitutes multiple times during a build.

verbosity=0 can be used to disable ALL output messages. However, this
isn't ideal for automated build pipelines where people need to monitor
the status and review what may have gone wrong.

Because "updating substitutes" prints so many lines to the terminal that
aren't typically relevant from a log reviewer's perspective that hide
useful information, it should be possible to disable just those
messages.

Alternatively, I believe Guix has code to detect when it's attached to a
"dumb" terminal. Perhaps these messages should be conditionally removed
or replaced with a pair of static messages like the following:

--8<---------------cut here---------------start------------->8---
substitute: Updating subsitutes from .....
substitute: Finished updating substitutes from ....
--8<---------------cut here---------------end--------------->8---

This would make log files much easier to parse. Instead of having
potentially thousands of lines printed to the console per "build stage",
it would be limited to 2.

[1]: https://builds.sr.ht/query/log/1238029/update-readme/log
-- 
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.

bug#71299: Investigation

[Richard Sent]

Hi Guix!

I started looking into this problem and unfortunately it looks like it
might be more complicated than I thought.

My initial thought was having two progress-reporters and selecting on
based on a simple conditional if current-error-port was a tty or not.
This would be in guix/scripts/substitute. Unfortunately, this might be a
bit more challenging.

Unlike the other scripts, guix/scripts/substitute is invoked by the
daemon directly. Furthermore, it isn't passed a file descriptor to the
invokers stderr. Instead, it goes through the build daemon. See
nix/libstore/local-store.cc:LocalStore::getLineFromSubstituter.

From my testing calling istty? on that error port always returns #f,
ergo the "simple" progress-reporter is always used and we lose the
interactive progress bars.

Testing this is also a pain as well because it involves changing the
build daemon. In my experience the easiest way is:

1. Change the commit field for the guix package in
package-management.scm to the commit you want to check

2. Update the url field for the guix package to
"file:///path/to/guix/clone"

3. Forcefully disable authentication in guix/build-system/channel.scm

4. Generate an installer image via $ ./pre-inst-env guix system image
gnu/system/install.scm --image-type=iso9660, then boot from that image
and observe the output.

So, that leaves two options that I can see:

1. The daemon stops capturing stderr from the substituter and merely
passes it the daemon's stderr.

  1. Challenging to get right and this may have unforseen consequences.
  Two processes writing freely to the same output at once is a bad idea.

2. The daemon has a isatty? check and sets a flag for the build agent
which is passed along to scripts/substitute.

-- 
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.

bug#71299: Fixed link for demonstration of the problem

[Richard Sent]

I was informed that the link I mentioned in the first issue is
nonpublic. Here's the definitely public build output that demonstrates
the problem, albeit in trimmed form:

https://builds.sr.ht/~freakingpenguin/job/1238029

-- 
Take it easy,
Richard Sent
Making my computer weirder one commit at a time.