Crash in progress-bar

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

Leo Famulari <leo@famulari.name> writes:

[...]

In the last line of the 'progress-bar' procedure in (guix progress),

reproduced below, the 'empty' variable was apparently -51.

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

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

[...]

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’.

On Mon, Oct 15, 2018 at 11:20:42AM +0200, Ludovic Courtès wrote:

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

From https://www.unicode.org/Public/UNIDATA/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%

Hello,

Leo Famulari <leo@famulari.name> skribis:

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’.

I’ve just got the very same error:

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

Hello,

Ricardo Wurmus <rekado@elephly.net> skribis:

Clément just pushed a couple of fixes in this area. Clément, is this

what you fixed?

Thanks,

Ludo’.

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

[...]

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

Clément