bug#33030: Crash in progress-bar

[Mark H Weaver <mhw@netris.org>]

Leo Famulari <leo@famulari.name> writes:

> While updating my installed packages, Guix crashed as shown below. I
> don't really know how to interpret it.
>
> $ guix --version
> guix (GNU Guix) aa227b3be3d7728331a08dbd139c47c9b271dc23
> Copyright (C) 2018 the Guix authors
> License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
> This is free software: you are free to change and redistribute it.
> There is NO WARRANTY, to the extent permitted by law.
> $ ./pre-inst-env guix package -u .
> [...]
> downloading from https://private.mirror/guix/nar/gzip/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt...
> Backtrace:.txt  347KiB                               1.4MiB/s 00:00 [################  ]  92.3%

[...]

> In guix/status.scm:
>    474:13  4 (write! _ _ 181)
>     422:6  3 (_ (download-progress "/gnu/store/iql35g1g5q9dkap5s…" …) …)
> In guix/progress.scm:
>    208:33  2 (display-download-progress _ _ #:start-time _ # _ # _)
>    183:12  1 (progress-bar _ _)
> In unknown file:
>            0 (make-string -51 #\space)
>
> ERROR: In procedure make-string:
> Value out of range 0 to 18446744073709551615: -51

In the last line of the 'progress-bar' procedure in (guix progress),
reproduced below, the 'empty' variable was apparently -51.

--8<---------------cut here---------------start------------->8---
(define* (progress-bar % #:optional (bar-width 20))
  "Return % as a string representing an ASCII-art progress bar.  The total
width of the bar is BAR-WIDTH."
  (let* ((bar-width (max 3 (- bar-width 2)))
         (fraction (/ % 100))
         (filled   (inexact->exact (floor (* fraction bar-width))))
         (empty    (- bar-width filled)))
    (format #f "[~a~a]"
            (make-string filled #\#)
            (make-string empty #\space))))
--8<---------------cut here---------------end--------------->8---

The 'bar-width' argument must have been the default 20, since the caller
on line 208 of the same file didn't pass a second argument.  Therefore,
the inner 'bar-width' variable was 18.  (confusing variable name)

Based on the fact that 'empty' is -51 and 'bar-width' is 18, we can
conclude that 'filled' must have been 69.  It follows that 'fraction'
must have been somewhere between 3.8333... and 3.8888..., and therefore
that '%' (a confusingly named argument, IMO) was between 383 and 388.

Following this back to the caller, 'display-download-progress' in the
same file, it appears that 'transferred' was about 3.8 times larger than
'size'.  Both 'transferred' and 'size' are arguments, so the problem is
not here either.

Looking further up the call stack, this is apparently coming from
'process-line' in 'build-event-output-port', i.e. from a faulty trace
being printed by the downloader, which I guess is the substituter in
this case.

I don't have time to diagnose this further right now, but hopefully this
partial investigation will be of some help.

To aid future debugging of this new download/status code that was
revamped in commit dc0f74e5fc26977a3ee6c4f2aa74a141f4359982, I would
suggest adding more assertions to this code on the build side, so that
the error message would be closer to the source of the bug.  In
particular, it would be good to check that the status updates being
printed on the build side are sane, for example that the value of
'transferred' being printed is actually a number, and within the
expected range.  If it's bogus, it would be useful for that to lead to a
error and backtrace on the _build_ side, instead of causing an error on
the client side.

Bug 32895 (file progress reporter crashes on small files) was another
bug that would have been much easier to track down with such assertions.
In that case, the build side was printing "#f" for the 'transferred'
field in one of its status reports, leading to an error on the client
side.

       Mark