Subject: 'guix substitutes' sometimes hangs on glibc 2.27

From: [email-masked] (Ludovic Courtès)
Date: Thu, 21 Jun 2018 13:45:12 +0200

Hello Guix!

When downloading a number of substitutes, ‘guix substitute’ sometimes
hangs for me since the switch to glibc 2.27.  Anyone else experiencing
this?  It’s relatively frequent for me.

The backtrace shows this:

--8<---------------cut here---------------start------------->8---
(gdb) bt
#0  0x00007fbb34bf794d in __GI___pthread_timedjoin_ex (threadid=140441961314048, thread_return=thread_return@entry=0x0, abstime=abstime@entry=0x0, block=block@entry=true)
    at pthread_join_common.c:89
#1  0x00007fbb34bf773c in __pthread_join (threadid=<optimized out>, thread_return=thread_return@entry=0x0) at pthread_join.c:24
#2  0x00007fbb350d7548 in stop_finalization_thread () at finalizers.c:265
#3  0x00007fbb350d7759 in scm_i_finalizer_pre_fork () at finalizers.c:290
#4  0x00007fbb3514f256 in scm_fork () at posix.c:1222
#5  0x00007fbb351477fd in vm_regular_engine (thread=0x7fbb313739d0, vp=0x1569f30, registers=0x52de, resume=884963661) at vm-engine.c:784
#6  0x00007fbb3514ae5a in scm_call_n (proc=<error reading variable: ERROR: Cannot access memory at address 0x355c2030>0x7fbb355c2030, argv=argv@entry=0x7fff856ae7f8, nargs=nargs@entry=1)
    at vm.c:1257
#7  0x00007fbb350ceff7 in scm_primitive_eval (exp=exp@entry=<error reading variable: ERROR: Cannot access memory at address 0x31738cf8>0x164fb00) at eval.c:662
#8  0x00007fbb350cf053 in scm_eval (exp=<error reading variable: ERROR: Cannot access memory at address 0x31738cf8>0x164fb00, 
    module_or_state=module_or_state@entry=<error reading variable: ERROR: Cannot access memory at address 0x354750d8>0x162b140) at eval.c:696
#9  0x00007fbb3511a0b0 in scm_shell (argc=10, argv=0x15f0390) at script.c:454
#10 0x00007fbb350e5add in invoke_main_func (body_data=0x7fff856aed10) at init.c:340
#11 0x00007fbb350c82da in c_body (d=0x7fff856aec50) at continuations.c:422
#12 0x00007fbb351477fd in vm_regular_engine (thread=0x7fbb313739d0, vp=0x1569f30, registers=0x52de, resume=884963661) at vm-engine.c:784
#13 0x00007fbb3514ae5a in scm_call_n (proc=proc@entry=#<smob catch-closure 1564200>, argv=argv@entry=0x0, nargs=nargs@entry=0) at vm.c:1257
#14 0x00007fbb350cdef9 in scm_call_0 (proc=proc@entry=#<smob catch-closure 1564200>) at eval.c:481
#15 0x00007fbb3513a026 in catch (tag=tag@entry=#t, thunk=#<smob catch-closure 1564200>, handler=<error reading variable: ERROR: Cannot access memory at address 0x0>0x15641e0, 
    pre_unwind_handler=<error reading variable: ERROR: Cannot access memory at address 0x0>0x15641c0) at throw.c:137
#16 0x00007fbb3513a365 in scm_catch_with_pre_unwind_handler (key=key@entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#17 0x00007fbb3513a51f in scm_c_catch (tag=tag@entry=#t, body=body@entry=0x7fbb350c82d0 <c_body>, body_data=body_data@entry=0x7fff856aec50, handler=handler@entry=0x7fbb350c8560 <c_handler>, 
    handler_data=handler_data@entry=0x7fff856aec50, pre_unwind_handler=pre_unwind_handler@entry=0x7fbb350c83c0 <pre_unwind_handler>, pre_unwind_handler_data=0x1564b60) at throw.c:377
