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

[Maxim Cournoyer]

Hello,

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

> Hello Ludovic,
>
> Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:
>
>> Hello again!
>>
>> Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:
>>
>>> Hello!
>>>
>>> Ludovic Courtès <ludo@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