bug#67565: shepherd: FAIL: tests/close-on-exec.sh

bug#67565: shepherd: FAIL: tests/close-on-exec.sh

[Attila Lendvai]

[-- Attachment #1: Type: text/plain, Size: 363 bytes --]

make check TESTS="tests/close-on-exec.sh"

fails for me in shepherd.

it's the same with master, with v0.10.2, and with v0.10.1.

i didn't check other revisions.

the log file is attached.

HTH,

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
You cannot enslave a mind that knows itself, that values itself, that understands itself.

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: close-on-exec.log --]
[-- Type: text/x-log; name=close-on-exec.log, Size: 10255 bytes --]

+ shepherd --version
shepherd (GNU Shepherd) 0.10.2
Copyright (C) 2023 the Shepherd authors
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
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.2
Copyright (C) 2023 the Shepherd authors
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
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-12913
+ conf=t-conf-12913
+ log=t-log-12913
+ pid=t-pid-12913
+ c_file=t-count-file-descriptors-12913.c
+ exe=/home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-12913
+ fd_count=/home/alendvai/workspace/guix/shepherd/t-fd-count-12913
+ herd='herd -s t-socket-12913'
+ trap 'cat t-log-12913 || true; rm -f t-socket-12913 t-conf-12913 t-log-12913 /home/alendvai/workspace/guix/shepherd/t-fd-count-12913 t-count-file-descriptors-12913.c /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-12913;
      test -f t-pid-12913 && kill `cat t-pid-12913` || true; rm -f t-pid-12913' EXIT
