bug#43518: Guix substitute crash in procedure raise-exception: wrong type agument in position 1: #f

[Ludovic Courtès]

Hi,

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

> Ludovic Courtès <ludo@gnu.org> writes:
>
>> Hi,
>>
>> Maxim Cournoyer <maxim.cournoyer@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’.