Crash in progress-bar

OpenSubmitted by Leo Famulari.
Details
5 participants
  • Clément Lassieur
  • Leo Famulari
  • Ludovic Courtès
  • Mark H Weaver
  • Ricardo Wurmus
Owner
unassigned
Severity
normal
L
L
Leo Famulari wrote on 13 Oct 2018 04:53
(address . bug-guix@gnu.org)
20181013025308.GA22913@jasmine.lan
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 .
[...]
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
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlvBXhQACgkQJkb6MLrK
fwjJtBAA7TaElgL8NPG8955dBEscZjOHJb1YlP/uxAbdiITGAaNgqX77QC2UlUu0
mFNZ8nMJph2lwxR4kWmHHVR0pQI5XPGLsZceqMwqLK8sxcQJpB0jGskrW81tAlvo
7IczKI/E+hCh0c74sCvFnDk4OHHb2yOhDBVjjkTXKv6fkErj1g/rIYshukMxCKcT
BtYY/moecI614F1cKpL3ucijoKdI/WNAYHwcSMPXUfpVnO8JhWcSCs9SPYc0HsO2
Sj18hx74bPPZxs4qO8sBbFgl0zwL8uxZFNfIivxB66h/5U3N6mR+ZM9oele+CpKG
94MnbQVUSi+H3G+dz8TPGg+AUUD46ztDjUt7+TDfe8PxHg53mzaQXcC1KXKVTF+z
lB+tKD8RKgt9dUbO+DAQQ7hWX+gLcNQAl+Y6pdy0oqoXR4Kk8lKtaPxqS5h3sp5t
cz4blrGldNGKN24AzB4sYUtFd2NCfXSppDN4f02ib0TjCuJDP6rV3esa9TpapPiL
IlQjkczxC8iLwPedc3RHm/8GoRX3e54ldLWjo4woYPtcDi49dC+IYTDQ4sn6+pJF
U/9Z1mSFGNWnIuwi7X6PSKQqunPx0u8AjpFSoHGajMtMOoDbGDSOb8UEMjCLoDnM
BQgGFRGqDmW2O2nThvASP/8CyFsb41Tm/P7Sdlk0o2xHDkMLBAE=
=7VAn
-----END PGP SIGNATURE-----


M
M
Mark H Weaver wrote on 14 Oct 2018 00:39
(name . Leo Famulari)(address . leo@famulari.name)(address . 33030@debbugs.gnu.org)
875zy5wjxm.fsf@netris.org
Leo Famulari <leo@famulari.name> writes:

Toggle quote (14 lines)
> 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%

[...]

Toggle quote (12 lines)
> 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.

Toggle snippet (12 lines)
(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))))

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
L
L
Ludovic Courtès wrote on 15 Oct 2018 11:20
(name . Leo Famulari)(address . leo@famulari.name)(address . 33030@debbugs.gnu.org)
87in23k1lh.fsf@gnu.org
Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (11 lines)
> $ 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%

[...]

Toggle quote (5 lines)
> 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’.
L
L
Leo Famulari wrote on 16 Oct 2018 06:57
(name . Ludovic Courtès)(address . ludo@gnu.org)(address . 33030@debbugs.gnu.org)
20181016045750.GA14739@jasmine.lan
On Mon, Oct 15, 2018 at 11:20:42AM +0200, Ludovic Courtès wrote:
Toggle quote (7 lines)
> 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

I've attached it instead of pasting it in case my our mail clients
mangle the contents.
/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
warning: TLS warning alert received: unrecognized-name
 NamesList.txt 1.5MiB 0B/s 00:00 [ ] 0.0%  NamesList.txt 1.5MiB 265KiB/s 00:00 [ ] 4.3%  NamesList.txt 1.5MiB 441KiB/s 00:01 [### ] 17.1%  NamesList.txt 1.5MiB 771KiB/s 00:01 [######### ] 46.9%  NamesList.txt 1.5MiB 1.2MiB/s 00:01 [################### ] 98.1%  NamesList.txt 1.5MiB 1.2MiB/s 00:01 [####################] 100.0%
-----BEGIN PGP SIGNATURE-----

iQIzBAABCAAdFiEEsFFZSPHn08G5gDigJkb6MLrKfwgFAlvFb8oACgkQJkb6MLrK
fwhn5A/8DcQw1Knw0UPaJHTh0dywd737cTNKtLSCiiePMlIpZJjs4c78i5FKfDtB
jZeC99Ml+2dWD7c8UbT7xRo0HZs9zfF7WoxlRVIUGfmlt2RD30NY0oCNHwlmkGgj
txijN/okxEwa24U9OuAzVQ8nCF7ZT4FcBPR0Co4yg66b7xOcjHGu5wNBn6UaPlv9
H89kKIODYd1mNXdCNl1WwXCknMfTCxKjT+R13+4IbEmL7l3QRbD8lBh8XMZce/BW
cMqptui66MOITyKcJgjM8AAszqhm3Mbx51gkk0rY3+0h0qm6fA4YfgmFiPSMkA3v
XLN7fMH8Ce1qq312F3sJsW11UF0v65U+el0j1XmY2B7+4K4H5QaZmT6W2G/AWjDY
TihjBXNdJXBzUMYh4JBnPyi/96M+6bm1oaXvAVWFXRSaD/KYh34Jw5+DQar/hjl9
zX5Fsqtc/zBLfTI+qlD2FIoNDs/wxjnCyqD4UDu6VGb5KVPwr5YYlHzzrjIl0aCw
Bsj9qIIUztVvCFOc/nI68s6nPaUXQvzRqTE0wUdkKCkmWbW/1iy4tWrPncHcdNKI
Cxef0z/J6SWRpQvQLCT9xo6/Uv+q59qu9/jJVdhk7JNQ72EIQMYZpkniY1sZHz7V
Xp47xDfyuSluAHNxlZFP7a+58X1x6yhhANQ8KZqBLsKtbOOzg8g=
=p09x
-----END PGP SIGNATURE-----


L
L
Ludovic Courtès wrote on 16 Oct 2018 13:32
(name . Leo Famulari)(address . leo@famulari.name)(address . 33030@debbugs.gnu.org)
87in22i0un.fsf@gnu.org
Hello,

Leo Famulari <leo@famulari.name> skribis:

Toggle quote (11 lines)
> 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’.
R
R
Ricardo Wurmus wrote on 11 Nov 2018 21:55
Crash in progress-bar
(address . 33030@debbugs.gnu.org)
87r2frwcyr.fsf@elephly.net
I’ve just got the very same error:

Toggle snippet (40 lines)
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

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

“guix build --log-file /gnu/store/iql35g1g5q9dkap5splc7f9ggskr31vl-NamesList.txt” prints

--
Ricardo
L
L
Ludovic Courtès wrote on 16 Nov 2018 19:04
(address . 33030@debbugs.gnu.org)
87sh00vqzn.fsf@gnu.org
Hello,

Ricardo Wurmus <rekado@elephly.net> skribis:

Toggle quote (41 lines)
> 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’.
C
C
Clément Lassieur wrote on 19 Nov 2018 10:48
(name . Ludovic Courtès)(address . ludo@gnu.org)
87bm6lbdo6.fsf@lassieur.org
Ludovic Courtès <ludo@gnu.org> writes:

Toggle quote (6 lines)
> Hello,
>
> Ricardo Wurmus <rekado@elephly.net> skribis:
>
>> I’ve just got the very same error:

[...]

Toggle quote (6 lines)
>> 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
?