+ '[' -d /proc/self/fd ']'
+ cat
+ gcc -Wall t-count-file-descriptors-12913.c -o /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-12913
+ /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-12913
0 -> /dev/pts/1
1 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log
2 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log
3 -> /proc/12945/fd
+ cat
++ type -P sleep
+ rm -f t-pid-12913 /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
+ test -f t-pid-12913
+ sleep 0.3
+ shepherd -I -s t-socket-12913 -c t-conf-12913 -l t-log-12913 --pid=t-pid-12913
Starting service root...
Service root started.
Service root running with value #t.
Service root has been started.
Configuration successfully loaded from 't-conf-12913'.
+ test -f t-pid-12913
++ cat t-pid-12913
+ shepherd_pid=12949
+ kill -0 12949
+ herd -s t-socket-12913 start inetd-ctor
Starting service inetd-ctor...
Service inetd-ctor started.
Service inetd-ctor running with value (#<input-output: socket 17>).
Service inetd-ctor has been started.
+ ls -l /proc/12949/fd
total 0
lr-x------ 1 alendvai users 64 Nov 17 21:46 0 -> /dev/null
l-wx------ 1 alendvai users 64 Nov 17 21:46 1 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log
lrwx------ 1 alendvai users 64 Nov 17 21:46 10 -> anon_inode:[signalfd]
l-wx------ 1 alendvai users 64 Nov 17 21:46 11 -> pipe:[16921055]
lr-x------ 1 alendvai users 64 Nov 17 21:46 12 -> pipe:[16920173]
l-wx------ 1 alendvai users 64 Nov 17 21:46 13 -> pipe:[16920173]
lrwx------ 1 alendvai users 64 Nov 17 21:46 14 -> anon_inode:[eventpoll]
lrwx------ 1 alendvai users 64 Nov 17 21:46 15 -> socket:[16920174]
lrwx------ 1 alendvai users 64 Nov 17 21:46 17 -> socket:[16920178]
l-wx------ 1 alendvai users 64 Nov 17 21:46 2 -> /home/alendvai/workspace/guix/shepherd/tests/close-on-exec.log
lr-x------ 1 alendvai users 64 Nov 17 21:46 3 -> pipe:[16918174]
l-wx------ 1 alendvai users 64 Nov 17 21:46 4 -> pipe:[16918174]
lr-x------ 1 alendvai users 64 Nov 17 21:46 5 -> /home/alendvai/workspace/guix/shepherd/shepherd
l-wx------ 1 alendvai users 64 Nov 17 21:46 6 -> /home/alendvai/workspace/guix/shepherd/t-log-12913
lr-x------ 1 alendvai users 64 Nov 17 21:46 7 -> pipe:[16920172]
l-wx------ 1 alendvai users 64 Nov 17 21:46 8 -> pipe:[16920172]
lr-x------ 1 alendvai users 64 Nov 17 21:46 9 -> pipe:[16921055]
+ herd -s t-socket-12913 start system-ctor
Starting service system-ctor...
Service system-ctor has been started.
+ herd -s t-socket-12913 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-12913
++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
+ test 4 -eq 4
+ herd -s t-socket-12913 start forkexec-ctor
Starting service forkexec-ctor...
Service forkexec-ctor started.
Service forkexec-ctor running with value 13000.
Service forkexec-ctor has been started.
+ herd -s t-socket-12913 status forkexec-ctor
Status of forkexec-ctor:
  It is running since 21:46:15 (0 seconds ago).
  Running value is 13000.
  It is enabled.
  Provides (forkexec-ctor).
  Requires ().
  Will not be respawned.
++ herd -s t-socket-12913 status forkexec-ctor
++ grep 'Running value'
++ sed '-es/^.* \([0-9]\+\)\.$/\1/g'
+ pid=13000
+ kill -0 13000
+ ls -l /proc/13000/fd
total 0
lr-x------ 1 alendvai users 64 Nov 17 21:46 0 -> /dev/null
l-wx------ 1 alendvai users 64 Nov 17 21:46 1 -> pipe:[16918179]
l-wx------ 1 alendvai users 64 Nov 17 21:46 2 -> pipe:[16918179]
++ cd /proc/13000/fd
++ echo 0 1 2
+ test '0 1 2' = '0 1 2'
+ herd -s t-socket-12913 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-12913
+ guile -c '(use-modules (ice-9 match))
      (define IN6ADDR_LOOPBACK 1)
      (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-12913
+ sleep 0.3
+ test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
+ test 4 -eq 4
+ herd -s t-socket-12913 enable systemd-ctor
Enabled service systemd-ctor.
+ herd -s t-socket-12913 start systemd-ctor
Service systemd-ctor has been started.
+ connect_to_server 5556
+ rm -f /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
+ guile -c '(use-modules (ice-9 match))
      (define IN6ADDR_LOOPBACK 1)
      (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-12913
+ sleep 0.3
+ test -f /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
++ cat /home/alendvai/workspace/guix/shepherd/t-fd-count-12913
+ test 4 -eq 6
+ cat t-log-12913
2023-11-17 21:46:15 Starting service root...
2023-11-17 21:46:15 Service root started.
2023-11-17 21:46:15 Service root running with value #t.
2023-11-17 21:46:15 Service root has been started.
2023-11-17 21:46:15 Configuration successfully loaded from 't-conf-12913'.
2023-11-17 21:46:15 Starting service inetd-ctor...
2023-11-17 21:46:15 Service inetd-ctor started.
2023-11-17 21:46:15 Service inetd-ctor running with value (#<input-output: socket 17>).
2023-11-17 21:46:15 Service inetd-ctor has been started.
2023-11-17 21:46:15 Starting service system-ctor...
2023-11-17 21:46:15 [sh] 0 -> /dev/null
2023-11-17 21:46:15 [sh] 1 -> pipe:[16920182]
2023-11-17 21:46:15 [sh] 2 -> pipe:[16920182]
2023-11-17 21:46:15 [sh] 3 -> /proc/12980/fd
2023-11-17 21:46:15 Service system-ctor has been started.
2023-11-17 21:46:15 Service system-ctor started.
2023-11-17 21:46:15 Service system-ctor running with value #t.
2023-11-17 21:46:15 Starting service forkexec-ctor...
2023-11-17 21:46:15 Service forkexec-ctor started.
2023-11-17 21:46:15 Service forkexec-ctor running with value 13000.
2023-11-17 21:46:15 Service forkexec-ctor has been started.
2023-11-17 21:46:15 Stopping service forkexec-ctor...
2023-11-17 21:46:15 Service forkexec-ctor stopped.
2023-11-17 21:46:15 Service forkexec-ctor is now stopped.
2023-11-17 21:46:15 Accepted connection on 127.0.0.1:5555 from 127.0.0.1:43514.
2023-11-17 21:46:15 Starting service t-count-file-descriptors-12913-1...
2023-11-17 21:46:15 Service t-count-file-descriptors-12913-1 started.
2023-11-17 21:46:15 Service t-count-file-descriptors-12913-1 running with value 13045.
2023-11-17 21:46:15 Service t-count-file-descriptors-12913-1 has been started.
2023-11-17 21:46:15 0 connections still in use after t-count-file-descriptors-12913-1 termination.
2023-11-17 21:46:15 Service t-count-file-descriptors-12913-1 has been disabled.
2023-11-17 21:46:15 Transient service t-count-file-descriptors-12913-1 terminated, now unregistered.
2023-11-17 21:46:16 Enabled service systemd-ctor.
2023-11-17 21:46:16 Starting service systemd-ctor...
2023-11-17 21:46:16 Service systemd-ctor has been started.
2023-11-17 21:46:16 Service systemd-ctor started.
2023-11-17 21:46:16 Service systemd-ctor running with value (("unknown" . #<input-output: socket 18>)).
2023-11-17 21:46:16 Spawning systemd-style service /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-12913.
2023-11-17 21:46:16 Running value of service systemd-ctor changed to 13077.
2023-11-17 21:46:16 [t-count-file-descriptors-12913] 0 -> /dev/null
2023-11-17 21:46:16 [t-count-file-descriptors-12913] 1 -> pipe:[16916369]
2023-11-17 21:46:16 [t-count-file-descriptors-12913] 2 -> pipe:[16916369]
2023-11-17 21:46:16 [t-count-file-descriptors-12913] 3 -> socket:[16920216]
2023-11-17 21:46:16 [t-count-file-descriptors-12913] 4 -> socket:[16918195]
2023-11-17 21:46:16 [t-count-file-descriptors-12913] 5 -> /proc/13077/fd
2023-11-17 21:46:16 Service systemd-ctor has been disabled.
2023-11-17 21:46:16 Accepted connection on 127.0.0.1:5555 from 127.0.0.1:43530.
2023-11-17 21:46:16 Starting service t-count-file-descriptors-12913-2...
2023-11-17 21:46:16 Service t-count-file-descriptors-12913-2 started.
2023-11-17 21:46:16 Service t-count-file-descriptors-12913-2 running with value 13081.
2023-11-17 21:46:16 Service t-count-file-descriptors-12913-2 has been started.
2023-11-17 21:46:16 0 connections still in use after t-count-file-descriptors-12913-2 termination.
2023-11-17 21:46:16 Service t-count-file-descriptors-12913-2 has been disabled.
2023-11-17 21:46:16 Transient service t-count-file-descriptors-12913-2 terminated, now unregistered.
+ rm -f t-socket-12913 t-conf-12913 t-log-12913 /home/alendvai/workspace/guix/shepherd/t-fd-count-12913 t-count-file-descriptors-12913.c /home/alendvai/workspace/guix/shepherd/t-count-file-descriptors-12913
+ test -f t-pid-12913
++ cat t-pid-12913
+ kill 12949
+ rm -f t-pid-12913
Stopping service root...
Exiting shepherd...
Exiting.
FAIL tests/close-on-exec.sh (exit status: 1)

bug#67565: (No Subject)

[Attila Lendvai]

hrm, i tried to reproduce it just now on the same machine, and i couldn't.

not sure it's relevant, but my router is overloaded, and sometimes DNS resolution, and other things break. looking at the test it shouldn't matter as it deals with the loopback device.

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
“If one rejects laissez faire on account of man's fallibility and moral weakness, one must for the same reason also reject every kind of government action.”
	— Ludwig von Mises (1881–1973), 'Planning for Freedom' (1952)

bug#67565: (No Subject)

[Attila Lendvai]

[-- Attachment #1: Type: text/plain, Size: 595 bytes --]

> hrm, i tried to reproduce it just now on the same machine, and i couldn't.

it has happened again, i'm attaching another log file.

this log file is with my shepherd branch, i.e. it contains much more log.

the error:

+ test 4 -eq 6

HTH,

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
“I don't trust a man who talks about ethics when he is picking my pocket. But if he is acting in his own self-interest and says so, I have usually been able to work out some way to do business with him.”
	— Robert Heinlein (1907–1988), 'Time Enough For Love' (1973)

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: close-on-exec.log --]
[-- Type: text/x-log; name=close-on-exec.log, Size: 45806 bytes --]

+ shepherd --version
shepherd (GNU Shepherd) 0.10.3
Copyright (C) 2024 the Shepherd authors
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
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 <http://gnu.org/licenses/gpl.html>
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 (#<input-output: socket 22>).
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 (#<service (root shepherd)>)
2024-01-19 00:06:05 [debug] service-registry; register service #<service (root shepherd)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:05 [debug] service-registry is registering service #<service (root shepherd)>
2024-01-19 00:06:05 [debug] Service controller spawned; service #<service (root shepherd)>, channel #<<channel> getq: #<atomic-box 7fcecaec0a20 value: (())> getq-gc-counter: #<atomic-box 7fcecaec0a10 value: 42> putq: #<atomic-box 7fcecaec09f0 value: (() #(#<atomic-box 7fcecaec09b0 value: W> #<procedure resume (thunk)> (start #<<channel> getq: #<atomic-box 7fcecaec0ae0 value: (())> getq-gc-counter: #<atomic-box 7fcecaec0ad0 value: 42> putq: #<atomic-box 7fcecaec0ab0 value: (())> putq-gc-counter: #<atomic-box 7fcecaec0aa0 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecaec09e0 value: 41>>
2024-01-19 00:06:05 Starting service root...
2024-01-19 00:06:05 [debug] About to apply the start lambda of service #<service (root shepherd)> 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 #<input-output: socket 20>
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 (#<service (system-ctor)> #<service (forkexec-ctor)> #<service (inetd-ctor)> #<service (systemd-ctor)>)
2024-01-19 00:06:05 [debug] service-registry; register service #<service (system-ctor)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:05 [debug] service-registry is registering service #<service (system-ctor)>
2024-01-19 00:06:05 [debug] service-registry; register service #<service (forkexec-ctor)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:05 [debug] service-registry is registering service #<service (forkexec-ctor)>
2024-01-19 00:06:05 [debug] service-registry; register service #<service (inetd-ctor)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:05 [debug] service-registry is registering service #<service (inetd-ctor)>
2024-01-19 00:06:05 [debug] service-registry; register service #<service (systemd-ctor)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:05 [debug] service-registry is registering service #<service (systemd-ctor)>
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 '#<<shepherd-command> version: (0) action: start service: inetd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 21>
2024-01-19 00:06:05 [debug] Service controller spawned; service #<service (inetd-ctor)>, channel #<<channel> getq: #<atomic-box 7fcecb3bdfd0 value: (())> getq-gc-counter: #<atomic-box 7fcecb3bdfc0 value: 42> putq: #<atomic-box 7fcecb3bdf90 value: (() #(#<atomic-box 7fcecb3bdf60 value: W> #<procedure resume (thunk)> (status #<<channel> getq: #<atomic-box 7fcecb3b8090 value: (())> getq-gc-counter: #<atomic-box 7fcecb3b8070 value: 42> putq: #<atomic-box 7fcecb3b8040 value: (())> putq-gc-counter: #<atomic-box 7fcecb3b8030 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecb3bdf80 value: 41>>
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 #<service (inetd-ctor)> to args ()
2024-01-19 00:06:05 Service inetd-ctor started.
2024-01-19 00:06:05 Service inetd-ctor running with value (#<input-output: socket 22>).
2024-01-19 00:06:05 Service inetd-ctor has been started.
2024-01-19 00:06:05 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: start service: inetd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: #<service (inetd-ctor)> error: #f messages: ("Starting service inetd-ctor..." "Service inetd-ctor started." "Service inetd-ctor running with value (#<input-output: socket 22>)." "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 '#<<shepherd-command> version: (0) action: start service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 21>
2024-01-19 00:06:05 [debug] Service controller spawned; service #<service (system-ctor)>, channel #<<channel> getq: #<atomic-box 7fcecb3efc60 value: (())> getq-gc-counter: #<atomic-box 7fcecb3efc50 value: 42> putq: #<atomic-box 7fcecb3efc30 value: (() #(#<atomic-box 7fcecb3efbf0 value: W> #<procedure resume (thunk)> (status #<<channel> getq: #<atomic-box 7fcecb3efd30 value: (())> getq-gc-counter: #<atomic-box 7fcecb3efd20 value: 42> putq: #<atomic-box 7fcecb3efcf0 value: (())> putq-gc-counter: #<atomic-box 7fcecb3efce0 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecb3efc20 value: 41>>
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 #<service (system-ctor)> 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 #<output: file 24>
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-reply> command: #<<shepherd-command> version: (0) action: start service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: #<service (system-ctor)> 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 '#<<shepherd-command> version: (0) action: status service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:05 [debug] perform-service-action for action 'status', service '#<service (system-ctor)>', with args ()
2024-01-19 00:06:05 [debug] Calling the action's proc #<procedure 7fced03f2f00 at shepherd/service.scm:1013:7 (_)>, action status, running-value #f, args ()
2024-01-19 00:06:05 [debug] Received (#<service (system-ctor)>) from the action's proc #<procedure 7fced03f2f00 at shepherd/service.scm:1013:7 (_)>, action status, args ()
2024-01-19 00:06:05 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: status service: system-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#<service (system-ctor)>) 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 '#<<shepherd-command> version: (0) action: start service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:05 [debug] Service controller spawned; service #<service (forkexec-ctor)>, channel #<<channel> getq: #<atomic-box 7fcecaf60920 value: (())> getq-gc-counter: #<atomic-box 7fcecaf60910 value: 42> putq: #<atomic-box 7fcecaf608f0 value: (() #(#<atomic-box 7fcecaf608c0 value: W> #<procedure resume (thunk)> (status #<<channel> getq: #<atomic-box 7fcecaf609c0 value: (())> getq-gc-counter: #<atomic-box 7fcecaf609b0 value: 42> putq: #<atomic-box 7fcecaf60990 value: (())> putq-gc-counter: #<atomic-box 7fcecaf60980 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecaf608e0 value: 41>>
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 #<service (forkexec-ctor)> 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 #<output: file 18>
2024-01-19 00:06:05 [debug] monitor-service-process for service #<service (forkexec-ctor)>, pid 11947
2024-01-19 00:06:05 Service forkexec-ctor has been started.
2024-01-19 00:06:05 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: start service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: #<service (forkexec-ctor)> 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 #<service (forkexec-ctor)>, 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 '#<<shepherd-command> version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:05 [debug] perform-service-action for action 'status', service '#<service (forkexec-ctor)>', with args ()
2024-01-19 00:06:05 [debug] Calling the action's proc #<procedure 7fcecac4e560 at shepherd/service.scm:1013:7 (_)>, action status, running-value 11947, args ()
2024-01-19 00:06:05 [debug] Received (#<service (forkexec-ctor)>) from the action's proc #<procedure 7fcecac4e560 at shepherd/service.scm:1013:7 (_)>, action status, args ()
2024-01-19 00:06:05 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#<service (forkexec-ctor)>) 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 '#<<shepherd-command> version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:05 [debug] perform-service-action for action 'status', service '#<service (forkexec-ctor)>', with args ()
2024-01-19 00:06:05 [debug] Calling the action's proc #<procedure 7fcecab54b40 at shepherd/service.scm:1013:7 (_)>, action status, running-value 11947, args ()
2024-01-19 00:06:05 [debug] Received (#<service (forkexec-ctor)>) from the action's proc #<procedure 7fcecab54b40 at shepherd/service.scm:1013:7 (_)>, action status, args ()
2024-01-19 00:06:05 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: status service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#<service (forkexec-ctor)>) 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 '#<<shepherd-command> version: (0) action: stop service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:05 [debug] Service controller spawned; service #<service (systemd-ctor)>, channel #<<channel> getq: #<atomic-box 7fced03fbd40 value: (())> getq-gc-counter: #<atomic-box 7fced03fbd20 value: 42> putq: #<atomic-box 7fced03fbcf0 value: (() #(#<atomic-box 7fced03fbcb0 value: W> #<procedure resume (thunk)> (status #<<channel> getq: #<atomic-box 7fced03fbe30 value: (())> getq-gc-counter: #<atomic-box 7fced03fbe20 value: 42> putq: #<atomic-box 7fced03fbe00 value: (())> putq-gc-counter: #<atomic-box 7fced03fbdf0 value: 42>>)))> putq-gc-counter: #<atomic-box 7fced03fbce0 value: 41>>
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-reply> command: #<<shepherd-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 (#<service (t-count-file-descriptors-11858-1)>)
2024-01-19 00:06:05 [debug] service-registry; register service #<service (t-count-file-descriptors-11858-1)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:05 [debug] service-registry is registering service #<service (t-count-file-descriptors-11858-1)>
2024-01-19 00:06:05 [debug] Service controller spawned; service #<service (t-count-file-descriptors-11858-1)>, channel #<<channel> getq: #<atomic-box 7fcecb3cbc60 value: (())> getq-gc-counter: #<atomic-box 7fcecb3cbc40 value: 42> putq: #<atomic-box 7fcecb3cbc20 value: (() #(#<atomic-box 7fcecb3cbbf0 value: W> #<procedure resume (thunk)> (start #<<channel> getq: #<atomic-box 7fcecb3cbd40 value: (())> getq-gc-counter: #<atomic-box 7fcecb3cbd30 value: 42> putq: #<atomic-box 7fcecb3cbd00 value: (())> putq-gc-counter: #<atomic-box 7fcecb3cbcf0 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecb3cbc10 value: 41>>
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 #<service (t-count-file-descriptors-11858-1)> 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 #<input-output: socket 16>
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 #<service (t-count-file-descriptors-11858-1)>, 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 #<service (t-count-file-descriptors-11858-1)>, 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 #<service (t-count-file-descriptors-11858-1)>
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 (#<service (t-count-file-descriptors-11858-1)>)
2024-01-19 00:06:05 [debug] service-registry is unregistering services (#<service (t-count-file-descriptors-11858-1)>)
2024-01-19 00:06:05 [debug] service-controller is terminating, service #<service (t-count-file-descriptors-11858-1)>
2024-01-19 00:06:05 [debug] Service controller fiber is exiting; service #<service (t-count-file-descriptors-11858-1)>, channel #<<channel> getq: #<atomic-box 7fcecb3cbc60 value: (())> getq-gc-counter: #<atomic-box 7fcecb3cbc40 value: 37> putq: #<atomic-box 7fcecb3cbc20 value: (())> putq-gc-counter: #<atomic-box 7fcecb3cbc10 value: 40>>
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 (#<service (t-count-file-descriptors-11858-2)>)
2024-01-19 00:06:06 [debug] service-registry; register service #<service (t-count-file-descriptors-11858-2)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:06 [debug] service-registry is registering service #<service (t-count-file-descriptors-11858-2)>
2024-01-19 00:06:06 [debug] Service controller spawned; service #<service (t-count-file-descriptors-11858-2)>, channel #<<channel> getq: #<atomic-box 7fcecac36700 value: (())> getq-gc-counter: #<atomic-box 7fcecac366f0 value: 42> putq: #<atomic-box 7fcecac366d0 value: (() #(#<atomic-box 7fcecac366a0 value: W> #<procedure resume (thunk)> (start #<<channel> getq: #<atomic-box 7fcecac367b0 value: (())> getq-gc-counter: #<atomic-box 7fcecac367a0 value: 42> putq: #<atomic-box 7fcecac36780 value: (())> putq-gc-counter: #<atomic-box 7fcecac36770 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecac366c0 value: 41>>
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 #<service (t-count-file-descriptors-11858-2)> 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 #<input-output: socket 16>
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 #<service (t-count-file-descriptors-11858-2)>, 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 #<service (t-count-file-descriptors-11858-2)>, 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 #<service (t-count-file-descriptors-11858-2)>
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 (#<service (t-count-file-descriptors-11858-2)>)
2024-01-19 00:06:06 [debug] service-registry is unregistering services (#<service (t-count-file-descriptors-11858-2)>)
2024-01-19 00:06:06 [debug] service-controller is terminating, service #<service (t-count-file-descriptors-11858-2)>
2024-01-19 00:06:06 [debug] Service controller fiber is exiting; service #<service (t-count-file-descriptors-11858-2)>, channel #<<channel> getq: #<atomic-box 7fcecac36700 value: (())> getq-gc-counter: #<atomic-box 7fcecac366f0 value: 37> putq: #<atomic-box 7fcecac366d0 value: (())> putq-gc-counter: #<atomic-box 7fcecac366c0 value: 40>>
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 '#<<shepherd-command> version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:06 [debug] perform-service-action for action 'enable', service '#<service (systemd-ctor)>', with args ()
2024-01-19 00:06:06 [debug] Calling the action's proc #<procedure 7fcecac1d9e0 at shepherd/service.scm:1015:7 (_)>, action enable, running-value #f, args ()
2024-01-19 00:06:06 Enabled service systemd-ctor.
2024-01-19 00:06:06 [debug] Received (#<unspecified>) from the action's proc #<procedure 7fcecac1d9e0 at shepherd/service.scm:1015:7 (_)>, action enable, args ()
2024-01-19 00:06:06 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#<unspecified>) 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 '#<<shepherd-command> version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
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 #<service (systemd-ctor)> to args ()
2024-01-19 00:06:06 Service systemd-ctor has been started.
2024-01-19 00:06:06 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: #<service (systemd-ctor)> 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" . #<input-output: socket 17>)).
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 #<output: file 18>
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 #<service (systemd-ctor)>, pid 12034
2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #<service (systemd-ctor)>, 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 #<service (systemd-ctor)>
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 '#<<shepherd-command> version: (0) action: stop service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:06 [debug] Sending reply #<<command-reply> command: #<<shepherd-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 '#<<shepherd-command> version: (0) action: restart service: forkexec-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:06 [debug] perform-service-action for action 'restart', service '#<service (forkexec-ctor)>', with args ()
2024-01-19 00:06:06 [debug] Calling the action's proc #<procedure 7fcecaf05060 at shepherd/service.scm:1005:7 (running . args)>, 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 #<service (forkexec-ctor)> 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 #<output: file 18>
2024-01-19 00:06:06 [debug] Received (#t) from the action's proc #<procedure 7fcecaf05060 at shepherd/service.scm:1005:7 (running . args)>, action restart, args ()
2024-01-19 00:06:06 [debug] Sending reply #<<command-reply> command: #<<shepherd-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 #<service (forkexec-ctor)>, pid 12054
2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #<service (forkexec-ctor)>, 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 (#<service (t-count-file-descriptors-11858-3)>)
2024-01-19 00:06:06 [debug] service-registry; register service #<service (t-count-file-descriptors-11858-3)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:06 [debug] service-registry is registering service #<service (t-count-file-descriptors-11858-3)>
2024-01-19 00:06:06 [debug] Service controller spawned; service #<service (t-count-file-descriptors-11858-3)>, channel #<<channel> getq: #<atomic-box 7fced02bd0b0 value: (())> getq-gc-counter: #<atomic-box 7fced02bd0a0 value: 42> putq: #<atomic-box 7fced02bd080 value: (() #(#<atomic-box 7fced02bd050 value: W> #<procedure resume (thunk)> (start #<<channel> getq: #<atomic-box 7fced02bd160 value: (())> getq-gc-counter: #<atomic-box 7fced02bd150 value: 42> putq: #<atomic-box 7fced02bd130 value: (())> putq-gc-counter: #<atomic-box 7fced02bd120 value: 42>>)))> putq-gc-counter: #<atomic-box 7fced02bd070 value: 41>>
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 #<service (t-count-file-descriptors-11858-3)> 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 #<input-output: socket 16>
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 #<service (t-count-file-descriptors-11858-3)>, 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 #<service (t-count-file-descriptors-11858-3)>, 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 #<service (t-count-file-descriptors-11858-3)>
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 (#<service (t-count-file-descriptors-11858-3)>)
2024-01-19 00:06:06 [debug] service-registry is unregistering services (#<service (t-count-file-descriptors-11858-3)>)
2024-01-19 00:06:06 [debug] service-controller is terminating, service #<service (t-count-file-descriptors-11858-3)>
2024-01-19 00:06:06 [debug] Service controller fiber is exiting; service #<service (t-count-file-descriptors-11858-3)>, channel #<<channel> getq: #<atomic-box 7fced02bd0b0 value: (())> getq-gc-counter: #<atomic-box 7fced02bd0a0 value: 37> putq: #<atomic-box 7fced02bd080 value: (())> putq-gc-counter: #<atomic-box 7fced02bd070 value: 40>>
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 '#<<shepherd-command> version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
2024-01-19 00:06:06 [debug] perform-service-action for action 'enable', service '#<service (systemd-ctor)>', with args ()
2024-01-19 00:06:06 [debug] Calling the action's proc #<procedure 7fced034cdc0 at shepherd/service.scm:1015:7 (_)>, action enable, running-value #f, args ()
2024-01-19 00:06:06 Enabled service systemd-ctor.
2024-01-19 00:06:06 [debug] Received (#<unspecified>) from the action's proc #<procedure 7fced034cdc0 at shepherd/service.scm:1015:7 (_)>, action enable, args ()
2024-01-19 00:06:06 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: enable service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: (#<unspecified>) 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 '#<<shepherd-command> version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd">', port #<input-output: socket 16>
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 #<service (systemd-ctor)> to args ()
2024-01-19 00:06:06 Service systemd-ctor has been started.
2024-01-19 00:06:06 [debug] Sending reply #<<command-reply> command: #<<shepherd-command> version: (0) action: start service: systemd-ctor args: () directory: "/home/alendvai/workspace/guix/shepherd"> result: #<service (systemd-ctor)> 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" . #<input-output: socket 18>)).
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 #<output: file 19>
2024-01-19 00:06:06 [debug] monitor-service-process for service #<service (systemd-ctor)>, pid 12099
2024-01-19 00:06:06 [debug] monitor-service-process fiber speaking; service #<service (systemd-ctor)>, 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 #<service (systemd-ctor)>
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 (#<service (t-count-file-descriptors-11858-4)>)
2024-01-19 00:06:07 [debug] service-registry; register service #<service (t-count-file-descriptors-11858-4)>, current-module #<directory (guile-user) 7fced03c3c80>
2024-01-19 00:06:07 [debug] service-registry is registering service #<service (t-count-file-descriptors-11858-4)>
2024-01-19 00:06:07 [debug] Service controller spawned; service #<service (t-count-file-descriptors-11858-4)>, channel #<<channel> getq: #<atomic-box 7fcecae88880 value: (())> getq-gc-counter: #<atomic-box 7fcecae88870 value: 42> putq: #<atomic-box 7fcecae88850 value: (() #(#<atomic-box 7fcecae88820 value: W> #<procedure resume (thunk)> (start #<<channel> getq: #<atomic-box 7fcecae88930 value: (())> getq-gc-counter: #<atomic-box 7fcecae88920 value: 42> putq: #<atomic-box 7fcecae88900 value: (())> putq-gc-counter: #<atomic-box 7fcecae888f0 value: 42>>)))> putq-gc-counter: #<atomic-box 7fcecae88840 value: 41>>
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 #<service (t-count-file-descriptors-11858-4)> 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 #<input-output: socket 16>
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 #<service (t-count-file-descriptors-11858-4)>, 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 #<service (t-count-file-descriptors-11858-4)>, 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 #<service (t-count-file-descriptors-11858-4)>
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 (#<service (t-count-file-descriptors-11858-4)>)
2024-01-19 00:06:07 [debug] service-registry is unregistering services (#<service (t-count-file-descriptors-11858-4)>)
2024-01-19 00:06:07 [debug] service-controller is terminating, service #<service (t-count-file-descriptors-11858-4)>
2024-01-19 00:06:07 [debug] Service controller fiber is exiting; service #<service (t-count-file-descriptors-11858-4)>, channel #<<channel> getq: #<atomic-box 7fcecae88880 value: (())> getq-gc-counter: #<atomic-box 7fcecae88870 value: 37> putq: #<atomic-box 7fcecae88850 value: (())> putq-gc-counter: #<atomic-box 7fcecae88840 value: 40>>
+ 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.

bug#67565: shepherd: FAIL: tests/close-on-exec.sh

[Ludovic Courtès]

Hi,

Attila Lendvai <attila@lendvai.name> skribis:

> this log file is with my shepherd branch, i.e. it contains much more log.

Could you check whether it happens with current ‘main’?

The test is quite sensitive to anything that would open file
descriptors, as you can imagine.

Thanks,
Ludo’.

bug#67565: shepherd: FAIL: tests/close-on-exec.sh

[Attila Lendvai]

> > this log file is with my shepherd branch, i.e. it contains much more log.
> 
> 
> Could you check whether it happens with current ‘main’?


i ran a `make check` recently on main, and it ran clean.

it doesn't mean much, though, because it only failed sporadically.

-- 
• attila lendvai
• PGP: 963F 5D5F 45C7 DFCD 0A39
--
“The worst enemy of clear thinking is the propensity to hypostatize, i.e. to ascribe substance or real existence to mental constructs or concepts.”
	— Ludwig von Mises (1881–1973), 'The Ultimate Foundations of Economic Science' (1962)