+ shepherd --version shepherd (GNU Shepherd) 0.10.3 Copyright (C) 2024 the Shepherd authors License GPLv3+: GNU GPL version 3 or later This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. + herd --version herd (GNU Shepherd) 0.10.3 Copyright (C) 2024 the Shepherd authors License GPLv3+: GNU GPL version 3 or later This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. + socket=t-socket-11858 + conf=t-conf-11858 + log=t-log-11858 + pid=t-pid-11858 + c_file=t-count-file-descriptors-11858.c + exe=/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858 + fd_count=/home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + herd='herd -s t-socket-11858' + trap 'cat t-log-11858 || true; rm -f t-socket-11858 t-conf-11858 t-log-11858 /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 t-count-file-descriptors-11858.c /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858; test -f t-pid-11858 && kill `cat t-pid-11858` || true; rm -f t-pid-11858' EXIT + '[' -d /proc/self/fd ']' + cat + gcc -Wall t-count-file-descriptors-11858.c -o /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858 + /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858 0 -> /dev/pts/0 1 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log 2 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log 3 -> /proc/11890/fd 15 -> /gnu/store/l0y8jkmip7qpa7x33972mn0dsfy8ac01-libffi-3.4.4/lib/libffi.so.8.1.2 + cat ++ type -P sleep + rm -f t-pid-11858 /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + test -f t-pid-11858 + sleep 0.3 + shepherd -I -s t-socket-11858 -c t-conf-11858 -l t-log-11858 --pid=t-pid-11858 Starting service root... Service root started. Service root running with value #t. Service root has been started. Configuration successfully loaded from 't-conf-11858'. + test -f t-pid-11858 ++ cat t-pid-11858 + shepherd_pid=11894 + kill -0 11894 + herd -s t-socket-11858 start inetd-ctor Starting service inetd-ctor... Service inetd-ctor started. Service inetd-ctor running with value (#). Service inetd-ctor has been started. + ls -l /proc/11894/fd total 0 lr-x------ 1 alendvai users 64 Jan 19 00:06 0 -> /dev/null l-wx------ 1 alendvai users 64 Jan 19 00:06 1 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log lrwx------ 1 alendvai users 64 Jan 19 00:06 10 -> anon_inode:[signalfd] lr-x------ 1 alendvai users 64 Jan 19 00:06 11 -> pipe:[7007304] l-wx------ 1 alendvai users 64 Jan 19 00:06 12 -> pipe:[7007304] lr-x------ 1 alendvai users 64 Jan 19 00:06 13 -> pipe:[7005516] l-wx------ 1 alendvai users 64 Jan 19 00:06 14 -> pipe:[7005516] lr-x------ 1 alendvai users 64 Jan 19 00:06 15 -> /gnu/store/l0y8jkmip7qpa7x33972mn0dsfy8ac01-libffi-3.4.4/lib/libffi.so.8.1.2 lr-x------ 1 alendvai users 64 Jan 19 00:06 16 -> pipe:[7005517] l-wx------ 1 alendvai users 64 Jan 19 00:06 17 -> pipe:[7005517] lr-x------ 1 alendvai users 64 Jan 19 00:06 18 -> pipe:[7003504] l-wx------ 1 alendvai users 64 Jan 19 00:06 19 -> pipe:[7003504] l-wx------ 1 alendvai users 64 Jan 19 00:06 2 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log lrwx------ 1 alendvai users 64 Jan 19 00:06 20 -> socket:[7007305] lrwx------ 1 alendvai users 64 Jan 19 00:06 22 -> socket:[7007310] lr-x------ 1 alendvai users 64 Jan 19 00:06 3 -> pipe:[7007301] l-wx------ 1 alendvai users 64 Jan 19 00:06 4 -> pipe:[7007301] lr-x------ 1 alendvai users 64 Jan 19 00:06 5 -> /home/alendvai/workspace/guix/shepherd/shepherd l-wx------ 1 alendvai users 64 Jan 19 00:06 6 -> /home/alendvai/workspace/guix/shepherd/t-log-11858 lr-x------ 1 alendvai users 64 Jan 19 00:06 7 -> pipe:[7007303] l-wx------ 1 alendvai users 64 Jan 19 00:06 8 -> pipe:[7007303] lrwx------ 1 alendvai users 64 Jan 19 00:06 9 -> anon_inode:[eventpoll] + herd -s t-socket-11858 start system-ctor Starting service system-ctor... Service system-ctor has been started. + herd -s t-socket-11858 status system-ctor Status of system-ctor: It is stopped (one-shot). It is enabled. Provides (system-ctor). Requires (). Will not be respawned. + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 ++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + test 4 -eq 4 + herd -s t-socket-11858 start forkexec-ctor Starting service forkexec-ctor... Service forkexec-ctor started. Service forkexec-ctor running with value 11947. Service forkexec-ctor has been started. + herd -s t-socket-11858 status forkexec-ctor Status of forkexec-ctor: It is running since 00:06:05 (0 seconds ago). Running value is 11947. It is enabled. Provides (forkexec-ctor). Requires (). Will not be respawned. ++ herd -s t-socket-11858 status forkexec-ctor ++ grep 'Running value' ++ sed '-es/^.* \([0-9]\+\)\.$/\1/g' + pid=11947 + kill -0 11947 + ls -l /proc/11947/fd total 0 lr-x------ 1 alendvai users 64 Jan 19 00:06 0 -> /dev/null l-wx------ 1 alendvai users 64 Jan 19 00:06 1 -> pipe:[7007319] l-wx------ 1 alendvai users 64 Jan 19 00:06 2 -> pipe:[7007319] ++ cd /proc/11947/fd ++ echo 0 1 2 + test '0 1 2' = '0 1 2' + herd -s t-socket-11858 stop forkexec-ctor ++ seq 1 3 + for i in $(seq 1 3) + connect_to_server 5555 + rm -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + guile -c '(use-modules (ice-9 match)) (define address (make-socket-address AF_INET INADDR_LOOPBACK 5555)) (define sock (socket (sockaddr:fam address) SOCK_STREAM 0)) (connect sock address)' + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + sleep 0.3 + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 ++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + test 4 -eq 4 + herd -s t-socket-11858 enable systemd-ctor Enabled service systemd-ctor. + herd -s t-socket-11858 start systemd-ctor Service systemd-ctor has been started. + connect_to_server 5556 + rm -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + guile -c '(use-modules (ice-9 match)) (define address (make-socket-address AF_INET INADDR_LOOPBACK 5556)) (define sock (socket (sockaddr:fam address) SOCK_STREAM 0)) (connect sock address)' + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + sleep 0.3 + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 ++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + test 6 -eq 6 + herd -s t-socket-11858 stop systemd-ctor + herd -s t-socket-11858 restart forkexec-ctor Service forkexec-ctor is not running. Service forkexec-ctor has been started. + for i in $(seq 1 3) + connect_to_server 5555 + rm -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + guile -c '(use-modules (ice-9 match)) (define address (make-socket-address AF_INET INADDR_LOOPBACK 5555)) (define sock (socket (sockaddr:fam address) SOCK_STREAM 0)) (connect sock address)' + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + sleep 0.3 + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 ++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + test 4 -eq 4 + herd -s t-socket-11858 enable systemd-ctor Enabled service systemd-ctor. + herd -s t-socket-11858 start systemd-ctor Service systemd-ctor has been started. + connect_to_server 5556 + rm -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + guile -c '(use-modules (ice-9 match)) (define address (make-socket-address AF_INET INADDR_LOOPBACK 5556)) (define sock (socket (sockaddr:fam address) SOCK_STREAM 0)) (connect sock address)' + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + sleep 0.3 + test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 ++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 + test 4 -eq 6 + cat t-log-11858 2024-01-19 00:06:05 [debug] Shepherd is starting up, logging has been initialized 2024-01-19 00:06:05 [debug] Signal handlers installed, about to call run-fibers 2024-01-19 00:06:05 [debug] Registering and starting root-service 2024-01-19 00:06:05 [debug] register-services for (#) 2024-01-19 00:06:05 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:05 [debug] service-registry is registering service # 2024-01-19 00:06:05 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (start #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:05 Starting service root... 2024-01-19 00:06:05 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:05 Service root started. 2024-01-19 00:06:05 Service root running with value #t. 2024-01-19 00:06:05 Service root has been started. 2024-01-19 00:06:05 [debug] run-daemon speaking, config-file is "t-conf-11858", socket-file is "t-socket-11858", pid-file is "t-pid-11858" 2024-01-19 00:06:05 [debug] Will receive commands on socket # 2024-01-19 00:06:05 [debug] load-in-user-module for file 't-conf-11858' 2024-01-19 00:06:05 [debug] register-services for (# # # #) 2024-01-19 00:06:05 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:05 [debug] service-registry is registering service # 2024-01-19 00:06:05 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:05 [debug] service-registry is registering service # 2024-01-19 00:06:05 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:05 [debug] service-registry is registering service # 2024-01-19 00:06:05 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:05 [debug] service-registry is registering service # 2024-01-19 00:06:05 Configuration successfully loaded from 't-conf-11858'. 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action start, service inetd-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: start service: inetd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (status #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:05 Starting service inetd-ctor... 2024-01-19 00:06:05 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:05 Service inetd-ctor started. 2024-01-19 00:06:05 Service inetd-ctor running with value (#). 2024-01-19 00:06:05 Service inetd-ctor has been started. 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: start service: inetd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: # error: #f messages: ("Starting service inetd-ctor..." "Service inetd-ctor started." "Service inetd-ctor running with value (#)." "Service inetd-ctor has been started.")> 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action start, service system-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: start service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (status #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:05 Starting service system-ctor... 2024-01-19 00:06:05 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:05 [debug] fork+exec-command for (/bin/sh -c /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f 2024-01-19 00:06:05 [debug] exec-command for (/bin/sh -c /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:05 [sh] 0 -> /dev/null 2024-01-19 00:06:05 [sh] 1 -> pipe:[7007314] 2024-01-19 00:06:05 [sh] 2 -> pipe:[7007314] 2024-01-19 00:06:05 [sh] 3 -> /proc/11927/fd 2024-01-19 00:06:05 Service system-ctor has been started. 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: start service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: # error: #f messages: ("Starting service system-ctor..." "Service system-ctor has been started.")> 2024-01-19 00:06:05 Service system-ctor started. 2024-01-19 00:06:05 Service system-ctor running with value #t. 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action status, service system-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: status service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] perform-service-action for action 'status', service '#', with args () 2024-01-19 00:06:05 [debug] Calling the action's proc #, action status, running-value #f, args () 2024-01-19 00:06:05 [debug] Received (#) from the action's proc #, action status, args () 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: status service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#) error: #f messages: ()> 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action start, service forkexec-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: start service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (status #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:05 Starting service forkexec-ctor... 2024-01-19 00:06:05 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:05 [debug] fork+exec-command for (/gnu/store/zqk7jjj97dzhf6h9inf3q3q9n2pv43xj-profile/bin/sleep 100), user #f, group #f, supplementary-groups (), log-file #f 2024-01-19 00:06:05 Service forkexec-ctor started. 2024-01-19 00:06:05 Service forkexec-ctor running with value 11947. 2024-01-19 00:06:05 [debug] exec-command for (/gnu/store/zqk7jjj97dzhf6h9inf3q3q9n2pv43xj-profile/bin/sleep 100), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:05 [debug] monitor-service-process for service #, pid 11947 2024-01-19 00:06:05 Service forkexec-ctor has been started. 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: start service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: # error: #f messages: ("Starting service forkexec-ctor..." "Service forkexec-ctor started." "Service forkexec-ctor running with value 11947." "Service forkexec-ctor has been started.")> 2024-01-19 00:06:05 [debug] monitor-service-process fiber speaking; service #, pid 11947; reading reply... 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action status, service forkexec-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] perform-service-action for action 'status', service '#', with args () 2024-01-19 00:06:05 [debug] Calling the action's proc #, action status, running-value 11947, args () 2024-01-19 00:06:05 [debug] Received (#) from the action's proc #, action status, args () 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#) error: #f messages: ()> 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action status, service forkexec-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] perform-service-action for action 'status', service '#', with args () 2024-01-19 00:06:05 [debug] Calling the action's proc #, action status, running-value 11947, args () 2024-01-19 00:06:05 [debug] Received (#) from the action's proc #, action status, args () 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#) error: #f messages: ()> 2024-01-19 00:06:05 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:05 [debug] read-command: version (0), action stop, service forkexec-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:05 [debug] process-command; command '#< version: (0) action: stop service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:05 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (status #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:05 Stopping service forkexec-ctor... 2024-01-19 00:06:05 [debug] monitor-service-process fiber got reply (status) 15 2024-01-19 00:06:05 Service forkexec-ctor stopped. 2024-01-19 00:06:05 Service forkexec-ctor is now stopped. 2024-01-19 00:06:05 [debug] Sending reply #< command: #< version: (0) action: stop service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (forkexec-ctor) error: #f messages: ()> 2024-01-19 00:06:05 Accepted connection on 127.0.0.1:5555 from 127.0.0.1:48536. 2024-01-19 00:06:05 [debug] register-services for (#) 2024-01-19 00:06:05 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:05 [debug] service-registry is registering service # 2024-01-19 00:06:05 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (start #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:05 Starting service t-count-file-descriptors-11858-1... 2024-01-19 00:06:05 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:05 Service t-count-file-descriptors-11858-1 started. 2024-01-19 00:06:05 [debug] exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:05 Service t-count-file-descriptors-11858-1 running with value 11992. 2024-01-19 00:06:05 [debug] monitor-service-process for service #, pid 11992 2024-01-19 00:06:05 Service t-count-file-descriptors-11858-1 has been started. 2024-01-19 00:06:05 [debug] monitor-service-process fiber speaking; service #, pid 11992; reading reply... 2024-01-19 00:06:05 [debug] monitor-service-process fiber got reply (status) 0 2024-01-19 00:06:05 0 connections still in use after t-count-file-descriptors-11858-1 termination. 2024-01-19 00:06:05 [debug] disable-service for # 2024-01-19 00:06:05 Service t-count-file-descriptors-11858-1 has been disabled. 2024-01-19 00:06:05 Transient service t-count-file-descriptors-11858-1 terminated, now unregistered. 2024-01-19 00:06:05 [debug] service-registry; unregister services (#) 2024-01-19 00:06:05 [debug] service-registry is unregistering services (#) 2024-01-19 00:06:05 [debug] service-controller is terminating, service # 2024-01-19 00:06:05 [debug] Service controller fiber is exiting; service #, channel #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #> 2024-01-19 00:06:06 Accepted connection on 127.0.0.1:5555 from 127.0.0.1:48538. 2024-01-19 00:06:06 [debug] register-services for (#) 2024-01-19 00:06:06 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:06 [debug] service-registry is registering service # 2024-01-19 00:06:06 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (start #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:06 Starting service t-count-file-descriptors-11858-2... 2024-01-19 00:06:06 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-2 started. 2024-01-19 00:06:06 [debug] exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-2 running with value 12006. 2024-01-19 00:06:06 [debug] monitor-service-process for service #, pid 12006 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-2 has been started. 2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #, pid 12006; reading reply... 2024-01-19 00:06:06 [debug] monitor-service-process fiber got reply (status) 0 2024-01-19 00:06:06 0 connections still in use after t-count-file-descriptors-11858-2 termination. 2024-01-19 00:06:06 [debug] disable-service for # 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-2 has been disabled. 2024-01-19 00:06:06 Transient service t-count-file-descriptors-11858-2 terminated, now unregistered. 2024-01-19 00:06:06 [debug] service-registry; unregister services (#) 2024-01-19 00:06:06 [debug] service-registry is unregistering services (#) 2024-01-19 00:06:06 [debug] service-controller is terminating, service # 2024-01-19 00:06:06 [debug] Service controller fiber is exiting; service #, channel #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #> 2024-01-19 00:06:06 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:06 [debug] read-command: version (0), action enable, service systemd-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:06 [debug] process-command; command '#< version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:06 [debug] perform-service-action for action 'enable', service '#', with args () 2024-01-19 00:06:06 [debug] Calling the action's proc #, action enable, running-value #f, args () 2024-01-19 00:06:06 Enabled service systemd-ctor. 2024-01-19 00:06:06 [debug] Received (#) from the action's proc #, action enable, args () 2024-01-19 00:06:06 [debug] Sending reply #< command: #< version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#) error: #f messages: ("Enabled service systemd-ctor.")> 2024-01-19 00:06:06 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:06 [debug] read-command: version (0), action start, service systemd-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:06 [debug] process-command; command '#< version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:06 Starting service systemd-ctor... 2024-01-19 00:06:06 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:06 Service systemd-ctor has been started. 2024-01-19 00:06:06 [debug] Sending reply #< command: #< version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: # error: #f messages: ("Service systemd-ctor has been started.")> 2024-01-19 00:06:06 Service systemd-ctor started. 2024-01-19 00:06:06 Service systemd-ctor running with value (("unknown" . #)). 2024-01-19 00:06:06 Spawning systemd-style service /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858. 2024-01-19 00:06:06 [debug] fork+exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f 2024-01-19 00:06:06 [debug] exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:06 Running value of service systemd-ctor changed to 12034. 2024-01-19 00:06:06 [debug] monitor-service-process for service #, pid 12034 2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #, pid 12034; reading reply... 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 0 -> /dev/null 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 1 -> pipe:[7007344] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 2 -> pipe:[7007344] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 3 -> socket:[7007343] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 4 -> socket:[7003523] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 5 -> /proc/12034/fd 2024-01-19 00:06:06 [debug] monitor-service-process fiber got reply (status) 0 2024-01-19 00:06:06 [debug] disable-service for # 2024-01-19 00:06:06 Service systemd-ctor has been disabled. 2024-01-19 00:06:06 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:06 [debug] read-command: version (0), action stop, service systemd-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:06 [debug] process-command; command '#< version: (0) action: stop service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:06 [debug] Sending reply #< command: #< version: (0) action: stop service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: () error: #f messages: ()> 2024-01-19 00:06:06 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:06 [debug] read-command: version (0), action restart, service forkexec-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:06 [debug] process-command; command '#< version: (0) action: restart service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:06 [debug] perform-service-action for action 'restart', service '#', with args () 2024-01-19 00:06:06 [debug] Calling the action's proc #, action restart, running-value #f, args () 2024-01-19 00:06:06 Service forkexec-ctor is not running. 2024-01-19 00:06:06 Starting service forkexec-ctor... 2024-01-19 00:06:06 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:06 [debug] fork+exec-command for (/gnu/store/zqk7jjj97dzhf6h9inf3q3q9n2pv43xj-profile/bin/sleep 100), user #f, group #f, supplementary-groups (), log-file #f 2024-01-19 00:06:06 Service forkexec-ctor has been started. 2024-01-19 00:06:06 [debug] exec-command for (/gnu/store/zqk7jjj97dzhf6h9inf3q3q9n2pv43xj-profile/bin/sleep 100), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:06 [debug] Received (#t) from the action's proc #, action restart, args () 2024-01-19 00:06:06 [debug] Sending reply #< command: #< version: (0) action: restart service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#t) error: #f messages: ("Service forkexec-ctor is not running." "Service forkexec-ctor has been started.")> 2024-01-19 00:06:06 Service forkexec-ctor started. 2024-01-19 00:06:06 Service forkexec-ctor running with value 12054. 2024-01-19 00:06:06 [debug] monitor-service-process for service #, pid 12054 2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #, pid 12054; reading reply... 2024-01-19 00:06:06 Accepted connection on 127.0.0.1:5555 from 127.0.0.1:48550. 2024-01-19 00:06:06 [debug] register-services for (#) 2024-01-19 00:06:06 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:06 [debug] service-registry is registering service # 2024-01-19 00:06:06 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (start #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:06 Starting service t-count-file-descriptors-11858-3... 2024-01-19 00:06:06 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-3 started. 2024-01-19 00:06:06 [debug] exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-3 running with value 12066. 2024-01-19 00:06:06 [debug] monitor-service-process for service #, pid 12066 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-3 has been started. 2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #, pid 12066; reading reply... 2024-01-19 00:06:06 [debug] monitor-service-process fiber got reply (status) 0 2024-01-19 00:06:06 0 connections still in use after t-count-file-descriptors-11858-3 termination. 2024-01-19 00:06:06 [debug] disable-service for # 2024-01-19 00:06:06 Service t-count-file-descriptors-11858-3 has been disabled. 2024-01-19 00:06:06 Transient service t-count-file-descriptors-11858-3 terminated, now unregistered. 2024-01-19 00:06:06 [debug] service-registry; unregister services (#) 2024-01-19 00:06:06 [debug] service-registry is unregistering services (#) 2024-01-19 00:06:06 [debug] service-controller is terminating, service # 2024-01-19 00:06:06 [debug] Service controller fiber is exiting; service #, channel #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #> 2024-01-19 00:06:06 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:06 [debug] read-command: version (0), action enable, service systemd-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:06 [debug] process-command; command '#< version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:06 [debug] perform-service-action for action 'enable', service '#', with args () 2024-01-19 00:06:06 [debug] Calling the action's proc #, action enable, running-value #f, args () 2024-01-19 00:06:06 Enabled service systemd-ctor. 2024-01-19 00:06:06 [debug] Received (#) from the action's proc #, action enable, args () 2024-01-19 00:06:06 [debug] Sending reply #< command: #< version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#) error: #f messages: ("Enabled service systemd-ctor.")> 2024-01-19 00:06:06 [debug] Received next-command from client #(1 #f) 2024-01-19 00:06:06 [debug] read-command: version (0), action start, service systemd-ctor, args (), directory /home/alendvai/workspace/guix/shepherd 2024-01-19 00:06:06 [debug] process-command; command '#< version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port # 2024-01-19 00:06:06 Starting service systemd-ctor... 2024-01-19 00:06:06 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:06 Service systemd-ctor has been started. 2024-01-19 00:06:06 [debug] Sending reply #< command: #< version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: # error: #f messages: ("Service systemd-ctor has been started.")> 2024-01-19 00:06:06 Service systemd-ctor started. 2024-01-19 00:06:06 Service systemd-ctor running with value (("unknown" . #)). 2024-01-19 00:06:06 Spawning systemd-style service /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858. 2024-01-19 00:06:06 [debug] fork+exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f 2024-01-19 00:06:06 Running value of service systemd-ctor changed to 12099. 2024-01-19 00:06:06 [debug] exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:06 [debug] monitor-service-process for service #, pid 12099 2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #, pid 12099; reading reply... 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 0 -> /dev/null 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 1 -> pipe:[7005567] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 2 -> pipe:[7005567] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 3 -> socket:[7005566] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 4 -> socket:[7007355] 2024-01-19 00:06:06 [t-count-file-descriptors-11858] 5 -> /proc/12099/fd 2024-01-19 00:06:06 [debug] monitor-service-process fiber got reply (status) 0 2024-01-19 00:06:06 [debug] disable-service for # 2024-01-19 00:06:06 Service systemd-ctor has been disabled. 2024-01-19 00:06:07 Accepted connection on 127.0.0.1:5555 from 127.0.0.1:48554. 2024-01-19 00:06:07 [debug] register-services for (#) 2024-01-19 00:06:07 [debug] service-registry; register service #, current-module # 2024-01-19 00:06:07 [debug] service-registry is registering service # 2024-01-19 00:06:07 [debug] Service controller spawned; service #, channel #< getq: # getq-gc-counter: # putq: # # (start #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #>)))> putq-gc-counter: #> 2024-01-19 00:06:07 Starting service t-count-file-descriptors-11858-4... 2024-01-19 00:06:07 [debug] About to apply the start lambda of service # to args () 2024-01-19 00:06:07 Service t-count-file-descriptors-11858-4 started. 2024-01-19 00:06:07 [debug] exec-command for (/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858), user #f, group #f, supplementary-groups (), log-file #f, log-port # 2024-01-19 00:06:07 Service t-count-file-descriptors-11858-4 running with value 12102. 2024-01-19 00:06:07 [debug] monitor-service-process for service #, pid 12102 2024-01-19 00:06:07 Service t-count-file-descriptors-11858-4 has been started. 2024-01-19 00:06:07 [debug] monitor-service-process fiber speaking; service #, pid 12102; reading reply... 2024-01-19 00:06:07 [debug] monitor-service-process fiber got reply (status) 0 2024-01-19 00:06:07 0 connections still in use after t-count-file-descriptors-11858-4 termination. 2024-01-19 00:06:07 [debug] disable-service for # 2024-01-19 00:06:07 Service t-count-file-descriptors-11858-4 has been disabled. 2024-01-19 00:06:07 Transient service t-count-file-descriptors-11858-4 terminated, now unregistered. 2024-01-19 00:06:07 [debug] service-registry; unregister services (#) 2024-01-19 00:06:07 [debug] service-registry is unregistering services (#) 2024-01-19 00:06:07 [debug] service-controller is terminating, service # 2024-01-19 00:06:07 [debug] Service controller fiber is exiting; service #, channel #< getq: # getq-gc-counter: # putq: # putq-gc-counter: #> + rm -f t-socket-11858 t-conf-11858 t-log-11858 /home/alendvai/workspace/guix/shepherd/t-fd-count-11858 t-count-file-descriptors-11858.c /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-11858 + test -f t-pid-11858 ++ cat t-pid-11858 + kill 11894 + rm -f t-pid-11858 Stopping service root... Exiting shepherd... FAIL tests/close-on-exec.sh (exit status: 1) Exiting.