GNU bug report logs - #43518
(guix status) occasionally crashes when max-jobs > 1

Previous Next

Full log

View this message in rfc822 format

From: Ludovic Courtès <ludo <at> gnu.org>
To: Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Cc: 43518 <at> debbugs.gnu.org
Subject: bug#43518: Guix substitute crash in procedure raise-exception: wrong type agument in position 1: #f
Date: Sat, 03 Oct 2020 11:37:47 +0200

Hi,

Maxim Cournoyer <maxim.cournoyer <at> gmail.com> skribis:

> Ludovic Courtès <ludo <at> gnu.org> writes:
>
>> Hi,
>>
>> Maxim Cournoyer <maxim.cournoyer <at> gmail.com> skribis:
>>
>>> downloading from https://ci.guix.gnu.org/nar/6m9zimmw8p6gbc1yfbg454c1r587b7h4-gcc-10.2.0.tar.xz ...
>> […]
>>>  gcc-10.2.0.tar.xz  74.3MiB                                     1.1MiB/s 00:25 [#######           ]  39.1%Backtrace:
>> […]
>>> In unknown file:
>>>            5 (display "@ substituter-succeeded /gnu/store/r06j3ms57z4mzfpdzfclsi3i9hr4184g-module-imp…" …)
>>> In guix/status.scm:
>>>    699:16  4 (write! _ _ _)
>>>     613:6  3 (_ (download-progress "/gnu/store/6m9zimmw8p6gbc1yfbg454c1r587b7h4-gcc-10.2.0.tar.xz" # …) …)
>>> In guix/progress.scm:
>>>    213:14  2 (display-download-progress "6m9zimmw8p6gbc1yfbg454c1r58@" _ #:start-time _ #:transferred _ …)
>>> In ice-9/boot-9.scm:
>>>   1669:16  1 (raise-exception _ #:continuable? _)
>>>   1669:16  0 (raise-exception _ #:continuable? _)
>>>
>>> ice-9/boot-9.scm:1669:16: In procedure raise-exception:
>>> In procedure =: Wrong type argument in position 1: #f
>>
>> If you have a case that’s reproducible, please take advantage of it and
>> add ‘pk’ calls in (guix progress) to see what happens.  Here it seems
>> that ‘transferred’ (in ‘display-download-progress’) is #f.
>>
>> The #f would come from this clause in (guix status):
>>
>>      ('download-progress item uri
>>                          (= string->number size)
>>                          (= string->number transferred))  ;<- here
>>
>> That in turn comes from ‘progress-reporter/trace’, called from (guix
>> scripts substitute).
>
> It's a bit difficult for me to follow the calls here :-).  I thought
> it'd have to be in 'progress-reporter/file' because that's the only one
> that ends up calling display-download-progress.  The line 213 of (guix
> progress) is:
>
>       (unless (zero? transferred)
>
> and if transferred is #f that would indeed fail with the error message
> shown in the backtrace, so it seems you are correct in your analysis.

That’s correct.

The “@ download-progress” line is printed by (guix scripts substitute)
and later consumed by (guix status) in the client, which is why I
mentioned ‘progress-reporter/trace’ above.

I think the problem we’re looking at could occur if those traces are not
printed in an atomic way, and thus (guix status) gets to see
truncated/mixed up traces.  So I tried this:

  _NIX_OPTIONS=print-extended-build-trace=1 sudo -E \
    ./pre-inst-env strace -s 200 -o ,,s  guix substitute \
       --substitute /gnu/store/pknm43xsza6nlc7bn27djip8fis92akd-gcc-toolchain-10.2.0 /tmp/t.drv

It shows that traces are printed in a single write(2) call:

--8<---------------cut here---------------start------------->8---
write(2, "@ download-progress /tmp/t.drv http://ci.guix.gnu.org/nar/lzip/pknm43xsza6nlc7bn27djip8fis92akd-gcc-toolchain-10.2.0 4843 4843\n", 127) = 127
--8<---------------cut here---------------end--------------->8---

So this side of things seems to be good.  But then traces could be
mangled/truncated by the daemon maybe.  An strace log of the failing
case would be very helpful.

Thanks,
Ludo’.

Previous Next

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