GNU bug report logs - #29335
'guix publish' workers occasionally crash

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 29335 in the body.
You can then email your comments to 29335 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: bug-guix <at> gnu.org
Subject: 'guix publish' workers occasionally crash
Date: Fri, 17 Nov 2017 11:10:49 +0100

Hello,

On berlin I’ve noticed that the ‘guix publish’ workers would
occasionally stop working: the main thread would keep replying to HTTP
requests, but the worker threads would no longer do anything, and would
leave behind them a bunch of .tmp files in /var/cache/guix/publish.

I captured the output of ‘guix publish’ (guix-0.13.0-8.357ab93) and the
only clue I have is this:

--8<---------------cut here---------------start------------->8---
GET /6kl9ydqmgklcqhxswg6v5isq5n1ih5gp.narinfo
In guix/workers.scm:
     74:9  2 (_)
    78:32  1 (_ srfi-34 #<condition &nix-connection-error [file: "/v…>)
In unknown file:
           0 (make-stack #t)
ERROR: In procedure make-stack:
ERROR: Throw to key `srfi-34' with args `(#<condition &nix-connection-error [file: "/var/guix/daemon-socket/socket" errno: 9] 3ba2ea0>)'.
GET /fgiih42mg2sr82mbmzf56grvrf021im6.narinfo
--8<---------------cut here---------------end--------------->8---

… where 9 is EBADF.

The open files are:

--8<---------------cut here---------------start------------->8---
ludo <at> berlin ~$ sudo ls -l /proc/4105/fd
total 0
l-wx------ 1 root root 64 Nov 17 04:00 0 -> /dev/null
l-wx------ 1 root root 64 Nov 17 04:00 1 -> /home/ludo/nohup.out
lr-x------ 1 root root 64 Nov 17 04:00 10 -> pipe:[9911558]
l-wx------ 1 root root 64 Nov 17 04:00 11 -> pipe:[9911558]
lr-x------ 1 root root 64 Nov 17 04:00 12 -> pipe:[9900923]
l-wx------ 1 root root 64 Nov 17 04:00 13 -> pipe:[9900923]
lrwx------ 1 root root 64 Nov 17 04:00 14 -> socket:[9911560]
lrwx------ 1 root root 64 Nov 17 04:00 15 -> socket:[9911563]
lr-x------ 1 root root 64 Nov 17 04:00 16 -> pipe:[9912323]
l-wx------ 1 root root 64 Nov 17 04:00 17 -> pipe:[9912323]
lr-x------ 1 root root 64 Nov 17 04:00 18 -> pipe:[9909649]
l-wx------ 1 root root 64 Nov 17 04:00 19 -> pipe:[9909649]
l-wx------ 1 root root 64 Nov 17 04:00 2 -> /home/ludo/nohup.out
lr-x------ 1 root root 64 Nov 17 04:00 20 -> pipe:[9908165]
l-wx------ 1 root root 64 Nov 17 04:00 21 -> pipe:[9908165]
lr-x------ 1 root root 64 Nov 17 04:00 22 -> pipe:[9899432]
l-wx------ 1 root root 64 Nov 17 04:00 23 -> pipe:[9899432]
lr-x------ 1 root root 64 Nov 17 04:00 24 -> pipe:[9911564]
l-wx------ 1 root root 64 Nov 17 04:00 25 -> pipe:[9911564]
lr-x------ 1 root root 64 Nov 17 04:00 26 -> pipe:[9908166]
l-wx------ 1 root root 64 Nov 17 04:00 27 -> pipe:[9908166]
l-wx------ 1 root root 64 Nov 17 04:00 28 -> /var/cache/guix/publish/gzip/11vik22bwzzvwksd1l08frhcm3v3hhmm-dealii-8.5.1.nar.tmp
l-wx------ 1 root root 64 Nov 17 04:00 29 -> /var/cache/guix/publish/gzip/k90h1bkmsiq8qxrhk31l5c8maiqmy5k0-zathura-pdf-mupdf-0.3.1.nar.tmp
lr-x------ 1 root root 64 Nov 17 04:00 3 -> pipe:[9902378]
lr-x------ 1 root root 64 Nov 17 04:00 30 -> /gnu/store/2xp8n6k6mbfgi8972lj0vvk52gfx4576-linux-libre-4.9.61/lib/modules/4.9.61-gnu/kernel/drivers/net/ethernet/intel/i40evf
lr-x------ 1 root root 64 Nov 17 04:00 31 -> /gnu/store/k90h1bkmsiq8qxrhk31l5c8maiqmy5k0-zathura-pdf-mupdf-0.3.1/share
l-wx------ 1 root root 64 Nov 17 04:00 32 -> /var/cache/guix/publish/gzip/xa6bwlgm82xwfg9icl4d9bs2bhj8cb1a-perl-safe-isa-1.000008.nar.tmp
l-wx------ 1 root root 64 Nov 17 04:00 33 -> /var/cache/guix/publish/gzip/2xp8n6k6mbfgi8972lj0vvk52gfx4576-linux-libre-4.9.61.nar.tmp
lr-x------ 1 root root 64 Nov 17 04:00 34 -> /gnu/store/11vik22bwzzvwksd1l08frhcm3v3hhmm-dealii-8.5.1/share
l-wx------ 1 root root 64 Nov 17 04:00 4 -> pipe:[9902378]
lr-x------ 1 root root 64 Nov 17 04:00 5 -> pipe:[9902379]
l-wx------ 1 root root 64 Nov 17 04:00 6 -> pipe:[9902379]
lr-x------ 1 root root 64 Nov 17 04:00 7 -> /gnu/store/sk1w5whws8xhvb03sm2h44f9fm6c2gkc-guix-0.13.0-8.357ab93/bin/.guix-real
lr-x------ 1 root root 64 Nov 17 04:00 8 -> pipe:[9910685]
l-wx------ 1 root root 64 Nov 17 04:00 9 -> pipe:[9910685]
--8<---------------cut here---------------end--------------->8---

Ludo’.

Message #8 received at 29335 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: 29335 <at> debbugs.gnu.org
Subject: Re: bug#29335: 'guix publish' workers occasionally crash
Date: Fri, 17 Nov 2017 13:22:58 +0100

If we look at our worker threads, they’re all stuck in mutex_lock:

--8<---------------cut here---------------start------------->8---
(gdb) info threads
  Id   Target Id         Frame
* 1    Thread 0x7f7ee99d5f00 (LWP 4105) "guix publish" 0x00007f7ee79c60ad in poll () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6
  2    Thread 0x7f7ee78e6700 (LWP 4106) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  3    Thread 0x7f7ee70e5700 (LWP 4107) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  4    Thread 0x7f7ee68e4700 (LWP 4108) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  5    Thread 0x7f7ee60e3700 (LWP 4109) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  6    Thread 0x7f7ee58e2700 (LWP 4110) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  7    Thread 0x7f7ee50e1700 (LWP 4111) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  8    Thread 0x7f7ee48e0700 (LWP 4112) ".guix-real" 0x00007f7ee900d58f in pthread_cond_wait@@GLIBC_2.3.2 () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  9    Thread 0x7f7ee3a4f700 (LWP 4113) ".guix-real" 0x00007f7ee9010aed in read () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  10   Thread 0x7f7ee114b700 (LWP 4114) ".guix-real" 0x00007f7ee9010aed in read () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  11   Thread 0x7f7edf892700 (LWP 4116) "publish worker" 0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  12   Thread 0x7f7edf090700 (LWP 4117) "publish worker" 0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  13   Thread 0x7f7ede88e700 (LWP 4118) "publish worker" 0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  14   Thread 0x7f7ede08c700 (LWP 4119) "publish worker" 0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  15   Thread 0x7f7edd88a700 (LWP 4120) "publish worker" 0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
  16   Thread 0x7f7edd088700 (LWP 4121) "publish worker" 0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
(gdb) thread apply 11-16 bt

Thread 11 (Thread 0x7f7edf892700 (LWP 4116)):
#0  0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#1  0x00007f7ee9009b05 in pthread_mutex_lock () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#2  0x00007f7ee9545815 in scm_pthread_mutex_lock (mutex=<optimized out>) at threads.c:1600
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94e2927 in scm_readdir (port=#<unmatched-tag 10a77>) at filesys.c:1749
#5  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bea0, registers=0x0, resume=-385808132) at vm-engine.c:784
#6  0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 20045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#7  0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 20045>) at eval.c:481
#8  0x00007f7ee94cbef8 in scm_call_with_unblocked_asyncs (proc=#<unmatched-tag 20045>) at async.c:400
#9  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bea0, registers=0x0, resume=-385808132) at vm-engine.c:784
#10 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 50045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#11 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
#12 0x00007f7ee9544fe6 in really_launch (d=0x266ab80) at threads.c:793
#13 0x00007f7ee94d4cba in c_body (d=0x7f7edf891e60) at continuations.c:422
#14 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bea0, registers=0x0, resume=-385808132) at vm-engine.c:784
#15 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 1077>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#16 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 1077>) at eval.c:481
#17 0x00007f7ee95464e6 in catch (tag=tag <at> entry=#t, thunk=#<unmatched-tag 1077>, handler=#<unmatched-tag 11077>, pre_unwind_handler=#<unmatched-tag 11077>) at throw.c:137
#18 0x00007f7ee9546825 in scm_catch_with_pre_unwind_handler (key=key <at> entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#19 0x00007f7ee95469df in scm_c_catch (tag=tag <at> entry=#t, body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edf891e60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edf891e60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at throw.c:377
#20 0x00007f7ee94d52a0 in scm_i_with_continuation_barrier (body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edf891e60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edf891e60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at continuations.c:360
#21 0x00007f7ee94d5335 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#22 0x00007f7ee954510c in with_guile (base=0x7f7edf891ec0, data=0x7f7edf891ef0) at threads.c:660
#23 0x00007f7ee923a732 in GC_call_with_stack_base () from /gnu/store/9blidf28xz0a0glnv6a4xcw6nxadg427-libgc-7.6.0/lib/libgc.so.1
#24 0x00007f7ee95447dd in scm_i_with_guile (dynamic_state=<optimized out>, data=0x266ab80, func=0x7f7ee9544f70 <really_launch>) at threads.c:703
#25 launch_thread (d=0x266ab80) at threads.c:802
#26 0x00007f7ee9007454 in start_thread () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#27 0x00007f7ee79cf7bf in clone () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6

Thread 12 (Thread 0x7f7edf090700 (LWP 4117)):
#0  0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#1  0x00007f7ee9009b05 in pthread_mutex_lock () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#2  0x00007f7ee9545815 in scm_pthread_mutex_lock (mutex=<optimized out>) at threads.c:1600
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94d8dbb in scm_strerror (err=err <at> entry=17) at error.c:128
#5  0x00007f7ee94d8e73 in scm_syserror (subr=subr <at> entry=0x7f7ee956b07a <s_scm_mkdir> "mkdir") at error.c:169
#6  0x00007f7ee94e2189 in scm_mkdir (path=<optimized out>, mode=<optimized out>) at filesys.c:1274
#7  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211be10, registers=0x0, resume=-385808132) at vm-engine.c:784
#8  0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 20045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#9  0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 20045>) at eval.c:481
#10 0x00007f7ee94cbef8 in scm_call_with_unblocked_asyncs (proc=#<unmatched-tag 20045>) at async.c:400
#11 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211be10, registers=0x0, resume=-385808132) at vm-engine.c:784
#12 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 50045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#13 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
#14 0x00007f7ee9544fe6 in really_launch (d=0x266ab40) at threads.c:793
#15 0x00007f7ee94d4cba in c_body (d=0x7f7edf08fe60) at continuations.c:422
#16 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211be10, registers=0x0, resume=-385808132) at vm-engine.c:784
#17 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 1077>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#18 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 1077>) at eval.c:481
#19 0x00007f7ee95464e6 in catch (tag=tag <at> entry=#t, thunk=#<unmatched-tag 1077>, handler=#<unmatched-tag 11077>, pre_unwind_handler=#<unmatched-tag 11077>) at throw.c:137
#20 0x00007f7ee9546825 in scm_catch_with_pre_unwind_handler (key=key <at> entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#21 0x00007f7ee95469df in scm_c_catch (tag=tag <at> entry=#t, body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edf08fe60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edf08fe60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at throw.c:377
#22 0x00007f7ee94d52a0 in scm_i_with_continuation_barrier (body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edf08fe60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edf08fe60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at continuations.c:360
#23 0x00007f7ee94d5335 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#24 0x00007f7ee954510c in with_guile (base=0x7f7edf08fec0, data=0x7f7edf08fef0) at threads.c:660
#25 0x00007f7ee923a732 in GC_call_with_stack_base () from /gnu/store/9blidf28xz0a0glnv6a4xcw6nxadg427-libgc-7.6.0/lib/libgc.so.1
#26 0x00007f7ee95447dd in scm_i_with_guile (dynamic_state=<optimized out>, data=0x266ab40, func=0x7f7ee9544f70 <really_launch>) at threads.c:703
#27 launch_thread (d=0x266ab40) at threads.c:802
#28 0x00007f7ee9007454 in start_thread () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#29 0x00007f7ee79cf7bf in clone () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6

Thread 13 (Thread 0x7f7ede88e700 (LWP 4118)):
#0  0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#1  0x00007f7ee9009b05 in pthread_mutex_lock () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#2  0x00007f7ee9545815 in scm_pthread_mutex_lock (mutex=<optimized out>) at threads.c:1600
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94e2927 in scm_readdir (port=#<unmatched-tag 10a77>) at filesys.c:1749
#5  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bd80, registers=0x0, resume=-385808132) at vm-engine.c:784
#6  0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 20045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#7  0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 20045>) at eval.c:481
#8  0x00007f7ee94cbef8 in scm_call_with_unblocked_asyncs (proc=#<unmatched-tag 20045>) at async.c:400
#9  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bd80, registers=0x0, resume=-385808132) at vm-engine.c:784
#10 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 50045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#11 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
#12 0x00007f7ee9544fe6 in really_launch (d=0x266ab00) at threads.c:793
#13 0x00007f7ee94d4cba in c_body (d=0x7f7ede88de60) at continuations.c:422
#14 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bd80, registers=0x0, resume=-385808132) at vm-engine.c:784
#15 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 1077>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#16 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 1077>) at eval.c:481
#17 0x00007f7ee95464e6 in catch (tag=tag <at> entry=#t, thunk=#<unmatched-tag 1077>, handler=#<unmatched-tag 11077>, pre_unwind_handler=#<unmatched-tag 11077>) at throw.c:137
#18 0x00007f7ee9546825 in scm_catch_with_pre_unwind_handler (key=key <at> entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#19 0x00007f7ee95469df in scm_c_catch (tag=tag <at> entry=#t, body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7ede88de60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7ede88de60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at throw.c:377
#20 0x00007f7ee94d52a0 in scm_i_with_continuation_barrier (body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7ede88de60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7ede88de60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at continuations.c:360
#21 0x00007f7ee94d5335 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#22 0x00007f7ee954510c in with_guile (base=0x7f7ede88dec0, data=0x7f7ede88def0) at threads.c:660
#23 0x00007f7ee923a732 in GC_call_with_stack_base () from /gnu/store/9blidf28xz0a0glnv6a4xcw6nxadg427-libgc-7.6.0/lib/libgc.so.1
#24 0x00007f7ee95447dd in scm_i_with_guile (dynamic_state=<optimized out>, data=0x266ab00, func=0x7f7ee9544f70 <really_launch>) at threads.c:703
#25 launch_thread (d=0x266ab00) at threads.c:802
#26 0x00007f7ee9007454 in start_thread () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#27 0x00007f7ee79cf7bf in clone () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6

Thread 14 (Thread 0x7f7ede08c700 (LWP 4119)):
#0  0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#1  0x00007f7ee9009b05 in pthread_mutex_lock () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#2  0x00007f7ee9545815 in scm_pthread_mutex_lock (mutex=<optimized out>) at threads.c:1600
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94d8dbb in scm_strerror (err=err <at> entry=9) at error.c:128
#5  0x00007f7ee94d8e73 in scm_syserror (subr=subr <at> entry=0x7f7ee956afa0 <s_scm_readdir> "readdir") at error.c:169
#6  0x00007f7ee94e29b4 in scm_readdir (port=#<unmatched-tag 10a77>) at filesys.c:1754
#7  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bcf0, registers=0x0, resume=-385808132) at vm-engine.c:784
#8  0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 20045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#9  0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 20045>) at eval.c:481
#10 0x00007f7ee94cbef8 in scm_call_with_unblocked_asyncs (proc=#<unmatched-tag 20045>) at async.c:400
#11 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bcf0, registers=0x0, resume=-385808132) at vm-engine.c:784
#12 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 50045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#13 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
#14 0x00007f7ee9544fe6 in really_launch (d=0x266aac0) at threads.c:793
#15 0x00007f7ee94d4cba in c_body (d=0x7f7ede08be60) at continuations.c:422
#16 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bcf0, registers=0x0, resume=-385808132) at vm-engine.c:784
#17 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 1077>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#18 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 1077>) at eval.c:481
#19 0x00007f7ee95464e6 in catch (tag=tag <at> entry=#t, thunk=#<unmatched-tag 1077>, handler=#<unmatched-tag 11077>, pre_unwind_handler=#<unmatched-tag 11077>) at throw.c:137
#20 0x00007f7ee9546825 in scm_catch_with_pre_unwind_handler (key=key <at> entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#21 0x00007f7ee95469df in scm_c_catch (tag=tag <at> entry=#t, body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7ede08be60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7ede08be60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at throw.c:377
#22 0x00007f7ee94d52a0 in scm_i_with_continuation_barrier (body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7ede08be60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7ede08be60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at continuations.c:360
#23 0x00007f7ee94d5335 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#24 0x00007f7ee954510c in with_guile (base=0x7f7ede08bec0, data=0x7f7ede08bef0) at threads.c:660
#25 0x00007f7ee923a732 in GC_call_with_stack_base () from /gnu/store/9blidf28xz0a0glnv6a4xcw6nxadg427-libgc-7.6.0/lib/libgc.so.1
#26 0x00007f7ee95447dd in scm_i_with_guile (dynamic_state=<optimized out>, data=0x266aac0, func=0x7f7ee9544f70 <really_launch>) at threads.c:703
#27 launch_thread (d=0x266aac0) at threads.c:802
#28 0x00007f7ee9007454 in start_thread () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#29 0x00007f7ee79cf7bf in clone () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6

Thread 15 (Thread 0x7f7edd88a700 (LWP 4120)):
#0  0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#1  0x00007f7ee9009b05 in pthread_mutex_lock () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#2  0x00007f7ee9545815 in scm_pthread_mutex_lock (mutex=<optimized out>) at threads.c:1600
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94e2927 in scm_readdir (port=#<unmatched-tag 10a77>) at filesys.c:1749
#5  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bc60, registers=0x0, resume=-385808132) at vm-engine.c:784
#6  0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 20045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#7  0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 20045>) at eval.c:481
#8  0x00007f7ee94cbef8 in scm_call_with_unblocked_asyncs (proc=#<unmatched-tag 20045>) at async.c:400
#9  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bc60, registers=0x0, resume=-385808132) at vm-engine.c:784
#10 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 50045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#11 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
---Type <return> to continue, or q <return> to quit---
#12 0x00007f7ee9544fe6 in really_launch (d=0x266aa80) at threads.c:793
#13 0x00007f7ee94d4cba in c_body (d=0x7f7edd889e60) at continuations.c:422
#14 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bc60, registers=0x0, resume=-385808132) at vm-engine.c:784
#15 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 1077>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#16 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 1077>) at eval.c:481
#17 0x00007f7ee95464e6 in catch (tag=tag <at> entry=#t, thunk=#<unmatched-tag 1077>, handler=#<unmatched-tag 11077>, pre_unwind_handler=#<unmatched-tag 11077>) at throw.c:137
#18 0x00007f7ee9546825 in scm_catch_with_pre_unwind_handler (key=key <at> entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#19 0x00007f7ee95469df in scm_c_catch (tag=tag <at> entry=#t, body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edd889e60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edd889e60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at throw.c:377
#20 0x00007f7ee94d52a0 in scm_i_with_continuation_barrier (body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edd889e60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edd889e60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at continuations.c:360
#21 0x00007f7ee94d5335 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#22 0x00007f7ee954510c in with_guile (base=0x7f7edd889ec0, data=0x7f7edd889ef0) at threads.c:660
#23 0x00007f7ee923a732 in GC_call_with_stack_base () from /gnu/store/9blidf28xz0a0glnv6a4xcw6nxadg427-libgc-7.6.0/lib/libgc.so.1
#24 0x00007f7ee95447dd in scm_i_with_guile (dynamic_state=<optimized out>, data=0x266aa80, func=0x7f7ee9544f70 <really_launch>) at threads.c:703
#25 launch_thread (d=0x266aa80) at threads.c:802
#26 0x00007f7ee9007454 in start_thread () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#27 0x00007f7ee79cf7bf in clone () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6

Thread 16 (Thread 0x7f7edd088700 (LWP 4121)):
#0  0x00007f7ee90108fc in __lll_lock_wait () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#1  0x00007f7ee9009b05 in pthread_mutex_lock () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#2  0x00007f7ee9545815 in scm_pthread_mutex_lock (mutex=<optimized out>) at threads.c:1600
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94d8dbb in scm_strerror (err=err <at> entry=9) at error.c:128
#5  0x00007f7ee94d8e73 in scm_syserror (subr=subr <at> entry=0x7f7ee956bbd9 "fport_close") at error.c:169
#6  0x00007f7ee94e7a85 in fport_close (port=<optimized out>) at fports.c:677
#7  0x00007f7ee9514785 in release_port (port=#<port 4 2a15940>) at ports.c:158
#8  0x00007f7ee9517a0b in scm_close_port (port=#<port 4 2a15940>) at ports.c:887
#9  0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bbd0, registers=0x0, resume=-385808132) at vm-engine.c:784
#10 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 20045>, argv=<optimized out>, nargs=0) at vm.c:1257
#11 0x00007f7ee9514785 in release_port (port=#<port 4 2a158c0>) at ports.c:158
#12 0x00007f7ee9517a0b in scm_close_port (port=#<port 4 2a158c0>) at ports.c:887
#13 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bbd0, registers=0x0, resume=-385808132) at vm-engine.c:784
#14 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 10045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#15 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
#16 0x00007f7ee94d7ba0 in scm_dynstack_unwind_1 (dynstack=dynstack <at> entry=0x1fd9088) at dynstack.c:407
#17 0x00007f7ee94d7cd0 in scm_dynstack_unwind (dynstack=dynstack <at> entry=0x1fd9088, base=0x29e1720) at dynstack.c:437
#18 0x00007f7ee94d4b02 in scm_c_abort (vp=0x211bbd0, tag=<optimized out>, n=5, argv=0x7f7edd087200, current_registers=<optimized out>) at control.c:162
#19 0x00007f7ee9548df1 in vm_abort (vp=<optimized out>, tag=<optimized out>, nargs=<optimized out>, current_registers=<optimized out>) at vm.c:340
#20 0x00007f7ee9553cc6 in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bbd0, registers=0x0, resume=-385808132) at vm-engine.c:1004
#21 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 10045>, argv=<optimized out>, nargs=5) at vm.c:1257
#22 0x00007f7ee94dab6b in scm_apply_0 (proc=#<unmatched-tag 10045>, args=()) at eval.c:594
#23 0x00007f7ee94db76d in scm_apply_1 (proc=<optimized out>, arg1=arg1 <at> entry=system-error, args=<optimized out>) at eval.c:600
#24 0x00007f7ee954686c in scm_throw (key=key <at> entry=system-error, args=<optimized out>) at throw.c:266
#25 0x00007f7ee9546de5 in scm_ithrow (key=key <at> entry=system-error, args=<optimized out>, no_return=no_return <at> entry=1) at throw.c:611
#26 0x00007f7ee94d8d75 in scm_error_scm (key=key <at> entry=system-error, subr=<optimized out>, message=message <at> entry="~A", args=args <at> entry=("Invalid argument"), data=data <at> entry=(22)) at error.c:94
#27 0x00007f7ee94d8e2f in scm_error (key=system-error, subr=subr <at> entry=0x7f7ee956bbf1 "fport_read", message=message <at> entry=0x7f7ee95732db "~A", args=("Invalid argument"), rest=rest <at> entry=(22))
    at error.c:59
#28 0x00007f7ee94d8eaa in scm_syserror (subr=subr <at> entry=0x7f7ee956bbf1 "fport_read") at error.c:169
#29 0x00007f7ee94e7c75 in fport_read (port=<optimized out>, dst=<optimized out>, start=<optimized out>, count=58928) at fports.c:614
#30 0x00007f7ee9514d77 in scm_i_read_bytes (port=port <at> entry=#<port 2 26655c0>, dst=dst <at> entry="#<vu8vector>" = {...}, start=start <at> entry=0, count=count <at> entry=58928) at ports.c:1544
#31 0x00007f7ee95193fc in scm_c_read_bytes (port=port <at> entry=#<port 2 26655c0>, dst=dst <at> entry="#<vu8vector>" = {...}, start=start <at> entry=0, count=58928) at ports.c:1624
#32 0x00007f7ee951eb78 in scm_get_bytevector_n_x (port=#<port 2 26655c0>, bv="#<vu8vector>" = {...}, start=<optimized out>, count=58928) at r6rs-ports.c:461
#33 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bbd0, registers=0x0, resume=-385808132) at vm-engine.c:784
#34 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 20045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#35 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 20045>) at eval.c:481
#36 0x00007f7ee94cbef8 in scm_call_with_unblocked_asyncs (proc=#<unmatched-tag 20045>) at async.c:400
#37 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bbd0, registers=0x0, resume=-385808132) at vm-engine.c:784
#38 0x00007f7ee95572aa in scm_call_n (proc=#<unmatched-tag 50045>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#39 0x00007f7ee94da7d9 in scm_call_0 (proc=<optimized out>) at eval.c:481
#40 0x00007f7ee9544fe6 in really_launch (d=0x266aa40) at threads.c:793
#41 0x00007f7ee94d4cba in c_body (d=0x7f7edd087e60) at continuations.c:422
#42 0x00007f7ee9553c4d in vm_regular_engine (thread=0x7f7ee97bbfa0 <scm_i_misc_mutex>, vp=0x211bbd0, registers=0x0, resume=-385808132) at vm-engine.c:784
#43 0x00007f7ee95572aa in scm_call_n (proc=proc <at> entry=#<unmatched-tag 1077>, argv=argv <at> entry=0x0, nargs=nargs <at> entry=0) at vm.c:1257
#44 0x00007f7ee94da7d9 in scm_call_0 (proc=proc <at> entry=#<unmatched-tag 1077>) at eval.c:481
#45 0x00007f7ee95464e6 in catch (tag=tag <at> entry=#t, thunk=#<unmatched-tag 1077>, handler=#<unmatched-tag 11077>, pre_unwind_handler=#<unmatched-tag 11077>) at throw.c:137
#46 0x00007f7ee9546825 in scm_catch_with_pre_unwind_handler (key=key <at> entry=#t, thunk=<optimized out>, handler=<optimized out>, pre_unwind_handler=<optimized out>) at throw.c:254
#47 0x00007f7ee95469df in scm_c_catch (tag=tag <at> entry=#t, body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edd087e60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edd087e60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at throw.c:377
#48 0x00007f7ee94d52a0 in scm_i_with_continuation_barrier (body=body <at> entry=0x7f7ee94d4cb0 <c_body>, body_data=body_data <at> entry=0x7f7edd087e60, handler=handler <at> entry=0x7f7ee94d4f40 <c_handler>,
    handler_data=handler_data <at> entry=0x7f7edd087e60, pre_unwind_handler=pre_unwind_handler <at> entry=0x7f7ee94d4da0 <pre_unwind_handler>, pre_unwind_handler_data=0x2079ce0) at continuations.c:360
#49 0x00007f7ee94d5335 in scm_c_with_continuation_barrier (func=<optimized out>, data=<optimized out>) at continuations.c:456
#50 0x00007f7ee954510c in with_guile (base=0x7f7edd087ec0, data=0x7f7edd087ef0) at threads.c:660
#51 0x00007f7ee923a732 in GC_call_with_stack_base () from /gnu/store/9blidf28xz0a0glnv6a4xcw6nxadg427-libgc-7.6.0/lib/libgc.so.1
#52 0x00007f7ee95447dd in scm_i_with_guile (dynamic_state=<optimized out>, data=0x266aa40, func=0x7f7ee9544f70 <really_launch>) at threads.c:703
#53 launch_thread (d=0x266aa40) at threads.c:802
#54 0x00007f7ee9007454 in start_thread () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libpthread.so.0
#55 0x00007f7ee79cf7bf in clone () from /gnu/store/n6nvxlk2j8ysffjh3jphn1k5silnakh6-glibc-2.25/lib/libc.so.6
--8<---------------cut here---------------end--------------->8---

Thread 14 is in scm_readdir, so it holds the terrible
‘scm_i_misc_mutex’, but calling SCM_SYSERROR there causes it to try and
lock it again, leading to a deadlock:

--8<---------------cut here---------------start------------->8---
#3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
#4  0x00007f7ee94d8dbb in scm_strerror (err=err <at> entry=9) at error.c:128
#5  0x00007f7ee94d8e73 in scm_syserror (subr=subr <at> entry=0x7f7ee956afa0 <s_scm_readdir> "readdir") at error.c:169
#6  0x00007f7ee94e29b4 in scm_readdir (port=#<unmatched-tag 10a77>) at filesys.c:1754
--8<---------------cut here---------------end--------------->8---

Thread 16 got EINVAL from read(2), which sounds fishy:

--8<---------------cut here---------------start------------->8---
#29 0x00007f7ee94e7c75 in fport_read (port=<optimized out>, dst=<optimized out>, start=<optimized out>, count=58928) at fports.c:614
614     in fports.c
(gdb) p *fp
$1 = {fdes = 35, revealed = 0, options = 0}
(gdb) shell ls -l /proc/4105/fd/35
ls: cannot access '/proc/4105/fd/35': No such file or directory
--8<---------------cut here---------------end--------------->8---

To be continued…

Ludo’.

Message #11 received at 29335 <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: 29335 <at> debbugs.gnu.org
Subject: Re: bug#29335: 'guix publish' workers occasionally crash
Date: Fri, 17 Nov 2017 23:10:39 +0100

ludo <at> gnu.org (Ludovic Courtès) skribis:

> Thread 14 is in scm_readdir, so it holds the terrible
> ‘scm_i_misc_mutex’, but calling SCM_SYSERROR there causes it to try and
> lock it again, leading to a deadlock:
>
> #3  0x00007f7ee9545969 in scm_dynwind_pthread_mutex_lock (mutex=0x7f7ee97bbfa0 <scm_i_misc_mutex>) at threads.c:1613
> #4  0x00007f7ee94d8dbb in scm_strerror (err=err <at> entry=9) at error.c:128
> #5  0x00007f7ee94d8e73 in scm_syserror (subr=subr <at> entry=0x7f7ee956afa0 <s_scm_readdir> "readdir") at error.c:169
> #6  0x00007f7ee94e29b4 in scm_readdir (port=#<unmatched-tag 10a77>) at filesys.c:1754

This particular issue is now fixed in Guile:

  https://git.savannah.gnu.org/cgit/guile.git/commit/?h=stable-2.2&id=187655cedb42cc4b01088179649b02295cd35260

Ludo’.

Message #18 received at 29335-done <at> debbugs.gnu.org (full text, mbox):

From: ludo <at> gnu.org (Ludovic Courtès)
To: 29335-done <at> debbugs.gnu.org
Subject: Re: bug#29335: 'guix publish' workers occasionally crash
Date: Sun, 19 Nov 2017 23:48:47 +0100

ludo <at> gnu.org (Ludovic Courtès) skribis:

> On berlin I’ve noticed that the ‘guix publish’ workers would
> occasionally stop working: the main thread would keep replying to HTTP
> requests, but the worker threads would no longer do anything, and would
> leave behind them a bunch of .tmp files in /var/cache/guix/publish.
>
> I captured the output of ‘guix publish’ (guix-0.13.0-8.357ab93) and the
> only clue I have is this:
>
> GET /6kl9ydqmgklcqhxswg6v5isq5n1ih5gp.narinfo
> In guix/workers.scm:
>      74:9  2 (_)
>     78:32  1 (_ srfi-34 #<condition &nix-connection-error [file: "/v…>)
> In unknown file:
>            0 (make-stack #t)
> ERROR: In procedure make-stack:
> ERROR: Throw to key `srfi-34' with args `(#<condition &nix-connection-error [file: "/var/guix/daemon-socket/socket" errno: 9] 3ba2ea0>)'.
> GET /fgiih42mg2sr82mbmzf56grvrf021im6.narinfo

Good news, this is fixed in 85f4f7b79040d982c6a655c898b4cd00d868fa9c.

This could be reproduced by running ‘guix publish’ with 10 workers or
more, and then triggering nar compression en masse with ‘guix weather’.

EBADF was due to a race condition in zlib.scm when closing gzip output
ports:

          ;; 'gzclose' closes the underlying file descriptor.  'close-port'
          ;; calls close(2) and gets EBADF, which we swallow.
          (gzclose gzfile)
          (ignore-EBADF (close-port port)))

There was a window after the ‘gzclose’ call during which the file
descriptor for GZFILE and PORT above could be reused for something else,
and then ‘close-port’ would close it.

Thanks,
Ludo’.

Previous Next

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