GNU bug report logs - #33030
Crash in progress-bar

Previous Next

To reply to this bug, email your comments to 33030 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: Leo Famulari <leo <at> famulari.name>
To: bug-guix <at> gnu.org
Subject: Crash in progress-bar
Date: Fri, 12 Oct 2018 22:53:08 -0400

[Message part 1 (text/plain, inline)]

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 <at> 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

[signature.asc (application/pgp-signature, inline)]

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

From: Mark H Weaver <mhw <at> netris.org>
To: Leo Famulari <leo <at> famulari.name>
Cc: 33030 <at> debbugs.gnu.org
Subject: Re: bug#33030: Crash in progress-bar
Date: Sat, 13 Oct 2018 18:39:17 -0400

Leo Famulari <leo <at> 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

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

From: ludo <at> gnu.org (Ludovic Courtès)
To: Leo Famulari <leo <at> famulari.name>
Cc: 33030 <at> debbugs.gnu.org
Subject: Re: bug#33030: Crash in progress-bar
Date: Mon, 15 Oct 2018 11:20:42 +0200

Hi Leo,

Leo Famulari <leo <at> 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’.

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

From: Leo Famulari <leo <at> famulari.name>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 33030 <at> debbugs.gnu.org
Subject: Re: bug#33030: Crash in progress-bar
Date: Tue, 16 Oct 2018 00:57:50 -0400

[Message part 1 (text/plain, inline)]

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.

[iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt (text/plain, attachment)]

[signature.asc (application/pgp-signature, inline)]

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

From: ludo <at> gnu.org (Ludovic Courtès)
To: Leo Famulari <leo <at> famulari.name>
Cc: 33030 <at> debbugs.gnu.org
Subject: Re: bug#33030: Crash in progress-bar
Date: Tue, 16 Oct 2018 13:32:00 +0200

Hello,

Leo Famulari <leo <at> 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’.

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

From: Ricardo Wurmus <rekado <at> elephly.net>
To: 33030 <at> debbugs.gnu.org
Subject: Crash in progress-bar
Date: Sun, 11 Nov 2018 21:55:56 +0100

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 <at> 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

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

From: ludo <at> gnu.org (Ludovic Courtès)
To: Ricardo Wurmus <rekado <at> elephly.net>, clement <at> lassieur.org 
Cc: 33030 <at> debbugs.gnu.org
Subject: Re: bug#33030: Crash in progress-bar
Date: Fri, 16 Nov 2018 19:04:12 +0100

Hello,

Ricardo Wurmus <rekado <at> 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 <at> 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’.

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

From: Clément Lassieur <clement <at> lassieur.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: Ricardo Wurmus <rekado <at> elephly.net>, 33030 <at> debbugs.gnu.org
Subject: Re: bug#33030: Crash in progress-bar
Date: Mon, 19 Nov 2018 10:48:57 +0100

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

> Hello,
>
> Ricardo Wurmus <rekado <at> 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

Previous Next

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