bug#33030: Crash in progress-bar

bug#33030: Crash in progress-bar

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 2173 bytes --]

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/scripts/package.scm:
   910:10 19 (_)
In guix/status.scm:
    513:4 18 (call-with-status-report _ _)
In guix/scripts/package.scm:
   918:14 17 (_)
   870:19 16 (process-actions #<build-daemon 256.98 2768f50> _)
    595:4 15 (options->installable ((upgrade . ".") (# . 0) (. #) …) …)
In srfi/srfi-1.scm:
   501:18 14 (fold-right #<procedure 255ec80 at guix/scripts/pack…> . #)
In guix/scripts/package.scm:
   236:37 13 (transaction-upgrade-entry _ #<<manifest-transaction> i…>)
In guix/packages.scm:
   881:14 12 (cache! #<weak-table 1587/3517> #<package mpv@0.29.1 g…> …)
In unknown file:
          11 (_ #<procedure thunk ()> #<procedure list _> #<undefined>)
In guix/grafts.scm:
    303:4 10 (graft-derivation #<build-daemon 256.98 2768f50> #<der…> …)
    181:4  9 (references-oracle #<build-daemon 256.98 2768f50> #<der…>)
   190:20  8 (_ _ _)
In guix/store.scm:
  1087:15  7 (_ #<build-daemon 256.98 2768f50> _ _)
   661:13  6 (process-stderr _ _)
In unknown file:
           5 (display "@ download-progress /gnu/store/iql35g1g5q9dk…" …)
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


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#33030: Crash in progress-bar

[Mark H Weaver]

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

bug#33030: Crash in progress-bar

[Ludovic Courtès]

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

> $ 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%

[...]

>    208:33  2 (display-download-progress _ _ #:start-time _ # _ # _)
>    183:12  1 (progress-bar _ _)
> In unknown file:
>            0 (make-string -51 #\space)

Could you run:

  guix build --log-file \
    /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt

and post the contents of the file?

This should allow us to bridge the gap with Mark’s analysis.

Thanks in advance,
Ludo’.

bug#33030: Crash in progress-bar

[Leo Famulari]

[-- Attachment #1.1: Type: text/plain, Size: 572 bytes --]

On Mon, Oct 15, 2018 at 11:20:42AM +0200, Ludovic Courtès wrote:
> Could you run:
> 
>   guix build --log-file \
>     /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt
> 
> and post the contents of the file?

This log was actually found on Hydra for me (that private mirror is of
Hydra):

$ guix build --log-file /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt       
https://mirror.hydra.gnu.org/log/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt

I've attached it instead of pasting it in case my our mail clients
mangle the contents.

[-- Attachment #1.2: iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt --]
[-- Type: text/plain, Size: 1075 bytes --]

/gnu/store/kpxi8h3669afr9r1bgvaf9ij3y4wdyyn-bash-minimal-4.4.12/bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.utf8)
/gnu/store/kpxi8h3669afr9r1bgvaf9ij3y4wdyyn-bash-minimal-4.4.12/bin/bash: warning: setlocale: LC_ALL: cannot change locale (en_US.utf8)
guile: warning: failed to install locale
warning: failed to install locale: Invalid argument

Starting download of /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt
From https://www.unicode.org/Public/UNIDATA/NamesList.txt...
warning: TLS warning alert received: unrecognized-name
\r^[[K NamesList.txt  1.5MiB                  0B/s 00:00 [                    ]   0.0%\r^[[K NamesList.txt  1.5MiB              265KiB/s 00:00 [                    ]   4.3%\r^[[K NamesList.txt  1.5MiB              441KiB/s 00:01 [###                 ]  17.1%\r^[[K NamesList.txt  1.5MiB              771KiB/s 00:01 [#########           ]  46.9%\r^[[K NamesList.txt  1.5MiB              1.2MiB/s 00:01 [################### ]  98.1%\r^[[K NamesList.txt  1.5MiB              1.2MiB/s 00:01 [####################] 100.0%

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#33030: Crash in progress-bar

[Ludovic Courtès]

Hello,

Leo Famulari <leo@famulari.name> skribis:

> On Mon, Oct 15, 2018 at 11:20:42AM +0200, Ludovic Courtès wrote:
>> Could you run:
>> 
>>   guix build --log-file \
>>     /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt
>> 
>> and post the contents of the file?
>
> This log was actually found on Hydra for me (that private mirror is of
> Hydra):

Oh, so the faulty “download-progress” traces must have come from
‘guix substitute’ instead.

Hmm, do you have a way to reproduce this?  I started a fresh build of
ibus yesterday to trigger the download of this file but I failed to
reproduce it.

Thanks,
Ludo’.

bug#33030: Crash in progress-bar

[Ricardo Wurmus]

I’ve just got the very same error:

--8<---------------cut here---------------start------------->8---
downloading from https://berlin.guixsd.org/nar/gzip/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt...
Backtrace:
In guix/scripts/package.scm:
   913:10 19 (_)
In guix/status.scm:
    600:4 18 (call-with-status-report _ _)
In guix/scripts/package.scm:
   921:14 17 (_)
   873:19 16 (process-actions #<build-daemon 256.98 1b9ff50> _)
    598:4 15 (options->installable ((upgrade . #f) (verbosity . 0) (graft? . #t) (substitutes? . #t) (# . #t) # # …) …)
In srfi/srfi-1.scm:
   501:18 14 (fold-right #<procedure 1b98700 at guix/scripts/package.scm:598:16 (entry transaction)> _ _ . _)
In guix/scripts/package.scm:
   238:37 13 (transaction-upgrade-entry _ #<<manifest-transaction> install: (#<<manifest-entry> name: "qtractor" ve…>)
In guix/packages.scm:
   881:14 12 (cache! #<weak-table 970/1759> #<package alsa-plugins@1.1.6 gnu/packages/linux.scm:1060 2d9c300> (. #) _)
In unknown file:
          11 (_ #<procedure thunk ()> #<procedure list _> #<undefined>)
In guix/grafts.scm:
    303:4 10 (graft-derivation #<build-daemon 256.98 1b9ff50> #<derivation /gnu/store/cy3q34absx81bfygp33ji4nxi7m1…> …)
    181:4  9 (references-oracle #<build-daemon 256.98 1b9ff50> #<derivation /gnu/store/cy3q34absx81bfygp33ji4nxi7m1…>)
   190:20  8 (_ _ _)
In guix/store.scm:
  1100:15  7 (_ #<build-daemon 256.98 1b9ff50> _ _)
   661:13  6 (process-stderr _ _)
In unknown file:
           5 (display "@ download-progress /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt https://berli…" …)
In guix/status.scm:
   521:16  4 (write! _ _ _)
    439:6  3 (_ (download-progress "/gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt" "https://berlin.…" …) …)
In guix/progress.scm:
   208:33  2 (display-download-progress _ _ #:start-time _ #:transferred _ #:log-port _)
   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
--8<---------------cut here---------------end--------------->8---

I do not have a local log file for the download of that file.

“guix build --log-file /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt” prints
“https://mirror.hydra.gnu.org/log/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt”.

--
Ricardo

bug#33030: Crash in progress-bar

[Ludovic Courtès]

Hello,

Ricardo Wurmus <rekado@elephly.net> skribis:

> I’ve just got the very same error:
>
> downloading from https://berlin.guixsd.org/nar/gzip/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt...
> Backtrace:
> In guix/scripts/package.scm:
>    913:10 19 (_)
> In guix/status.scm:
>     600:4 18 (call-with-status-report _ _)
> In guix/scripts/package.scm:
>    921:14 17 (_)
>    873:19 16 (process-actions #<build-daemon 256.98 1b9ff50> _)
>     598:4 15 (options->installable ((upgrade . #f) (verbosity . 0) (graft? . #t) (substitutes? . #t) (# . #t) # # …) …)
> In srfi/srfi-1.scm:
>    501:18 14 (fold-right #<procedure 1b98700 at guix/scripts/package.scm:598:16 (entry transaction)> _ _ . _)
> In guix/scripts/package.scm:
>    238:37 13 (transaction-upgrade-entry _ #<<manifest-transaction> install: (#<<manifest-entry> name: "qtractor" ve…>)
> In guix/packages.scm:
>    881:14 12 (cache! #<weak-table 970/1759> #<package alsa-plugins@1.1.6 gnu/packages/linux.scm:1060 2d9c300> (. #) _)
> In unknown file:
>           11 (_ #<procedure thunk ()> #<procedure list _> #<undefined>)
> In guix/grafts.scm:
>     303:4 10 (graft-derivation #<build-daemon 256.98 1b9ff50> #<derivation /gnu/store/cy3q34absx81bfygp33ji4nxi7m1…> …)
>     181:4  9 (references-oracle #<build-daemon 256.98 1b9ff50> #<derivation /gnu/store/cy3q34absx81bfygp33ji4nxi7m1…>)
>    190:20  8 (_ _ _)
> In guix/store.scm:
>   1100:15  7 (_ #<build-daemon 256.98 1b9ff50> _ _)
>    661:13  6 (process-stderr _ _)
> In unknown file:
>            5 (display "@ download-progress /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt https://berli…" …)
> In guix/status.scm:
>    521:16  4 (write! _ _ _)
>     439:6  3 (_ (download-progress "/gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt" "https://berlin.…" …) …)
> In guix/progress.scm:
>    208:33  2 (display-download-progress _ _ #:start-time _ #:transferred _ #:log-port _)
>    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

Clément just pushed a couple of fixes in this area.  Clément, is this
what you fixed?

Thanks,
Ludo’.

bug#33030: Crash in progress-bar

[Clément Lassieur]

Ludovic Courtès <ludo@gnu.org> writes:

> Hello,
>
> Ricardo Wurmus <rekado@elephly.net> skribis:
>
>> I’ve just got the very same error:

[...]

>> ERROR: In procedure make-string:
>> Value out of range 0 to 18446744073709551615: -51
>
> Clément just pushed a couple of fixes in this area.  Clément, is this
> what you fixed?

No, what I fixed is related to guix-publish being run without --cache.

Clément