#18 0x00007fbb350c88c0 in scm_i_with_continuation_barrier (body=body@entry=0x7fbb350c82d0 <c_body>, body_data=body_data@entry=0x7fff856aec50, handler=handler@entry=0x7fbb350c8560 <c_handler>, 
    handler_data=handler_data@entry=0x7fff856aec50, pre_unwind_handler=pre_unwind_handler@entry=0x7fbb350c83c0 <pre_unwind_handler>, pre_unwind_handler_data=0x1564b60) at continuations.c:360
#19 0x00007fbb350c8955 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#20 0x00007fbb35138c3c in with_guile (base=base@entry=0x7fff856aecb8, data=data@entry=0x7fff856aece0) at threads.c:661
#21 0x00007fbb34e2afb8 in GC_call_with_stack_base (fn=fn@entry=0x7fbb35138bf0 <with_guile>, arg=arg@entry=0x7fff856aece0) at misc.c:1949
#22 0x00007fbb35138fd8 in scm_i_with_guile (dynamic_state=<optimized out>, data=data@entry=0x7fff856aece0, func=func@entry=0x7fbb350e5ac0 <invoke_main_func>) at threads.c:704
#23 scm_with_guile (func=func@entry=0x7fbb350e5ac0 <invoke_main_func>, data=data@entry=0x7fff856aed10) at threads.c:710
#24 0x00007fbb350e5c72 in scm_boot_guile (argc=argc@entry=7, argv=argv@entry=0x7fff856aee68, main_func=main_func@entry=0x400ce0 <inner_main>, closure=closure@entry=0x0) at init.c:323
#25 0x0000000000400b80 in main (argc=7, argv=0x7fff856aee68) at guile.c:101
(gdb) info threads
  Id   Target Id         Frame 
* 1    Thread 0x7fbb355cab80 (LWP 21207) "guix substitute" 0x00007fbb34bf794d in __GI___pthread_timedjoin_ex (threadid=140441961314048, thread_return=thread_return@entry=0x0, 
    abstime=abstime@entry=0x0, block=block@entry=true) at pthread_join_common.c:89
  2    Thread 0x7fbb3342c700 (LWP 21208) ".guix-real" 0x00007fbb34bfc552 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fbb3504f6ec <mark_cv+44>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  3    Thread 0x7fbb32c2b700 (LWP 21209) ".guix-real" 0x00007fbb34bfc552 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fbb3504f6ec <mark_cv+44>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  4    Thread 0x7fbb3242a700 (LWP 21210) ".guix-real" 0x00007fbb34bfc552 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x7fbb3504f6ec <mark_cv+44>)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:88
  5    Thread 0x7fbb2eb78700 (LWP 21212) ".guix-real" 0x00007fbb34bffaac in __libc_read (fd=9, buf=buf@entry=0x7fbb2eb77540, nbytes=nbytes@entry=1) at ../sysdeps/unix/sysv/linux/read.c:27
  6    Thread 0x7fbb31373700 (LWP 21214) "guix substitute" 0x00007fbb34bffaac in __libc_read (fd=5, buf=buf@entry=0x7fbb31372a30, nbytes=nbytes@entry=1) at ../sysdeps/unix/sysv/linux/read.c:27
--8<---------------cut here---------------end--------------->8---

The finalization thread is itself stuck reading from its pipe:

