GNU bug report logs - #71299
Better handle "updating substitutes" messages in CI pipelines and dumb terminals

Previous Next

To reply to this bug, email your comments to 71299 AT debbugs.gnu.org.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Richard Sent <richard <at> freakingpenguin.com>
To: bug-guix <at> gnu.org
Subject: Better handle "updating substitutes" messages in CI pipelines and
 dumb terminals
Date: Fri, 31 May 2024 18:10:16 -0400

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.

Message #8 received at 71299 <at> debbugs.gnu.org (full text, mbox):

From: Richard Sent <richard <at> freakingpenguin.com>
To: 71299 <at> debbugs.gnu.org
Subject: Investigation
Date: Sat, 01 Jun 2024 14:39:55 -0400

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.

Message #11 received at 71299 <at> debbugs.gnu.org (full text, mbox):

From: Richard Sent <richard <at> freakingpenguin.com>
To: 71299 <at> debbugs.gnu.org
Subject: Fixed link for demonstration of the problem
Date: Sat, 01 Jun 2024 15:06:21 -0400

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.

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.