Package: guix;
Reported by: Maxim Cournoyer <maxim.cournoyer <at> gmail.com>
Date: Sat, 19 Sep 2020 17:36:01 UTC
Severity: important
View this message in rfc822 format
From: Maxim Cournoyer <maxim.cournoyer <at> gmail.com> To: Ludovic Courtès <ludo <at> gnu.org> Cc: 43518 <at> debbugs.gnu.org Subject: bug#43518: Guix substitute crash in procedure raise-exception: wrong type agument in position 1: #f Date: Mon, 18 Jan 2021 22:43:06 -0500
Hello,
Maxim Cournoyer <maxim.cournoyer <at> gmail.com> writes:
> Hello Ludovic,
>
> Maxim Cournoyer <maxim.cournoyer <at> gmail.com> writes:
>
>> Hello again!
>>
>> Maxim Cournoyer <maxim.cournoyer <at> gmail.com> writes:
>>
>>> Hello!
>>>
>>> Ludovic Courtès <ludo <at> gnu.org> writes:
>>>
>>> [...]
>>>
>>>> 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:
>>>>
>>>> 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
>>>>
>>>> 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.
>>
>> [...]
>>
>> I managed to capture two instances of 'transferred= #f' from my pk
>> output in the attached logs. Curiously, they didn't lead to the crash.
>> Attached is a pruned version of the strace log of a command like
>> './pre-inst-env guix package -m my-manifest --max-jobs=20'. Offloading
>> was in use.
>
> The trace attached is even better, in that it triggered the problem! I
> don't have time to take a look now, but I hope it'll be useful in
> understanding the issue better. It's rather precious (quite some luck
> seems to be needed to reproduce) :-).
>
[...]
> write(1, ";;; (print-build-event:download-progress transferred= #f)\n", 58) = 58
> write(1, "\n", 1) = 1
> write(1, ";;; (simultaneous-jobs= 1)\n", 27) = 27
> write(1, "\n", 1) = 1
> write(1, ";;; (display-download-progress file= \"https:@\" size= #f transferred= #f)\n", 73) = 73
> write(2, "Backtrace:\n", 11) = 11
> futex(0x7f81fbe97648, FUTEX_WAKE_PRIVATE, 2147483647) = 0
> write(2, "In ice-9/boot-9.scm:\n", 21) = 21
> write(2, " 1731:15 19 (with-exception-handler #<procedure 7f81f8667210 at ice-9/boot-9.scm:1815:7 (exn)> _ # _ # \342\200\246)\n", 109) = 109
> write(2, "In guix/scripts/package.scm:\n", 29) = 29
> write(2, " 972:10 18 (_)\n", 17) = 17
> write(2, "In guix/status.scm:\n", 20) = 20
> write(2, " 777:4 17 (call-with-status-report _ _)\n", 43) = 43
> write(2, "In guix/store.scm:\n", 19) = 19
> write(2, " 1301:8 16 (call-with-build-handler _ _)\n", 43) = 43
> write(2, " 1301:8 15 (call-with-build-handler #<procedure 7f81f866d5d0 at guix/ui.scm:1169:2 (continue store \342\200\246> \342\200\246)\n", 111) = 111
> write(2, "In guix/scripts/package.scm:\n", 29) = 29
> write(2, " 895:2 14 (_)\n", 17) = 17
> write(2, "In guix/build/syscalls.scm:\n", 28) = 28
> write(2, " 1167:4 13 (call-with-file-lock/no-wait _ _ _)\n", 49) = 49
> write(2, "In guix/scripts/package.scm:\n", 29) = 29
> write(2, " 144:19 12 (build-and-use-profile #<store-connection 256.99 7f81f6934870> \"/var/guix/profiles/per-u\342\200\246\" \342\200\246)\n", 111) = 111
> mmap(NULL, 262144, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f81e1d3f000
> write(2, "In guix/store.scm:\n", 19) = 19
> write(2, " 2049:24 11 (run-with-store #<store-connection 256.99 7f81f6934870> _ #:guile-for-build _ #:system _ # \342\200\246)\n", 109) = 109
> write(2, "In guix/profiles.scm:\n", 22) = 22
> write(2, " 1598:2 10 (_ _)\n", 19) = 19
> write(2, " 348:2 9 (_ _)\n", 19) = 19
> write(2, "In guix/store.scm:\n", 19) = 19
> write(2, " 1931:12 8 (_ #<store-connection 256.99 7f81f6934870>)\n", 57) = 57
> write(2, " 1358:5 7 (map/accumulate-builds #<store-connection 256.99 7f81f6934870> _ _)\n", 81) = 81
> write(2, " 1369:15 6 (_ #<store-connection 256.99 7f81f6934870> _ _)\n", 61) = 61
> write(2, " 741:13 5 (process-stderr _ _)\n", 34) = 34
> write(2, "In unknown file:\n", 17) = 17
> write(2, " 4 (display \"@ substituter-succeeded /gnu/store/srcpjs17wygd5f7fa251j716n2lvdlrz-gwenhywfar\342\200\246\" \342\200\246)\n", 111) = 111
> write(2, "In guix/status.scm:\n", 20) = 20
> write(2, " 700:16 3 (write! _ _ _)\n", 28) = 28
> write(2, " 614:6 2 (_ (download-progress \"/gnu/store/ypz9jjlv4gkfd4m2n359d9ixma0sfydz-ghc-8.6.5\" \"https:@\" \342\200\246) \342\200\246)\n", 111) = 111
> write(2, "In guix/progress.scm:\n", 22) = 22
> write(2, " 214:14 1 (display-download-progress \"https:@\" _ #:start-time _ #:transferred _ #:log-port _)\n", 97) = 97
> write(2, "In ice-9/boot-9.scm:\n", 21) = 21
> write(2, " 1669:16 0 (raise-exception _ #:continuable? _)\n", 50) = 50
> write(2, "\n", 1) = 1
> futex(0x7f81fbe97650, FUTEX_WAKE_PRIVATE, 2147483647) = 0
> futex(0x7f81fbe97ce8, FUTEX_WAKE_PRIVATE, 2147483647) = 0
> write(2, "ice-9/boot-9.scm:1669:16: In procedure raise-exception:\n", 56) = 56
> write(2, "In procedure =: Wrong type argument in position 1: #f\n", 54) = 54
> fcntl(18, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=0, l_len=0}) = 0
> close(18) = 0
> exit_group(1) = ?
> +++ exited with 1 +++
[...]
Today I stumbled upon this issue while building stuff on core-updates,
with the failure happening at a different place:
--8<---------------cut here---------------start------------->8---
jx934sgqx1qmybvn1yi1yfrgjk-rustc-1.24.1-src.tar.gz 67512512 4259936
Backtrace:
In guix/ui.scm:
2154:12 19 (run-guix-command _ . _)
In ice-9/boot-9.scm:
1736:10 18 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
1731:15 17 (with-exception-handler #<procedure 7f2203d53fc0 at ice-9/boot-9.scm:1815:7 (exn)> _ # _ # ?)
1736:10 16 (with-exception-handler _ _ #:unwind? _ #:unwind-for-type _)
In guix/store.scm:
632:37 15 (thunk)
1301:8 14 (call-with-build-handler _ _)
1301:8 13 (call-with-build-handler #<procedure 7f2203d538a0 at guix/ui.scm:1169:2 (continue store ?> ?)
In guix/status.scm:
780:4 12 (call-with-status-report _ _)
In guix/scripts/environment.scm:
751:14 11 (_)
In guix/store.scm:
2049:24 10 (run-with-store #<store-connection 256.99 7f2205598690> _ #:guile-for-build _ #:system _ # ?)
In guix/scripts/environment.scm:
764:18 9 (_ _)
In guix/store.scm:
1918:38 8 (_ #<store-connection 256.99 7f2200b33d70>)
1369:15 7 (_ #<store-connection 256.99 7f2200b33d70> _ _)
741:13 6 (process-stderr _ _)
In unknown file:
5 (display "gz https://ci.guix.gnu.org/nar/9dlfwa8qza8k6jj9m5a6sw2rkv73nx2m-rustc-1.20.0-s?" ?)
In guix/status.scm:
703:16 4 (write! _ _ _)
616:15 3 (_ (download-succeeded "/gnu/store/9dlfwa8qza8k6jj9m5a6sw2rkv73nx2m-rustc-1.20.0-src.?" ?) ?)
273:33 2 (compute-status _ #<<build-status> building: (#<<build> derivation: "/gnu/store/wmm8ghla?> ?)
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 struct-vtable: Wrong type argument in position 1 (expecting struct): #f
--8<---------------cut here---------------end--------------->8---
Maxim
GNU bug tracking system
Copyright (C) 1999 Darren O. Benham,
1997,2003 nCipher Corporation Ltd,
1994-97 Ian Jackson.