--8<---------------cut here---------------start------------->8---
(gdb) thread 6
[Switching to thread 6 (Thread 0x7fbb31373700 (LWP 21214))]
#0  0x00007fbb34bffaac in __libc_read (fd=5, buf=buf@entry=0x7fbb31372a30, nbytes=nbytes@entry=1) at ../sysdeps/unix/sysv/linux/read.c:27
27      in ../sysdeps/unix/sysv/linux/read.c
(gdb) bt
#0  0x00007fbb34bffaac in __libc_read (fd=5, buf=buf@entry=0x7fbb31372a30, nbytes=nbytes@entry=1) at ../sysdeps/unix/sysv/linux/read.c:27
#1  0x00007fbb350d74d7 in read_finalization_pipe_data (data=0x7fbb31372a30) at finalizers.c:199
#2  0x00007fbb34e30b63 in GC_do_blocking_inner (data=0x7fbb313729f0 "\300t\r5\273\177", context=<optimized out>) at pthread_support.c:1353
#3  0x00007fbb34e25389 in GC_with_callee_saves_pushed (fn=0x7fbb34e30b20 <GC_do_blocking_inner>, arg=arg@entry=0x7fbb313729f0 "\300t\r5\273\177") at mach_dep.c:322
#4  0x00007fbb34e2afec in GC_do_blocking (fn=fn@entry=0x7fbb350d74c0 <read_finalization_pipe_data>, client_data=client_data@entry=0x7fbb31372a30) at misc.c:2061
#5  0x00007fbb3513902a in scm_without_guile (func=0x7fbb350d74c0 <read_finalization_pipe_data>, data=0x7fbb31372a30) at threads.c:722
#6  0x00007fbb350d7887 in finalization_thread_proc (unused=<optimized out>) at finalizers.c:212
#7  0x00007fbb350c82da in c_body (d=0x7fbb31372e50) at continuations.c:422
#8  0x00007fbb351477fd in vm_regular_engine (thread=0x5, vp=0x172aea0, registers=0x1, resume=884996780) at vm-engine.c:784
#9  0x00007fbb3514ae5a in scm_call_n (proc=proc@entry=#<smob catch-closure 1c1ff60>, argv=argv@entry=0x0, nargs=nargs@entry=0) at vm.c:1257
#10 0x00007fbb350cdef9 in scm_call_0 (proc=proc@entry=#<smob catch-closure 1c1ff60>) at eval.c:481
#11 0x00007fbb3513a026 in catch (tag=tag@entry=#t, thunk=#<smob catch-closure 1c1ff60>, handler=<error reading variable: ERROR: Cannot access memory at address 0x0>0x1c1ff40, 
    pre_unwind_handler=<error reading variable: ERROR: Cannot access memory at address 0x0>0x1c1ff00) at throw.c:137
#12 0x00007fbb3513a365 in scm_catch_with_pre_unwind_handler (key=key@entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#13 0x00007fbb3513a51f in scm_c_catch (tag=tag@entry=#t, body=body@entry=0x7fbb350c82d0 <c_body>, body_data=body_data@entry=0x7fbb31372e50, handler=handler@entry=0x7fbb350c8560 <c_handler>, 
    handler_data=handler_data@entry=0x7fbb31372e50, pre_unwind_handler=pre_unwind_handler@entry=0x7fbb350c83c0 <pre_unwind_handler>, pre_unwind_handler_data=0x1564b60) at throw.c:377
#14 0x00007fbb350c88c0 in scm_i_with_continuation_barrier (body=body@entry=0x7fbb350c82d0 <c_body>, body_data=body_data@entry=0x7fbb31372e50, handler=handler@entry=0x7fbb350c8560 <c_handler>, 
    handler_data=handler_data@entry=0x7fbb31372e50, pre_unwind_handler=pre_unwind_handler@entry=0x7fbb350c83c0 <pre_unwind_handler>, pre_unwind_handler_data=0x1564b60) at continuations.c:360
#15 0x00007fbb350c8955 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#16 0x00007fbb35138c3c in with_guile (base=base@entry=0x7fbb31372eb8, data=data@entry=0x7fbb31372ee0) at threads.c:661
#17 0x00007fbb34e2afb8 in GC_call_with_stack_base (fn=fn@entry=0x7fbb35138bf0 <with_guile>, arg=arg@entry=0x7fbb31372ee0) at misc.c:1949
#18 0x00007fbb35138fd8 in scm_i_with_guile (dynamic_state=<optimized out>, data=<optimized out>, func=<optimized out>) at threads.c:704
#19 scm_with_guile (func=<optimized out>, data=<optimized out>) at threads.c:710
#20 0x00007fbb34bf6567 in start_thread (arg=0x7fbb31373700) at pthread_create.c:463
#21 0x00007fbb3351eeaf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
--8<---------------cut here---------------end--------------->8---

The ‘primitive-fork’ call itself presumably comes from
‘decompressed-port’, used in (guix scripts substitute).

Ludo’.