GNU bug report logs - #77132
Shepherd 1.0.3 build failure on powerpc-linux

Previous Next

To reply to this bug, email your comments to 77132 AT debbugs.gnu.org.

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

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

From: Efraim Flashner <efraim <at> flashner.co.il>
To: bug-guix <at> gnu.org
Subject: Shepherd 1.0.3 build failure on powerpc-linux
Date: Thu, 20 Mar 2025 13:02:18 +0200

[Message part 1 (text/plain, inline)]

I got a test failure on powerpc-linux in tests/services/log-rotation.sh.

-- 
Efraim Flashner   <efraim <at> flashner.co.il>   אפרים פלשנר
GPG key = A28B F40C 3E55 1372 662D  14F7 41AA E7DC CA3D 8351
Confidentiality cannot be guaranteed on emails sent or received unencrypted

[shepherd-ppc-1.0.3.log.gz (application/x-gunzip, attachment)]

[signature.asc (application/pgp-signature, inline)]

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

From: Ludovic Courtès <ludo <at> gnu.org>
To: Efraim Flashner <efraim <at> flashner.co.il>
Cc: 77132 <at> debbugs.gnu.org
Subject: Re: bug#77132: Shepherd 1.0.3 build failure on powerpc-linux
Date: Sun, 13 Apr 2025 22:44:01 +0200

[Message part 1 (text/plain, inline)]

Hey Efraim,

Efraim Flashner <efraim <at> flashner.co.il> skribis:

> I got a test failure on powerpc-linux in tests/services/log-rotation.sh.

The failure looks like this:

--8<---------------cut here---------------start------------->8---
+ herd -s t-socket-5219 stop three
++ file_descriptor_count
++ ls -l /proc/5229/fd/0 /proc/5229/fd/1 /proc/5229/fd/10 /proc/5229/fd/11 /proc/5229/fd/12 /proc/5229/fd/13 /proc/5229/fd/14 /proc/5229/fd/15 /proc/5229/fd/16 /proc/5229/fd/17 /proc/5229/fd/18 /proc/5229/fd/19 /proc/5229/fd/2 /proc/5229/fd/21 /proc/5229/fd/22 /proc/5229/fd/23 /proc/5229/fd/24 /proc/5229/fd/25 /proc/5229/fd/26 /proc/5229/fd/3 /proc/5229/fd/4 /proc/5229/fd/5 /proc/5229/fd/6 /proc/5229/fd/7 /proc/5229/fd/8 /proc/5229/fd/9
++ wc -l
+ test 26 -le 22
--8<---------------cut here---------------end--------------->8---

No idea what could be causing this.  It would be great if you could see
if this is reproducible, for instance by running:

  while make check TESTS=tests/service/log-rotation.sh ; do : ; done

from the failed build tree.

If it is, you could also try with this patch, to get more info:

[Message part 2 (text/x-patch, inline)]

diff --git a/tests/services/log-rotation.sh b/tests/services/log-rotation.sh
index b168aa7..f1a962d 100644
--- a/tests/services/log-rotation.sh
+++ b/tests/services/log-rotation.sh
@@ -96,6 +96,7 @@ shepherd_pid="$(cat "$pid")"
 
 file_descriptor_count ()
 {
+    ls -l /proc/$shepherd_pid/fd/[0-9]*
     ls -l /proc/$shepherd_pid/fd/[0-9]* | wc -l
 }
 

[Message part 3 (text/plain, inline)]

Thanks for the bug report. :-)

Ludo’.

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

From: Simon Josefsson <simon <at> josefsson.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: guix-devel <at> gnu.org, 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Thu, 03 Jul 2025 21:14:16 +0200

[Message part 1 (text/plain, inline)]

Ludovic Courtès <ludo <at> gnu.org> writes:

>> I've often seen failure in the 'log-rotation.sh' self-tests on my own
>> system (see attachment for log),
>
> It fails while checking the number of remaining open file descriptors:
>
> + herd -s t-socket-3705122 stop three
> ++ file_descriptor_count
> ++ ls -l /proc/3705350/fd/0 /proc/3705350/fd/1 /proc/3705350/fd/10 /proc/3705350/fd/11 /proc/3705350/fd/12 /proc/3705350/fd/13 /proc/3705350/fd/14 /proc/3705350/fd/16 /proc/3705350/fd/17 /proc/3705350/fd/18 /proc/3705350/fd/19 /proc/3705350/fd/2 /proc/3705350/fd/20 /proc/3705350/fd/21 /proc/3705350/fd/22 /proc/3705350/fd/3 /proc/3705350/fd/4 /proc/3705350/fd/5 /proc/3705350/fd/6 /proc/3705350/fd/7 /proc/3705350/fd/8 /proc/3705350/fd/9
> ++ wc -l
> + test 22 -le 18
>
> This is the same as <https://issues.guix.gnu.org/77132>.
>
> Could you instrument it as I suggested there?

I'm still seeing this with 1.0.5 which has been uploaded to Debian.  It
is not flaky now, happens every invocation when building on my Trisquel
laptop, even in a simple git checkout v1.0.5 + autoreconf -fvi +
configure + make check.

Below is the "ls" output as suggested in 77132.  Does it help?

/Simon

+ ls -l /proc/1588045/fd/0 /proc/1588045/fd/1 /proc/1588045/fd/10 /proc/1588045/fd/11 /proc/1588045/fd/12 /proc/1588045/fd/13 /proc/1588045/fd/14 /proc/1588045/fd/15 /proc/1588045/fd/16 /proc/1588045/fd/17 /proc/1588045/fd/18 /proc/1588045/fd/2 /proc/1588045/fd/20 /proc/1588045/fd/21 /proc/1588045/fd/22 /proc/1588045/fd/23 /proc/1588045/fd/24 /proc/1588045/fd/25 /proc/1588045/fd/26 /proc/1588045/fd/3 /proc/1588045/fd/4 /proc/1588045/fd/5 /proc/1588045/fd/6 /proc/1588045/fd/7 /proc/1588045/fd/8 /proc/1588045/fd/9
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/0 -> /dev/null
lrwx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/1 -> /dev/pts/4
lrwx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/10 -> 'anon_inode:[signalfd]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/11 -> 'pipe:[338411]'
lrwx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/12 -> 'anon_inode:[eventpoll]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/13 -> /home/jas/src/shepherd/t-log-1586685
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/14 -> 'pipe:[338412]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/15 -> 'pipe:[338412]'
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/16 -> 'pipe:[337388]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/17 -> 'pipe:[337388]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/18 -> /home/jas/src/shepherd/t-service-log1-1586685
lrwx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/2 -> /dev/pts/4
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/20 -> 'pipe:[311028]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/21 -> /home/jas/src/shepherd/t-service-log2-1586685
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/22 -> 'pipe:[339993]'
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/23 -> 'pipe:[339124]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/24 -> 'pipe:[339993]'
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/25 -> 'pipe:[329999]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/26 -> 'pipe:[329999]'
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/3 -> 'pipe:[337387]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/4 -> 'pipe:[337387]'
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/5 -> /home/jas/src/shepherd/shepherd
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/6 -> 'pipe:[338409]'
l-wx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/7 -> 'pipe:[338409]'
lrwx------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/8 -> 'socket:[338410]'
lr-x------ 1 jas jas 64  3 jul 21.12 /proc/1588045/fd/9 -> 'pipe:[338411]'

[signature.asc (application/pgp-signature, inline)]

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

From: Ludovic Courtès <ludo <at> gnu.org>
To: Simon Josefsson <simon <at> josefsson.org>
Cc: guix-devel <at> gnu.org, 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Thu, 03 Jul 2025 22:10:34 +0200

Hi Simon,

Simon Josefsson <simon <at> josefsson.org> writes:

> Ludovic Courtès <ludo <at> gnu.org> writes:

[...]

>> ++ wc -l
>> + test 22 -le 18
>>
>> This is the same as <https://issues.guix.gnu.org/77132>.
>>
>> Could you instrument it as I suggested there?
>
> I'm still seeing this with 1.0.5 which has been uploaded to Debian.  It
> is not flaky now, happens every invocation when building on my Trisquel
> laptop, even in a simple git checkout v1.0.5 + autoreconf -fvi +
> configure + make check.
>
> Below is the "ls" output as suggested in 77132.  Does it help?

Could you send all of ‘tests/services/log-rotation.log’ so we can
compare the open file descriptors before and after?

TIA,
Ludo’.

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

From: Simon Josefsson <simon <at> josefsson.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: guix-devel <at> gnu.org, 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Thu, 03 Jul 2025 23:22:46 +0200

[Message part 1 (text/plain, inline)]

Ludovic Courtès <ludo <at> gnu.org> writes:

> Hi Simon,
>
> Simon Josefsson <simon <at> josefsson.org> writes:
>
>> Ludovic Courtès <ludo <at> gnu.org> writes:
>
> [...]
>
>>> ++ wc -l
>>> + test 22 -le 18
>>>
>>> This is the same as <https://issues.guix.gnu.org/77132>.
>>>
>>> Could you instrument it as I suggested there?
>>
>> I'm still seeing this with 1.0.5 which has been uploaded to Debian.  It
>> is not flaky now, happens every invocation when building on my Trisquel
>> laptop, even in a simple git checkout v1.0.5 + autoreconf -fvi +
>> configure + make check.
>>
>> Below is the "ls" output as suggested in 77132.  Does it help?
>
> Could you send all of ‘tests/services/log-rotation.log’ so we can
> compare the open file descriptors before and after?

Build logs for more architectures, with same failure:

https://buildd.debian.org/status/package.php?p=shepherd&suite=experimental

Below is the log file.

/Simon

[log-rotation.log (application/octet-stream, attachment)]

[signature.asc (application/pgp-signature, inline)]

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

From: Ludovic Courtès <ludo <at> gnu.org>
To: Simon Josefsson <simon <at> josefsson.org>
Cc: guix-devel <at> gnu.org, 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Fri, 04 Jul 2025 08:39:34 +0200

Hi Simon,

Simon Josefsson <simon <at> josefsson.org> writes:

> Below is the log file.

> + shepherd --version
> ;;; WARNING: loading compiled file /usr/lib/x86_64-linux-gnu/guile/3.0/site-ccache/fibers.go failed:
> ;;; In procedure load-thunk-from-memory: incompatible bytecode version
> ;;; WARNING: loading compiled file /usr/lib/x86_64-linux-gnu/guile/3.0/site-ccache/fibers.go failed:
> ;;; In procedure load-thunk-from-memory: incompatible bytecode version

This voids your warranty, if I may: since those object files are
incompatible, Guile ends up interpreting all the code, and this can have
all sorts of side effects in terms of the opened file descriptors.

Could you make sure to use compatible versions of Guile for Fibers and
for the Shepherd?

Thanks,
Ludo’.

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

From: Simon Josefsson <simon <at> josefsson.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: guix-devel <at> gnu.org, 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Fri, 04 Jul 2025 09:47:14 +0200

[Message part 1 (text/plain, inline)]

Ludovic Courtès <ludo <at> gnu.org> writes:

> Hi Simon,
>
> Simon Josefsson <simon <at> josefsson.org> writes:
>
>> Below is the log file.
>
>> + shepherd --version
>> ;;; WARNING: loading compiled file /usr/lib/x86_64-linux-gnu/guile/3.0/site-ccache/fibers.go failed:
>> ;;; In procedure load-thunk-from-memory: incompatible bytecode version
>> ;;; WARNING: loading compiled file /usr/lib/x86_64-linux-gnu/guile/3.0/site-ccache/fibers.go failed:
>> ;;; In procedure load-thunk-from-memory: incompatible bytecode version
>
> This voids your warranty, if I may: since those object files are
> incompatible, Guile ends up interpreting all the code, and this can have
> all sorts of side effects in terms of the opened file descriptors.

Okay -- that log was from a local manual build, outside of the Debian
package build infrastructure.  The log-rotation self check fails in both
environments, and on every invocation now.  It also happens on most
Debian build architectures, but for some reason not on mips64el and
s390x:

https://buildd.debian.org/status/package.php?p=shepherd&suite=experimental

There are other failures in there, but let's fix one thing at a time...

> Could you make sure to use compatible versions of Guile for Fibers and
> for the Shepherd?

I instrumented the Debian package build system to patch the script to
print debug info, below is that log output, is this better?

/Simon

[Message part 2 (text/plain, inline)]

FAIL: tests/services/log-rotation
=================================

+ shepherd --version
shepherd (GNU Shepherd) 1.0.5
Copyright (C) 2025 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) 1.0.5
Copyright (C) 2025 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-473573
+ conf=t-conf-473573
+ log=t-log-473573
+ pid=t-pid-473573
+ service_log1=/build/shepherd-1.0.5/t-service-log1-473573
+ service_log2=/build/shepherd-1.0.5/t-service-log2-473573
+ service_log3=/build/shepherd-1.0.5/t-service-log3-473573
+ external_log=/build/shepherd-1.0.5/t-service-extlog-473573
+ invalid_external_log=/build/shepherd-1.0.5/t-service-invalid-extlog-473573
+ herd='herd -s t-socket-473573'
+ trap 'zcat t-log-473573.* || true; cat t-log-473573 || true;
      rm -f t-socket-473573 t-conf-473573 t-log-473573* /build/shepherd-1.0.5/t-service-log1-473573* /build/shepherd-1.0.5/t-service-log2-473573* /build/shepherd-1.0.5/t-service-log3-473573* /build/shepherd-1.0.5/t-service-extlog-473573*;
      rmdir /build/shepherd-1.0.5/t-service-invalid-extlog-473573;
      test -f t-pid-473573 && kill `cat t-pid-473573` || true; rm -f t-pid-473573' EXIT
+ cat
+ rm -f t-pid-473573
+ test -f t-pid-473573
+ sleep 0.3
+ shepherd -I -s t-socket-473573 -c t-conf-473573 -l t-log-473573 --pid=t-pid-473573
GNU Shepherd 1.0.5 (Guile 3.0.10, x86_64-pc-linux-gnu)
Starting service root...
Service root started.
Service root running with value #<<process> id: 473863 command: #f>.
Service root has been started.
Configuration successfully loaded from 't-conf-473573'.
+ test -f t-pid-473573
++ cat t-pid-473573
+ shepherd_pid=473863
+ herd -s t-socket-473573 start one
Starting service one...
Service one has been started.
+ herd -s t-socket-473573 start two
Starting service two...
Service two has been started.
+ herd -s t-socket-473573 start log-rotation
Starting service log-rotation...
Service log-rotation started.
Service log-rotation running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (6) days-of-week: (0 1 2 3 4 5 6)> #<procedure rotation ()> 7fd2672b3b40>.
Service log-rotation has been started.
+ sleep 0.5
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ grep /build/shepherd-1.0.5/t-service-log1-473573
+ herd -s t-socket-473573 files log-rotation
/build/shepherd-1.0.5/t-service-log1-473573	one
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-473573 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log2-473573
/build/shepherd-1.0.5/t-service-log2-473573	two
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-473573 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-extlog-473573
/build/shepherd-1.0.5/t-service-extlog-473573	(external)
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-473573 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-invalid-extlog-473573
/build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-473573 files log-rotation
+ grep t-log-473573
/build/shepherd-1.0.5/t-log-473573	root
+ test -f /build/shepherd-1.0.5/t-service-log1-473573
+ test -f /build/shepherd-1.0.5/t-service-log2-473573
+ echo 'This is an external log file.'
+ mkdir /build/shepherd-1.0.5/t-service-invalid-extlog-473573
+ herd -s t-socket-473573 trigger log-rotation
Triggering timer.
+ grep 'Rotated ' t-log-473573
+ sleep 0.5
Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
+ grep 'Rotated ' t-log-473573
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-service-extlog-473573'.
+ test -f /build/shepherd-1.0.5/t-service-log1-473573
+ test -f /build/shepherd-1.0.5/t-service-log2-473573
+ test -f t-log-473573
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.1.gz
+ test -f t-log-473573.1.gz
+ test -f /build/shepherd-1.0.5/t-service-log2-473573.1.gz
+ test -f /build/shepherd-1.0.5/t-service-extlog-473573.1.gz
+ gunzip
+ grep 'external log file'
This is an external log file.
+ test -f /build/shepherd-1.0.5/t-service-extlog-473573
+ guile -c '(exit (zero? (stat:size (stat "/build/shepherd-1.0.5/t-service-extlog-473573"))))'
+ zgrep 'Not rotating .*/build/shepherd-1.0.5/t-service-invalid-extlog-473573' t-log-473573 t-log-473573.1.gz
t-log-473573:2025-07-04 07:40:26 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
+ herd -s t-socket-473573 trigger log-rotation
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.1.gz
+ sleep 0.5
Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.1.gz
+ test -f t-log-473573.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-473573
+ test -f /build/shepherd-1.0.5/t-service-log2-473573.1.gz
+ touch -d 2017-10-01 /build/shepherd-1.0.5/t-service-log1-473573.2.gz
+ test -s /build/shepherd-1.0.5/t-service-log1-473573
+ herd -s t-socket-473573 trigger log-rotation
Triggering timer.
+ zgrep 'Deleting .*/build/shepherd-1.0.5/t-service-log1-473573.2.gz' t-log-473573 t-log-473573.1.gz t-log-473573.2.gz
t-log-473573:2025-07-04 07:40:27 Deleting old log file '/build/shepherd-1.0.5/t-service-log1-473573.2.gz'.
Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
gzip: t-log-473573.1.gz: No such file or directory
+ sleep 0.2
+ tail -10 t-log-473573
2025-07-04 07:40:27 Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
2025-07-04 07:40:27 Registering new logger for log-rotation.
2025-07-04 07:40:27 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-extlog-473573', which is below the 0 B threshold.
+ zgrep 'Deleting .*/build/shepherd-1.0.5/t-service-log1-473573.2.gz' t-log-473573 t-log-473573.1.gz t-log-473573.2.gz t-log-473573.3.gz
t-log-473573.1.gz:2025-07-04 07:40:27 Deleting old log file '/build/shepherd-1.0.5/t-service-log1-473573.2.gz'.
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.1.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-473573.3.gz
++ file_descriptor_count
++ ls -l /proc/473863/fd/0 /proc/473863/fd/1 /proc/473863/fd/10 /proc/473863/fd/11 /proc/473863/fd/12 /proc/473863/fd/13 /proc/473863/fd/14 /proc/473863/fd/16 /proc/473863/fd/17 /proc/473863/fd/19 /proc/473863/fd/2 /proc/473863/fd/3 /proc/473863/fd/4 /proc/473863/fd/5 /proc/473863/fd/6 /proc/473863/fd/7 /proc/473863/fd/8 /proc/473863/fd/9
++ ls -l /proc/473863/fd/0 /proc/473863/fd/1 /proc/473863/fd/10 /proc/473863/fd/11 /proc/473863/fd/12 /proc/473863/fd/13 /proc/473863/fd/14 /proc/473863/fd/16 /proc/473863/fd/17 /proc/473863/fd/19 /proc/473863/fd/2 /proc/473863/fd/3 /proc/473863/fd/4 /proc/473863/fd/5 /proc/473863/fd/6 /proc/473863/fd/7 /proc/473863/fd/8 /proc/473863/fd/9
++ wc -l
+ initial_fd_count='lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/0 -> /dev/null
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/1 -> /build/shepherd-1.0.5/tests/services/log-rotation.log
lrwx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/10 -> anon_inode:[signalfd]
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/11 -> pipe:[854239]
lrwx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/12 -> anon_inode:[eventpoll]
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/13 -> /build/shepherd-1.0.5/t-log-473573
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/14 -> /build/shepherd-1.0.5/t-service-log1-473573
lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/16 -> pipe:[851782]
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/17 -> /build/shepherd-1.0.5/t-service-log2-473573
lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/19 -> pipe:[854244]
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/2 -> /build/shepherd-1.0.5/tests/services/log-rotation.log
lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/3 -> pipe:[854236]
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/4 -> pipe:[854236]
lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/5 -> /build/shepherd-1.0.5/shepherd
lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/6 -> pipe:[854237]
l-wx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/7 -> pipe:[854237]
lrwx------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/8 -> socket:[854238]
lr-x------ 1 pbuilder pbuilder 64 Jul  4 07:40 /proc/473863/fd/9 -> pipe:[854239]
18'
+ herd -s t-socket-473573 start three
Service three has been started.
+ herd -s t-socket-473573 trigger three
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-473573
+ herd -s t-socket-473573 status three
+ grep 'Child process'
+ herd -s t-socket-473573 status three
+ grep 'Timer triggered from /build/shepherd-1.0.5'
  2025-07-04 07:40:27 Timer triggered from /build/shepherd-1.0.5.
+ herd -s t-socket-473573 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log3-473573
/build/shepherd-1.0.5/t-service-log3-473573	three
+ herd -s t-socket-473573 trigger log-rotation
Rotating '/build/shepherd-1.0.5/t-service-log3-473573' to '/build/shepherd-1.0.5/t-service-log3-473573.1'.
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-473573.1.gz
+ sleep 0.2
Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
+ test -f /build/shepherd-1.0.5/t-service-log3-473573.1.gz
+ herd -s t-socket-473573 status three
Status of three:
  It is running since 07:40:27 (1 second ago).
  Timed service.
  Periodically running: sh -c "echo Timer triggered from $PWD."
  It is enabled.
  Provides: three
  Custom action: trigger
  Will not be respawned.
  Log file: /build/shepherd-1.0.5/t-service-log3-473573

Recent runs:
  2025-07-04 07:40:27 Process exited successfully after 0 seconds.

Recent messages (use '-n' to view more or less):
  2025-07-04 07:40:27 Timer triggered from /build/shepherd-1.0.5.

Upcoming timer alarms:
  Sun Jan  4 07:41:00 2026 (in 184 days)
  Sun Jan  4 07:42:00 2026 (in 184 days)
  Sun Jan  4 07:43:00 2026 (in 184 days)
  Sun Jan  4 07:44:00 2026 (in 184 days)
  Sun Jan  4 07:45:00 2026 (in 184 days)
+ herd -s t-socket-473573 status three
+ grep 'Timer triggered from /build/shepherd-1.0.5'
  2025-07-04 07:40:27 Timer triggered from /build/shepherd-1.0.5.
+ herd -s t-socket-473573 trigger three
Triggering timer.
+ herd -s t-socket-473573 trigger log-rotation
Rotating '/build/shepherd-1.0.5/t-service-log3-473573' to '/build/shepherd-1.0.5/t-service-log3-473573.1'.
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-473573.2.gz
+ herd -s t-socket-473573 status three
Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
Status of three:
  It is running since 07:40:27 (1 second ago).
  Timed service.
  Periodically running: sh -c "echo Timer triggered from $PWD."
  It is enabled.
  Provides: three
  Custom action: trigger
  Will not be respawned.
  Log file: /build/shepherd-1.0.5/t-service-log3-473573

Recent runs:
  2025-07-04 07:40:27 Process exited successfully after 0 seconds.
  2025-07-04 07:40:28 Process exited successfully after 0 seconds.

Recent messages (use '-n' to view more or less):
  2025-07-04 07:40:28 Timer triggered from /build/shepherd-1.0.5.

Upcoming timer alarms:
  Sun Jan  4 07:41:00 2026 (in 184 days)
  Sun Jan  4 07:42:00 2026 (in 184 days)
  Sun Jan  4 07:43:00 2026 (in 184 days)
  Sun Jan  4 07:44:00 2026 (in 184 days)
  Sun Jan  4 07:45:00 2026 (in 184 days)
+ herd -s t-socket-473573 stop three
++ file_descriptor_count
++ ls -l /proc/473863/fd/0 /proc/473863/fd/1 /proc/473863/fd/10 /proc/473863/fd/11 /proc/473863/fd/12 /proc/473863/fd/13 /proc/473863/fd/14 /proc/473863/fd/16 /proc/473863/fd/17 /proc/473863/fd/18 /proc/473863/fd/19 /proc/473863/fd/2 /proc/473863/fd/20 /proc/473863/fd/21 /proc/473863/fd/22 /proc/473863/fd/3 /proc/473863/fd/4 /proc/473863/fd/5 /proc/473863/fd/6 /proc/473863/fd/7 /proc/473863/fd/8 /proc/473863/fd/9
++ ls -l /proc/473863/fd/0 /proc/473863/fd/1 /proc/473863/fd/10 /proc/473863/fd/11 /proc/473863/fd/12 /proc/473863/fd/13 /proc/473863/fd/14 /proc/473863/fd/16 /proc/473863/fd/17 /proc/473863/fd/18 /proc/473863/fd/19 /proc/473863/fd/2 /proc/473863/fd/20 /proc/473863/fd/21 /proc/473863/fd/22 /proc/473863/fd/3 /proc/473863/fd/4 /proc/473863/fd/5 /proc/473863/fd/6 /proc/473863/fd/7 /proc/473863/fd/8 /proc/473863/fd/9
++ wc -l
+ test lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/0 '->' /dev/null l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/1 '->' /build/shepherd-1.0.5/tests/services/log-rotation.log lrwx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/10 '->' 'anon_inode:[signalfd]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/11 '->' 'pipe:[854239]' lrwx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/12 '->' 'anon_inode:[eventpoll]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/13 '->' /build/shepherd-1.0.5/t-log-473573 l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/14 '->' /build/shepherd-1.0.5/t-service-log1-473573 lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/16 '->' 'pipe:[851782]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/17 '->' /build/shepherd-1.0.5/t-service-log2-473573 lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/18 '->' 'pipe:[829292]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/19 '->' 'pipe:[854244]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/2 '->' /build/shepherd-1.0.5/tests/services/log-rotation.log l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/20 '->' 'pipe:[829292]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/21 '->' 'pipe:[854290]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/22 '->' 'pipe:[854290]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/3 '->' 'pipe:[854236]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/4 '->' 'pipe:[854236]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/5 '->' /build/shepherd-1.0.5/shepherd lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/6 '->' 'pipe:[854237]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/7 '->' 'pipe:[854237]' lrwx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/8 '->' 'socket:[854238]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/9 '->' 'pipe:[854239]' 22 -le lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/0 '->' /dev/null l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/1 '->' /build/shepherd-1.0.5/tests/services/log-rotation.log lrwx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/10 '->' 'anon_inode:[signalfd]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/11 '->' 'pipe:[854239]' lrwx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/12 '->' 'anon_inode:[eventpoll]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/13 '->' /build/shepherd-1.0.5/t-log-473573 l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/14 '->' /build/shepherd-1.0.5/t-service-log1-473573 lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/16 '->' 'pipe:[851782]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/17 '->' /build/shepherd-1.0.5/t-service-log2-473573 lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/19 '->' 'pipe:[854244]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/2 '->' /build/shepherd-1.0.5/tests/services/log-rotation.log lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/3 '->' 'pipe:[854236]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/4 '->' 'pipe:[854236]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/5 '->' /build/shepherd-1.0.5/shepherd lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/6 '->' 'pipe:[854237]' l-wx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/7 '->' 'pipe:[854237]' lrwx------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/8 '->' 'socket:[854238]' lr-x------ 1 pbuilder pbuilder 64 Jul 4 07:40 /proc/473863/fd/9 '->' 'pipe:[854239]' 18
./tests/services/log-rotation.sh: line 186: test: too many arguments
+ zcat t-log-473573.1.gz t-log-473573.2.gz t-log-473573.3.gz t-log-473573.4.gz t-log-473573.5.gz
2025-07-04 07:40:27 Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
2025-07-04 07:40:27 Registering new logger for log-rotation.
2025-07-04 07:40:27 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-extlog-473573', which is below the 0 B threshold.
2025-07-04 07:40:28 Triggering timer.
2025-07-04 07:40:28 Timer 'three' spawned process 485879.
2025-07-04 07:40:28 Registering new logger for three.
2025-07-04 07:40:28 Process 485879 of timer 'three' terminated with status 0 after 0 seconds.
2025-07-04 07:40:28 Triggering timer.
2025-07-04 07:40:28 Rotating '/build/shepherd-1.0.5/t-service-log3-473573' to '/build/shepherd-1.0.5/t-service-log3-473573.1'.
2025-07-04 07:40:28 Registering new logger for log-rotation.
2025-07-04 07:40:28 Rotated '/build/shepherd-1.0.5/t-service-log3-473573'.
2025-07-04 07:40:28 Not rotating '/build/shepherd-1.0.5/t-service-log2-473573', which is below the 0 B threshold.
2025-07-04 07:40:28 Rotating '/build/shepherd-1.0.5/t-service-log1-473573' to '/build/shepherd-1.0.5/t-service-log1-473573.1'.
2025-07-04 07:40:28 Registering new logger for log-rotation.
2025-07-04 07:40:28 Rotated '/build/shepherd-1.0.5/t-service-log1-473573'.

2025-07-04 07:40:28 Rotating log.
2025-07-04 07:40:27 Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
2025-07-04 07:40:27 Registering new logger for log-rotation.
2025-07-04 07:40:27 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-extlog-473573', which is below the 0 B threshold.
2025-07-04 07:40:27 Starting service three...
2025-07-04 07:40:27 Service three has been started.
2025-07-04 07:40:27 Service three started.
2025-07-04 07:40:27 Service three running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (1) days-of-week: (0 1 2 3 4 5 6)> #<<command> arguments: ("sh" "-c" "echo Tim
2025-07-04 07:40:27 er triggered from $PWD.") user: #f group: #f supplementary-groups: () environment-variables: ("SHELL=/bin/bash" "SESSION_MANAGER=local/kaka:@/tmp/.ICE-unix/2013,unix/kaka:/tmp/.ICE-unix/2013" "QT_ACCESSIBILITY=1" "COLORTERM=truecolor" "DEB_HOST_ARCH_LIBC=gnu" "XDG_CONFIG_DIRS=/home/jas/.guix-home/profile/etc/xdg:/etc/xdg/xdg-gnome:/etc/xdg" "SSH_AGENT_LAUNCHER=gnome-keyring" "SUDO_GID=1000" "XDG_MENU_PREFIX=gnome-" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_POOL_GIT_TOKEN=glpat-KhpzkNzu1Lt5kxoRR7Y4" "DISTS_PUR
2025-07-04 07:40:27 EOS=/home/jas/src/dists/pureos" "GNOME_DESKTOP_SESSION_ID=this-is-deprecated" "DEB_TARGET_GNU_SYSTEM=linux-gnu" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_POOL_TRIGGER_TOKEN=glptt-1f76b69c2323931b05be6dabce858360b13d7487" "DPKG_ADMINDIR=/var/lib/dpkg" "PKG_CONFIG_PATH=/home/jas/.guix-profile/lib/pkgconfig:/home/jas/.guix-profile/share/pkgconfig:/home/jas/.guix-profile/lib/pkgconfig:/home/jas/.guix-profile/share/pkgconfig" "DEB_HOST_MULTIARCH=x86_64-linux-gnu" "CPPFLAGS_FOR_BUILD=-Wdate-time -D_FORTIFY_SOURCE=2
2025-07-04 07:40:27 " "OBJCXXFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "LDFLAGS_FOR_BUILD=-Wl,-z,relro -Wl,-z,now" "DEB_TARGET_ARCH_CPU=amd64" "DDU_BUILD_DEBIAN_TRIXIE_ARM64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-99b6eac82b98e014608e3020957fa23028403252" "SSH_AUTH_SOCK=/run/user/1000/gnupg/S.gpg-agent.ssh" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_GIT_TOKEN=glpat-HzLL_JrxeDWiTu4rzvy4" "XDG_DATA_HOME=/home/jas/.
2025-07-04 07:40:27 local/share" "GBP_PBUILDER_DIST=debian_latest" "DH_INTERNAL_OVERRIDE=dh_auto_test" "DDU_BUILD_DEBIAN_BOOKWORM_ARM64_STAGE0_PIPELINE_PROJECT=69100903" "PBUILDER_PKGLIBDIR=/usr/lib/pbuilder" "COWDANCER_REUSE=yes" "TEST_LOGS=tests/services/log-rotation.log" "XCURSOR_PATH=/home/jas/.guix-home/profile/share/icons:" "DEBFULLNAME=Simon Josefsson" "SUDO_COMMAND=/usr/sbin/cowbuilder --build --buildresult /home/jas/dpkg --debbuildopts  --debbuildopts  --source-only-changes --basepath /var/cache/pbuilder/base-debian_l
2025-07-04 07:40:27 atest.cow ../shepherd_1.0.5-1.dsc" "XMODIFIERS=@im=ibus" "DESKTOP_SESSION=gnome" "SUDO_USER=jas" "DEB_TARGET_ARCH_BITS=64" "EDITOR=nano" "FFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -fcf-protection" "PBUILDER_SYSCONFDIR=/etc" "DISTS_GNUINOS=/home/jas/src/dists/gnuinos" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-e3369473d1e749f15bd6ed9078f133ad13ea5737" "GTK_MODULES=gail:atk-bridge" "PWD=/build/shepherd-1.0.5" "DEB_BUILD_
2025-07-04 07:40:27 MULTIARCH=x86_64-linux-gnu" "SOURCE_DATE_EPOCH=1751527360" "LOGNAME=pbuilder" "XDG_SESSION_DESKTOP=gnome" "XDG_SESSION_TYPE=wayland" "DEB_HOST_GNU_SYSTEM=linux-gnu" "CCACHE_DIR=/var/cache/pbuilder/ccache" "DEB_RULES_REQUIRES_ROOT=no" "CFLAGS_FOR_BUILD=-g -O2 -Werror=implicit-function-declaration -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "MANPATH=/home/jas/.guix-home/profile/share/man:" "DEB_BUILD_ARCH_BITS=64
2025-07-04 07:40:27 " "SYSTEMD_EXEC_PID=17083" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_BUILD_PIPELINE_TRIGGER_TOKEN=glptt-c0716a7cd5d7e0f64d2a4aaa175be73629c04870" "GUILE_LOAD_PATH=/build/shepherd-1.0.5/modules:/build/shepherd-1.0.5/modules:" "CXXFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "DEB_BUILD_ARCH_OS=linux" "XAUTHORITY=/run/user/1000/.mutter-Xwaylandauth.F6F182" "DISTS_DEVUAN=/home/jas/src/dists/devuan" "DDU_B
2025-07-04 07:40:27 UILD_DEBIAN_TRIXIE_AMD64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-afb3c982190007b086a8627a95f87bc2301a43dd" "ASFLAGS_FOR_BUILD=" "LD_PRELOAD=" "DDU_BUILD_DEBIAN_TRIXIE_AMD64_STAGE0_PIPELINE_PROJECT=69108031" "DDU_ARCHIVES_DEBIAN_STAGE0_BOOKWORM_AMD64_TRIGGER_TOKEN=glptt-603e27e96c6c5e9bc914092c87d2f67683844310" "GIT_EXEC_PATH=/home/jas/.guix-home/profile/libexec/git-core" "LDFLAGS=-Wl,-z,relro -Wl,-z,now" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_PIPELINE_PROJECT=69099423" "HOME=/nonexistent" "USERNAME=jas" "COWDA
2025-07-04 07:40:27 NCER_ILISTFILE=/.ilist" "IM_CONFIG_PHASE=1" "DDU_BUILD_DEBIAN_BOOKWORM_ARM64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-8f7a7e2e95acbf781a1af27682b77039dc83a162" "GIT_SSL_CAINFO=/home/jas/.guix-profile/etc/ssl/certs/ca-certificates.crt" "LANG=C" "DEB_HOST_ARCH_ABI=base" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=00:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=0
2025-07-04 07:40:27 1;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.avif=01;35:*.jpg=01;35:*.jpeg=01;35:*.mjpg=
2025-07-04 07:40:27 01;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.webp=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;
2025-07-04 07:40:27 35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:*~=00;90:*#=00;90:*.bak=00;90:*.old=00;90:*.orig=00;90:*.part=00;90:*.rej=00;90:*.swp=00;90:*.tmp=00;90:*.dpkg-dist=00;90:*.dpkg-old=00;90:*.ucf-dist=00;90:*.ucf-new=00;90:*.ucf-old=00;90:*.rpmnew=00;90:*.rpmorig=00;90:*.rpmsave=00;90:" "XDG_CURRENT_DESKT
2025-07-04 07:40:27 OP=GNOME" "srcdir=." "VTE_VERSION=6800" "GIT_PBUILDER_OPTIONS=--source-only-changes" "DEB_TARGET_ARCH_LIBC=gnu" "DEB_TARGET_GNU_TYPE=x86_64-linux-gnu" "WAYLAND_DISPLAY=wayland-0" "SSL_CERT_DIR=/home/jas/.guix-profile/etc/ssl/certs" "BUILDRESULTGID=1000" "DEB_TARGET_ARCH_ABI=base" "DEBEMAIL=simon <at> josefsson.org" "DDU_BUILD_TRIXIE_AMD64_TRIGGER_TOKEN=glptt-2a3e7330e1058e0277bd9059ca81a4e345d4b0c5" "GNOME_TERMINAL_SCREEN=/org/gnome/Terminal/screen/a5d249ad_21e0_4620_b7d4_5aa269381a0d" "CPPFLAGS=-Wdate-time -D_F
2025-07-04 07:40:27 ORTIFY_SOURCE=2" "OBJCFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "DDU_BUILD_SCRATCH_ACCESS_TOKEN=glpat-1Xa2gjzbxdcGb_2WWiaS" "GUILE_LOAD_COMPILED_PATH=/build/shepherd-1.0.5/modules:/build/shepherd-1.0.5/modules:" "DEB_TARGET_ARCH=amd64" "DEB_BUILD_ARCH=amd64" "GUILE=/usr/bin/guile-3.0" "DOTNET_BUNDLE_EXTRACT_BASE_DIR=/home/jas/.cache/dotnet_bundle_extract" "PBCURRENTCOMMANDLINEOPERATION=
2025-07-04 07:40:27 build" "PBUILDER_PKGDATADIR=/usr/share/pbuilder" "DEB_TARGET_ARCH_OS=linux" "MFLAGS=" "XDG_CACHE_HOME=/home/jas/.cache" "PBUILDER_OPERATION=build" "INFOPATH=/home/jas/.guix-home/profile/share/info:/home/jas/.guix-profile/share/info:/home/jas/.guix-profile/share/info:/home/jas/.config/guix/current/share/info:" "GNOME_SETUP_DISPLAY=:1" "DDU_BUILD_BOOKWORM_ARM64_TRIGGER_TOKEN=glptt-56595017909976c40a98bdc789a725e6a6c3e11f" "FCFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fsta
2025-07-04 07:40:27 ck-clash-protection -fcf-protection" "XDG_SESSION_CLASS=user" "MAKEFLAGS= -- TEST_LOGS=tests/services/log-rotation.log VERBOSE=1 TESTS=tests/services/log-rotation.sh" "TERM=xterm-256color" "DEB_TARGET_MULTIARCH=x86_64-linux-gnu" "FCFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -fcf-protection" "DEB_BUILD_ARCH_CPU=amd64" "DEB_BUILD_ARCH_LIBC=gnu" "OBJCFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-cl
2025-07-04 07:40:27 ash-protection -Wformat -Werror=format-security -fcf-protection" "ACLOCAL_PATH=/home/jas/.guix-profile/share/aclocal:/home/jas/.guix-profile/share/aclocal" "LIBVIRT_DEFAULT_URI=qemu:///system" "USER=pbuilder" "GBP_BUILD_DIR=/home/jas/dpkg/shepherd" "CURL_CA_BUNDLE=/home/jas/.guix-profile/etc/ssl/certs/ca-certificates.crt" "DEB_HOST_ARCH_BITS=64" "GNOME_TERMINAL_SERVICE=:1.116" "FFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -fcf-protection
2025-07-04 07:40:27 " "DEB_BUILD_GNU_TYPE=x86_64-linux-gnu" "CXXFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "DEB_BUILD_OPTIONS=parallel=16" "SHLVL=7" "GUIX_LOCPATH=/home/jas/.guix-home/profile/lib/locale:/home/jas/.guix-profile/lib/locale" "MAKELEVEL=7" "DEB_BUILD_GNU_SYSTEM=linux-gnu" "DH_INTERNAL_OPTIONS=" "QT_IM_MODULE=ibus" "LC_MESSAGES=C" "DFLAGS_FOR_BUILD=-frelease" "DEB_BUILD_MAINT_OPTIONS=hardening=+
2025-07-04 07:40:27 bindnow" "DEB_TARGET_GNU_CPU=x86_64" "BUILDRESULTUID=1000" "DEB_TARGET_ARCH_ENDIAN=little" "DEB_HOST_ARCH=amd64" "XDG_STATE_HOME=/home/jas/.local/state" "GUIX_PROFILE=/home/jas/.guix-profile" "DDU_BUILD_DEBIAN_BOOKWORM_ARM64_STAGE0_GIT_TOKEN=glpat-X5P7zy3H9u7QPXesxJSh" "DEB_HOST_ARCH_ENDIAN=little" "XDG_RUNTIME_DIR=/run/user/1000" "SSL_CERT_FILE=/home/jas/.guix-profile/etc/ssl/certs/ca-certificates.crt" "DEB_HOST_GNU_TYPE=x86_64-linux-gnu" "DDU_BUILD_DEBIAN_TRIXIE_ARM64_STAGE0_PIPELINE_PROJECT=69108209" "LC
2025-07-04 07:40:27 _ALL=C" "DISTS_DEBIAN=/home/jas/src/dists/debian" "DISTS_UBUNTU=/home/jas/src/dists/ubuntu" "XDG_DATA_DIRS=/home/jas/.guix-home/profile/share:/home/jas/.guix-profile/share:/usr/share/gnome:/usr/local/share/:/usr/share/" "ICECAT_SYSTEM_DIR=/home/jas/.guix-home/profile/lib/icecat" "CONFIG_SITE=/home/jas/moln/dot-files/config.site" "PATH=/build/shepherd-1.0.5:/usr/lib/ccache:/usr/sbin:/usr/bin:/sbin:/bin" "DEB_BUILD_ARCH_ENDIAN=little" "DEB_HOST_ARCH_CPU=amd64" "DDU_ARCHIVES_DEBIAN_STAGE0_BOOKWORM_AMD64_GIT_TO
2025-07-04 07:40:27 KEN=glpat-xtGhb85bTtLgXqHyohEB" "CC=gcc" "GDMSESSION=gnome" "TESTS=tests/services/log-rotation.sh" "CFLAGS=-g -O2 -Werror=implicit-function-declaration -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "SUDO_UID=1000" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus" "DDU_BUILD_BOOKWORM_AMD64_TRIGGER_TOKEN=glptt-4d6dfa0a133b0d35bb3b7640b6d48f554bd3b868" "OBJCXXFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.
2025-07-04 07:40:27 5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "PASSWORD_STORE_DIR=/home/jas/moln/password-store/" "EMACSLOADPATH=/home/jas/.guix-profile/share/emacs/site-lisp:/home/jas/.guix-profile/share/emacs/site-lisp" "GBP_PBUILDER_OPTIONS=--source-only-changes" "DFLAGS=-frelease" "DISTS_TRISQUEL=/home/jas/src/dists/trisquel" "DEB_HOST_GNU_CPU=x86_64" "DEB_HOST_ARCH_OS=linux" "DEB_BUILD_GNU_CPU=x86_64" "DEBIAN_FRONTEND=noninteractive" "DEB_BUILD_ARCH_ABI=base" "
2025-07-04 07:40:27 DH_INTERNAL_BUILDFLAGS=1" "OLDPWD=/" "VERBOSE=1" "ASFLAGS=" "_=/build/shepherd-1.0.5/shepherd") directory: "/build/shepherd-1.0.5" resource-limits: ()> 7fd25e2358c0>.
2025-07-04 07:40:27 Triggering timer.
2025-07-04 07:40:27 Timer 'three' spawned process 484027.
2025-07-04 07:40:27 Process 484027 of timer 'three' terminated with status 0 after 0 seconds.
2025-07-04 07:40:27 /build/shepherd-1.0.5/t-service-log3-473573	three
2025-07-04 07:40:27 /build/shepherd-1.0.5/t-service-log2-473573	two
2025-07-04 07:40:27 /build/shepherd-1.0.5/t-service-log1-473573	one
2025-07-04 07:40:27 /build/shepherd-1.0.5/t-log-473573	root
2025-07-04 07:40:27 /build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
2025-07-04 07:40:27 /build/shepherd-1.0.5/t-service-extlog-473573	(external)
2025-07-04 07:40:27 Triggering timer.
2025-07-04 07:40:27 Rotating '/build/shepherd-1.0.5/t-service-log3-473573' to '/build/shepherd-1.0.5/t-service-log3-473573.1'.
2025-07-04 07:40:27 Registering new logger for log-rotation.
2025-07-04 07:40:27 Rotated '/build/shepherd-1.0.5/t-service-log3-473573'.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-log2-473573', which is below the 0 B threshold.
2025-07-04 07:40:27 Rotating '/build/shepherd-1.0.5/t-service-log1-473573' to '/build/shepherd-1.0.5/t-service-log1-473573.1'.
2025-07-04 07:40:27 Registering new logger for log-rotation.
2025-07-04 07:40:27 Rotated '/build/shepherd-1.0.5/t-service-log1-473573'.

2025-07-04 07:40:27 Rotating log.
2025-07-04 07:40:26 Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
2025-07-04 07:40:26 Registering new logger for log-rotation.
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:26 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
2025-07-04 07:40:26 Not rotating '/build/shepherd-1.0.5/t-service-extlog-473573', which is below the 0 B threshold.
2025-07-04 07:40:27 Triggering timer.
2025-07-04 07:40:27 Not rotating '/build/shepherd-1.0.5/t-service-log2-473573', which is below the 0 B threshold.
2025-07-04 07:40:27 Deleting old log file '/build/shepherd-1.0.5/t-service-log1-473573.2.gz'.
2025-07-04 07:40:27 Rotating '/build/shepherd-1.0.5/t-service-log1-473573' to '/build/shepherd-1.0.5/t-service-log1-473573.1'.
2025-07-04 07:40:27 Registering new logger for log-rotation.
2025-07-04 07:40:27 Rotated '/build/shepherd-1.0.5/t-service-log1-473573'.

2025-07-04 07:40:27 Rotating log.
2025-07-04 07:40:26 Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
2025-07-04 07:40:26 Registering new logger for log-rotation.
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:26 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
2025-07-04 07:40:26 Registering new logger for log-rotation.
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-service-extlog-473573'.
2025-07-04 07:40:26 Triggering timer.
2025-07-04 07:40:26 Not rotating '/build/shepherd-1.0.5/t-service-log2-473573', which is below the 0 B threshold.
2025-07-04 07:40:26 Rotating '/build/shepherd-1.0.5/t-service-log1-473573' to '/build/shepherd-1.0.5/t-service-log1-473573.1'.
2025-07-04 07:40:26 Registering new logger for log-rotation.
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-service-log1-473573'.

2025-07-04 07:40:26 Rotating log.
2025-07-04 07:40:25 GNU Shepherd 1.0.5 (Guile 3.0.10, x86_64-pc-linux-gnu)
2025-07-04 07:40:25 Starting service root...
2025-07-04 07:40:25 Service root started.
2025-07-04 07:40:25 Service root running with value #<<process> id: 473863 command: #f>.
2025-07-04 07:40:25 Service root has been started.
2025-07-04 07:40:25 Configuration successfully loaded from 't-conf-473573'.
2025-07-04 07:40:25 Starting service one...
2025-07-04 07:40:25 Service one has been started.
2025-07-04 07:40:25 Service one started.
2025-07-04 07:40:25 Service one running with value #<<process> id: 475511 command: ("/bin/bash" "-c" "while true; do echo logging things; sleep 0.2; done")>.
2025-07-04 07:40:25 Starting service two...
2025-07-04 07:40:25 Service two has been started.
2025-07-04 07:40:25 Service two started.
2025-07-04 07:40:25 Service two running with value #<<process> id: 475611 command: ("sleep" "600")>.
2025-07-04 07:40:25 Starting service log-rotation...
2025-07-04 07:40:25 Service log-rotation started.
2025-07-04 07:40:25 Service log-rotation running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (6) days-of-week: (0 1 2 3 4 5 6)> #<procedure rotation ()> 7fd2672b3b4
2025-07-04 07:40:25 0>.
2025-07-04 07:40:25 Service log-rotation has been started.
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log2-473573	two
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log1-473573	one
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-log-473573	root
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log2-473573	two
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log1-473573	one
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-log-473573	root
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log2-473573	two
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log1-473573	one
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-log-473573	root
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log2-473573	two
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log1-473573	one
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-log-473573	root
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log2-473573	two
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-log1-473573	one
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-log-473573	root
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-invalid-extlog-473573	(external)
2025-07-04 07:40:26 /build/shepherd-1.0.5/t-service-extlog-473573	(external)
2025-07-04 07:40:26 Triggering timer.
2025-07-04 07:40:26 Not rotating '/build/shepherd-1.0.5/t-service-log2-473573', which is below the 0 B threshold.
2025-07-04 07:40:26 Rotating '/build/shepherd-1.0.5/t-service-log1-473573' to '/build/shepherd-1.0.5/t-service-log1-473573.1'.
2025-07-04 07:40:26 Rotated '/build/shepherd-1.0.5/t-service-log1-473573'.

2025-07-04 07:40:26 Rotating log.
+ cat t-log-473573
2025-07-04 07:40:28 Rotating '/build/shepherd-1.0.5/t-log-473573' to '/build/shepherd-1.0.5/t-log-473573.1'.
2025-07-04 07:40:28 Registering new logger for log-rotation.
2025-07-04 07:40:28 Rotated '/build/shepherd-1.0.5/t-log-473573'.
2025-07-04 07:40:28 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-473573', which is not a regular file.
2025-07-04 07:40:28 Not rotating '/build/shepherd-1.0.5/t-service-extlog-473573', which is below the 0 B threshold.
2025-07-04 07:40:28 Stopping service three...
2025-07-04 07:40:28 Terminating timer 'three' with 0 processes running.
2025-07-04 07:40:28 Service three stopped.
2025-07-04 07:40:28 Service three is now stopped.
+ rm -f t-socket-473573 t-conf-473573 t-log-473573 t-log-473573.1.gz t-log-473573.2.gz t-log-473573.3.gz t-log-473573.4.gz t-log-473573.5.gz /build/shepherd-1.0.5/t-service-log1-473573 /build/shepherd-1.0.5/t-service-log1-473573.1.gz /build/shepherd-1.0.5/t-service-log1-473573.2.gz /build/shepherd-1.0.5/t-service-log1-473573.3.gz /build/shepherd-1.0.5/t-service-log1-473573.4.gz /build/shepherd-1.0.5/t-service-log2-473573 /build/shepherd-1.0.5/t-service-log3-473573 /build/shepherd-1.0.5/t-service-log3-473573.1.gz /build/shepherd-1.0.5/t-service-log3-473573.2.gz /build/shepherd-1.0.5/t-service-extlog-473573 /build/shepherd-1.0.5/t-service-extlog-473573.1.gz
+ rmdir /build/shepherd-1.0.5/t-service-invalid-extlog-473573
+ test -f t-pid-473573
++ cat t-pid-473573
+ kill 473863
+ rm -f t-pid-473573
Stopping service root...
FAIL tests/services/log-rotation.sh (exit status: 2)
Exiting shepherd...
Service three is not running.
Exiting.

[signature.asc (application/pgp-signature, inline)]

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

From: Ludovic Courtès <ludo <at> gnu.org>
To: Simon Josefsson <simon <at> josefsson.org>
Cc: 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Sun, 06 Jul 2025 21:44:18 +0200

[Message part 1 (text/plain, inline)]

Hi Simon,

(- guix-devel)

Simon Josefsson <simon <at> josefsson.org> writes:

> I instrumented the Debian package build system to patch the script to
> print debug info, below is that log output, is this better?

I made a mistake: in ‘file_descriptor_count’, the line to add should be:

  ls -l /proc/$shepherd_pid/fd/ >&2

Otherwise, if we do not redirect the output to standard error, the test
breaks poorly:

  ./tests/services/log-rotation.sh: line 186: test: too many arguments

Could you try that?

Also, I wonder if the problem could be a race condition, which would be
fixed like this:

[Message part 2 (text/x-patch, inline)]

diff --git a/tests/services/log-rotation.sh b/tests/services/log-rotation.sh
index 375f563..178bb49 100644
--- a/tests/services/log-rotation.sh
+++ b/tests/services/log-rotation.sh
@@ -182,6 +182,6 @@ $herd trigger log-rotation
 until test -f "$service_log3.2.gz"; do sleep 0.2; done
 $herd status three
 $herd stop three
-test $(file_descriptor_count) -le $initial_fd_count
+until test $(file_descriptor_count) -le $initial_fd_count; do sleep 0.3; done
 
 $herd stop log-rotation

[Message part 3 (text/plain, inline)]

Could you also give that a try?

Thanks,
Ludo’.

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

From: Simon Josefsson <simon <at> josefsson.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Sun, 06 Jul 2025 22:04:03 +0200

[Message part 1 (text/plain, inline)]

Ludovic Courtès <ludo <at> gnu.org> writes:

> Hi Simon,
>
> (- guix-devel)
>
> Simon Josefsson <simon <at> josefsson.org> writes:
>
>> I instrumented the Debian package build system to patch the script to
>> print debug info, below is that log output, is this better?
>
> I made a mistake: in ‘file_descriptor_count’, the line to add should be:
>
>   ls -l /proc/$shepherd_pid/fd/ >&2
>
> Otherwise, if we do not redirect the output to standard error, the test
> breaks poorly:
>
>   ./tests/services/log-rotation.sh: line 186: test: too many arguments
>
> Could you try that?

Sure, see output below.

/Simon

[Message part 2 (text/plain, inline)]

FAIL: tests/services/log-rotation
=================================

+ shepherd --version
shepherd (GNU Shepherd) 1.0.5
Copyright (C) 2025 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) 1.0.5
Copyright (C) 2025 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-2781150
+ conf=t-conf-2781150
+ log=t-log-2781150
+ pid=t-pid-2781150
+ service_log1=/build/shepherd-1.0.5/t-service-log1-2781150
+ service_log2=/build/shepherd-1.0.5/t-service-log2-2781150
+ service_log3=/build/shepherd-1.0.5/t-service-log3-2781150
+ external_log=/build/shepherd-1.0.5/t-service-extlog-2781150
+ invalid_external_log=/build/shepherd-1.0.5/t-service-invalid-extlog-2781150
+ herd='herd -s t-socket-2781150'
+ trap 'zcat t-log-2781150.* || true; cat t-log-2781150 || true;
      rm -f t-socket-2781150 t-conf-2781150 t-log-2781150* /build/shepherd-1.0.5/t-service-log1-2781150* /build/shepherd-1.0.5/t-service-log2-2781150* /build/shepherd-1.0.5/t-service-log3-2781150* /build/shepherd-1.0.5/t-service-extlog-2781150*;
      rmdir /build/shepherd-1.0.5/t-service-invalid-extlog-2781150;
      test -f t-pid-2781150 && kill `cat t-pid-2781150` || true; rm -f t-pid-2781150' EXIT
+ cat
+ rm -f t-pid-2781150
+ test -f t-pid-2781150
+ sleep 0.3
+ shepherd -I -s t-socket-2781150 -c t-conf-2781150 -l t-log-2781150 --pid=t-pid-2781150
GNU Shepherd 1.0.5 (Guile 3.0.10, x86_64-pc-linux-gnu)
Starting service root...
Service root started.
Service root running with value #<<process> id: 2781604 command: #f>.
Service root has been started.
Configuration successfully loaded from 't-conf-2781150'.
+ test -f t-pid-2781150
++ cat t-pid-2781150
+ shepherd_pid=2781604
+ herd -s t-socket-2781150 start one
Starting service one...
Service one has been started.
+ herd -s t-socket-2781150 start two
Starting service two...
Service two has been started.
+ herd -s t-socket-2781150 start log-rotation
Starting service log-rotation...
Service log-rotation started.
Service log-rotation running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (6) days-of-week: (0 1 2 3 4 5 6)> #<procedure rotation ()> 7f239d58dea0>.
Service log-rotation has been started.
+ sleep 0.5
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-2781150 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log1-2781150
/build/shepherd-1.0.5/t-service-log1-2781150	one
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-2781150 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log2-2781150
/build/shepherd-1.0.5/t-service-log2-2781150	two
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-2781150 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-extlog-2781150
/build/shepherd-1.0.5/t-service-extlog-2781150	(external)
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-2781150 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-invalid-extlog-2781150
/build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-2781150 files log-rotation
+ grep t-log-2781150
/build/shepherd-1.0.5/t-log-2781150	root
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150
+ test -f /build/shepherd-1.0.5/t-service-log2-2781150
+ echo 'This is an external log file.'
+ mkdir /build/shepherd-1.0.5/t-service-invalid-extlog-2781150
+ herd -s t-socket-2781150 trigger log-rotation
Triggering timer.
+ grep 'Rotated ' t-log-2781150
+ sleep 0.5
Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
+ grep 'Rotated ' t-log-2781150
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-log-2781150'.
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-service-extlog-2781150'.
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150
+ test -f /build/shepherd-1.0.5/t-service-log2-2781150
+ test -f t-log-2781150
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.1.gz
+ test -f t-log-2781150.1.gz
+ test -f /build/shepherd-1.0.5/t-service-log2-2781150.1.gz
+ test -f /build/shepherd-1.0.5/t-service-extlog-2781150.1.gz
+ gunzip
+ grep 'external log file'
This is an external log file.
+ test -f /build/shepherd-1.0.5/t-service-extlog-2781150
+ guile -c '(exit (zero? (stat:size (stat "/build/shepherd-1.0.5/t-service-extlog-2781150"))))'
+ zgrep 'Not rotating .*/build/shepherd-1.0.5/t-service-invalid-extlog-2781150' t-log-2781150 t-log-2781150.1.gz
t-log-2781150:2025-07-06 20:02:58 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-2781150', which is not a regular file.
+ herd -s t-socket-2781150 trigger log-rotation
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.1.gz
+ sleep 0.5
Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.1.gz
+ test -f t-log-2781150.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150
+ test -f /build/shepherd-1.0.5/t-service-log2-2781150.1.gz
+ touch -d 2017-10-01 /build/shepherd-1.0.5/t-service-log1-2781150.2.gz
+ test -s /build/shepherd-1.0.5/t-service-log1-2781150
+ herd -s t-socket-2781150 trigger log-rotation
Triggering timer.
+ zgrep 'Deleting .*/build/shepherd-1.0.5/t-service-log1-2781150.2.gz' t-log-2781150 t-log-2781150.1.gz t-log-2781150.2.gz
t-log-2781150:2025-07-06 20:02:59 Deleting old log file '/build/shepherd-1.0.5/t-service-log1-2781150.2.gz'.
Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.1.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-2781150.3.gz
++ file_descriptor_count
++ ls -l /proc/2781604/fd/
total 0
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 0 -> /dev/null
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 1 -> /build/shepherd-1.0.5/tests/services/log-rotation.log
lrwx------ 1 pbuilder pbuilder 64 Jul  6 20:02 10 -> anon_inode:[signalfd]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 11 -> pipe:[143612]
lrwx------ 1 pbuilder pbuilder 64 Jul  6 20:02 12 -> anon_inode:[eventpoll]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 13 -> /build/shepherd-1.0.5/t-log-2781150
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 14 -> /build/shepherd-1.0.5/t-service-log1-2781150
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 15 -> pipe:[144392]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 16 -> pipe:[141921]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 17 -> /build/shepherd-1.0.5/t-service-log2-2781150
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 19 -> pipe:[105208]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 2 -> /build/shepherd-1.0.5/tests/services/log-rotation.log
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 3 -> pipe:[139831]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 4 -> pipe:[139831]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 5 -> /build/shepherd-1.0.5/shepherd
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 6 -> pipe:[143610]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 7 -> pipe:[143610]
lrwx------ 1 pbuilder pbuilder 64 Jul  6 20:02 8 -> socket:[143611]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 9 -> pipe:[143612]
++ ls -l /proc/2781604/fd/0 /proc/2781604/fd/1 /proc/2781604/fd/10 /proc/2781604/fd/11 /proc/2781604/fd/12 /proc/2781604/fd/13 /proc/2781604/fd/14 /proc/2781604/fd/15 /proc/2781604/fd/16 /proc/2781604/fd/17 /proc/2781604/fd/19 /proc/2781604/fd/2 /proc/2781604/fd/3 /proc/2781604/fd/4 /proc/2781604/fd/5 /proc/2781604/fd/6 /proc/2781604/fd/7 /proc/2781604/fd/8 /proc/2781604/fd/9
++ wc -l
+ initial_fd_count=19
+ herd -s t-socket-2781150 start three
Service three has been started.
+ herd -s t-socket-2781150 trigger three
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-2781150
+ herd -s t-socket-2781150 status three
+ grep 'Child process'
+ herd -s t-socket-2781150 status three
+ grep 'Timer triggered from /build/shepherd-1.0.5'
  2025-07-06 20:02:59 Timer triggered from /build/shepherd-1.0.5.
+ herd -s t-socket-2781150 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log3-2781150
/build/shepherd-1.0.5/t-service-log3-2781150	three
+ herd -s t-socket-2781150 trigger log-rotation
Rotating '/build/shepherd-1.0.5/t-service-log3-2781150' to '/build/shepherd-1.0.5/t-service-log3-2781150.1'.
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-2781150.1.gz
+ sleep 0.2
Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
+ test -f /build/shepherd-1.0.5/t-service-log3-2781150.1.gz
+ herd -s t-socket-2781150 status three
Status of three:
  It is running since 20:02:59 (0 seconds ago).
  Timed service.
  Periodically running: sh -c "echo Timer triggered from $PWD."
  It is enabled.
  Provides: three
  Custom action: trigger
  Will not be respawned.
  Log file: /build/shepherd-1.0.5/t-service-log3-2781150

Recent runs:
  2025-07-06 20:02:59 Process exited successfully after 0 seconds.

Recent messages (use '-n' to view more or less):
  2025-07-06 20:02:59 Timer triggered from /build/shepherd-1.0.5.

Upcoming timer alarms:
  Tue Jan  6 20:03:00 2026 (in 184 days)
  Tue Jan  6 20:04:00 2026 (in 184 days)
  Tue Jan  6 20:05:00 2026 (in 184 days)
  Tue Jan  6 20:06:00 2026 (in 184 days)
  Tue Jan  6 20:07:00 2026 (in 184 days)
+ herd -s t-socket-2781150 status three
+ grep 'Timer triggered from /build/shepherd-1.0.5'
  2025-07-06 20:02:59 Timer triggered from /build/shepherd-1.0.5.
+ herd -s t-socket-2781150 trigger three
Triggering timer.
+ herd -s t-socket-2781150 trigger log-rotation
Rotating '/build/shepherd-1.0.5/t-service-log3-2781150' to '/build/shepherd-1.0.5/t-service-log3-2781150.1'.
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-2781150.2.gz
+ herd -s t-socket-2781150 status three
Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
Status of three:
  It is running since 20:02:59 (1 second ago).
  Timed service.
  Periodically running: sh -c "echo Timer triggered from $PWD."
  It is enabled.
  Provides: three
  Custom action: trigger
  Will not be respawned.
  Log file: /build/shepherd-1.0.5/t-service-log3-2781150

Recent runs:
  2025-07-06 20:02:59 Process exited successfully after 0 seconds.
  2025-07-06 20:03:00 Process exited successfully after 0 seconds.

Recent messages (use '-n' to view more or less):
  2025-07-06 20:03:00 Timer triggered from /build/shepherd-1.0.5.

Upcoming timer alarms:
  Tue Jan  6 20:04:00 2026 (in 184 days)
  Tue Jan  6 20:05:00 2026 (in 184 days)
  Tue Jan  6 20:06:00 2026 (in 184 days)
  Tue Jan  6 20:07:00 2026 (in 184 days)
  Tue Jan  6 20:08:00 2026 (in 184 days)
+ herd -s t-socket-2781150 stop three
++ file_descriptor_count
++ ls -l /proc/2781604/fd/
total 0
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 0 -> /dev/null
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 1 -> /build/shepherd-1.0.5/tests/services/log-rotation.log
lrwx------ 1 pbuilder pbuilder 64 Jul  6 20:02 10 -> anon_inode:[signalfd]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 11 -> pipe:[143612]
lrwx------ 1 pbuilder pbuilder 64 Jul  6 20:02 12 -> anon_inode:[eventpoll]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 13 -> /build/shepherd-1.0.5/t-log-2781150
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 14 -> /build/shepherd-1.0.5/t-service-log1-2781150
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 16 -> pipe:[141921]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 17 -> /build/shepherd-1.0.5/t-service-log2-2781150
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:03 18 -> pipe:[139900]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 19 -> pipe:[105208]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 2 -> /build/shepherd-1.0.5/tests/services/log-rotation.log
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:03 20 -> pipe:[139900]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:03 21 -> pipe:[124124]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:03 22 -> pipe:[124124]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 3 -> pipe:[139831]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 4 -> pipe:[139831]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 5 -> /build/shepherd-1.0.5/shepherd
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 6 -> pipe:[143610]
l-wx------ 1 pbuilder pbuilder 64 Jul  6 20:02 7 -> pipe:[143610]
lrwx------ 1 pbuilder pbuilder 64 Jul  6 20:02 8 -> socket:[143611]
lr-x------ 1 pbuilder pbuilder 64 Jul  6 20:02 9 -> pipe:[143612]
++ ls -l /proc/2781604/fd/0 /proc/2781604/fd/1 /proc/2781604/fd/10 /proc/2781604/fd/11 /proc/2781604/fd/12 /proc/2781604/fd/13 /proc/2781604/fd/14 /proc/2781604/fd/16 /proc/2781604/fd/17 /proc/2781604/fd/18 /proc/2781604/fd/19 /proc/2781604/fd/2 /proc/2781604/fd/20 /proc/2781604/fd/21 /proc/2781604/fd/22 /proc/2781604/fd/3 /proc/2781604/fd/4 /proc/2781604/fd/5 /proc/2781604/fd/6 /proc/2781604/fd/7 /proc/2781604/fd/8 /proc/2781604/fd/9
++ wc -l
+ test 22 -le 19
+ zcat t-log-2781150.1.gz t-log-2781150.2.gz t-log-2781150.3.gz t-log-2781150.4.gz t-log-2781150.5.gz
2025-07-06 20:02:59 Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
2025-07-06 20:02:59 Registering new logger for log-rotation.
2025-07-06 20:02:59 Rotated '/build/shepherd-1.0.5/t-log-2781150'.
2025-07-06 20:02:59 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-2781150', which is not a regular file.
2025-07-06 20:02:59 Not rotating '/build/shepherd-1.0.5/t-service-extlog-2781150', which is below the 0 B threshold.
2025-07-06 20:03:00 Triggering timer.
2025-07-06 20:03:00 Timer 'three' spawned process 2801243.
2025-07-06 20:03:00 Registering new logger for three.
2025-07-06 20:03:00 Process 2801243 of timer 'three' terminated with status 0 after 0 seconds.
2025-07-06 20:03:00 Triggering timer.
2025-07-06 20:03:00 Rotating '/build/shepherd-1.0.5/t-service-log3-2781150' to '/build/shepherd-1.0.5/t-service-log3-2781150.1'.
2025-07-06 20:03:00 Registering new logger for log-rotation.
2025-07-06 20:03:00 Rotated '/build/shepherd-1.0.5/t-service-log3-2781150'.
2025-07-06 20:03:00 Not rotating '/build/shepherd-1.0.5/t-service-log2-2781150', which is below the 0 B threshold.
2025-07-06 20:03:00 Rotating '/build/shepherd-1.0.5/t-service-log1-2781150' to '/build/shepherd-1.0.5/t-service-log1-2781150.1'.
2025-07-06 20:03:00 Registering new logger for log-rotation.
2025-07-06 20:03:00 Rotated '/build/shepherd-1.0.5/t-service-log1-2781150'.

2025-07-06 20:03:00 Rotating log.
2025-07-06 20:02:59 Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
2025-07-06 20:02:59 Registering new logger for log-rotation.
2025-07-06 20:02:59 Rotated '/build/shepherd-1.0.5/t-log-2781150'.
2025-07-06 20:02:59 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-2781150', which is not a regular file.
2025-07-06 20:02:59 Not rotating '/build/shepherd-1.0.5/t-service-extlog-2781150', which is below the 0 B threshold.
2025-07-06 20:02:59 Starting service three...
2025-07-06 20:02:59 Service three has been started.
2025-07-06 20:02:59 Service three started.
2025-07-06 20:02:59 Service three running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (1) days-of-week: (0 1 2 3 4 5 6)> #<<command> arguments: ("sh" "-c" "echo Tim
2025-07-06 20:02:59 er triggered from $PWD.") user: #f group: #f supplementary-groups: () environment-variables: ("SHELL=/bin/bash" "SESSION_MANAGER=local/kaka:@/tmp/.ICE-unix/2302,unix/kaka:/tmp/.ICE-unix/2302" "QT_ACCESSIBILITY=1" "COLORTERM=truecolor" "DEB_HOST_ARCH_LIBC=gnu" "XDG_CONFIG_DIRS=/home/jas/.guix-home/profile/etc/xdg:/etc/xdg/xdg-gnome:/etc/xdg" "SSH_AGENT_LAUNCHER=gnome-keyring" "SUDO_GID=1000" "XDG_MENU_PREFIX=gnome-" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_POOL_GIT_TOKEN=glpat-KhpzkNzu1Lt5kxoRR7Y4" "DISTS_PUR
2025-07-06 20:02:59 EOS=/home/jas/src/dists/pureos" "GNOME_DESKTOP_SESSION_ID=this-is-deprecated" "DEB_TARGET_GNU_SYSTEM=linux-gnu" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_POOL_TRIGGER_TOKEN=glptt-1f76b69c2323931b05be6dabce858360b13d7487" "DPKG_ADMINDIR=/var/lib/dpkg" "PKG_CONFIG_PATH=/home/jas/.guix-profile/lib/pkgconfig:/home/jas/.guix-profile/share/pkgconfig:/home/jas/.guix-profile/lib/pkgconfig:/home/jas/.guix-profile/share/pkgconfig" "DEB_HOST_MULTIARCH=x86_64-linux-gnu" "CPPFLAGS_FOR_BUILD=-Wdate-time -D_FORTIFY_SOURCE=2
2025-07-06 20:02:59 " "OBJCXXFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "LDFLAGS_FOR_BUILD=-Wl,-z,relro -Wl,-z,now" "DEB_TARGET_ARCH_CPU=amd64" "DDU_BUILD_DEBIAN_TRIXIE_ARM64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-99b6eac82b98e014608e3020957fa23028403252" "SSH_AUTH_SOCK=/run/user/1000/gnupg/S.gpg-agent.ssh" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_GIT_TOKEN=glpat-HzLL_JrxeDWiTu4rzvy4" "XDG_DATA_HOME=/home/jas/.
2025-07-06 20:02:59 local/share" "GBP_PBUILDER_DIST=debian_latest" "DH_INTERNAL_OVERRIDE=dh_auto_test" "DDU_BUILD_DEBIAN_BOOKWORM_ARM64_STAGE0_PIPELINE_PROJECT=69100903" "PBUILDER_PKGLIBDIR=/usr/lib/pbuilder" "COWDANCER_REUSE=yes" "TEST_LOGS=tests/services/log-rotation.log" "XCURSOR_PATH=/home/jas/.guix-home/profile/share/icons:" "DEBFULLNAME=Simon Josefsson" "SUDO_COMMAND=/usr/sbin/cowbuilder --build --buildresult /home/jas/dpkg --debbuildopts  --debbuildopts  --source-only-changes --basepath /var/cache/pbuilder/base-debian_l
2025-07-06 20:02:59 atest.cow ../shepherd_1.0.5-1.dsc" "XMODIFIERS=@im=ibus" "DESKTOP_SESSION=gnome" "SUDO_USER=jas" "DEB_TARGET_ARCH_BITS=64" "EDITOR=nano" "FFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -fcf-protection" "PBUILDER_SYSCONFDIR=/etc" "DISTS_GNUINOS=/home/jas/src/dists/gnuinos" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-e3369473d1e749f15bd6ed9078f133ad13ea5737" "GTK_MODULES=gail:atk-bridge" "PWD=/build/shepherd-1.0.5" "DEB_BUILD_
2025-07-06 20:02:59 MULTIARCH=x86_64-linux-gnu" "SOURCE_DATE_EPOCH=1751527360" "LOGNAME=pbuilder" "XDG_SESSION_DESKTOP=gnome" "XDG_SESSION_TYPE=wayland" "DEB_HOST_GNU_SYSTEM=linux-gnu" "CCACHE_DIR=/var/cache/pbuilder/ccache" "DEB_RULES_REQUIRES_ROOT=no" "CFLAGS_FOR_BUILD=-g -O2 -Werror=implicit-function-declaration -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "MANPATH=/home/jas/.guix-home/profile/share/man:" "DEB_BUILD_ARCH_BITS=64
2025-07-06 20:02:59 " "SYSTEMD_EXEC_PID=2327" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_BUILD_PIPELINE_TRIGGER_TOKEN=glptt-c0716a7cd5d7e0f64d2a4aaa175be73629c04870" "GUILE_LOAD_PATH=/build/shepherd-1.0.5/modules:/build/shepherd-1.0.5/modules:" "CXXFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "DEB_BUILD_ARCH_OS=linux" "XAUTHORITY=/run/user/1000/.mutter-Xwaylandauth.XKD682" "DISTS_DEVUAN=/home/jas/src/dists/devuan" "DDU_BU
2025-07-06 20:02:59 ILD_DEBIAN_TRIXIE_AMD64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-afb3c982190007b086a8627a95f87bc2301a43dd" "ASFLAGS_FOR_BUILD=" "LD_PRELOAD=" "DDU_BUILD_DEBIAN_TRIXIE_AMD64_STAGE0_PIPELINE_PROJECT=69108031" "DDU_ARCHIVES_DEBIAN_STAGE0_BOOKWORM_AMD64_TRIGGER_TOKEN=glptt-603e27e96c6c5e9bc914092c87d2f67683844310" "GIT_EXEC_PATH=/home/jas/.guix-home/profile/libexec/git-core" "LDFLAGS=-Wl,-z,relro -Wl,-z,now" "DDU_BUILD_DEBIAN_BOOKWORM_AMD64_STAGE0_PIPELINE_PROJECT=69099423" "HOME=/nonexistent" "USERNAME=jas" "COWDAN
2025-07-06 20:02:59 CER_ILISTFILE=/.ilist" "IM_CONFIG_PHASE=1" "DDU_BUILD_DEBIAN_BOOKWORM_ARM64_STAGE0_PIPELINE_TRIGGER_TOKEN=glptt-8f7a7e2e95acbf781a1af27682b77039dc83a162" "GIT_SSL_CAINFO=/home/jas/.guix-profile/etc/ssl/certs/ca-certificates.crt" "LANG=C" "DEB_HOST_ARCH_ABI=base" "LS_COLORS=rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=00:su=37;41:sg=30;43:ca=00:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01
2025-07-06 20:02:59 ;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.zst=01;31:*.tzst=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.wim=01;31:*.swm=01;31:*.dwm=01;31:*.esd=01;31:*.avif=01;35:*.jpg=01;35:*.jpeg=01;35:*.mjpg=0
2025-07-06 20:02:59 1;35:*.mjpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.webp=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;3
2025-07-06 20:02:59 5:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.m4a=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.oga=00;36:*.opus=00;36:*.spx=00;36:*.xspf=00;36:*~=00;90:*#=00;90:*.bak=00;90:*.old=00;90:*.orig=00;90:*.part=00;90:*.rej=00;90:*.swp=00;90:*.tmp=00;90:*.dpkg-dist=00;90:*.dpkg-old=00;90:*.ucf-dist=00;90:*.ucf-new=00;90:*.ucf-old=00;90:*.rpmnew=00;90:*.rpmorig=00;90:*.rpmsave=00;90:" "XDG_CURRENT_DESKTO
2025-07-06 20:02:59 P=GNOME" "srcdir=." "VTE_VERSION=6800" "GIT_PBUILDER_OPTIONS=--source-only-changes" "DEB_TARGET_ARCH_LIBC=gnu" "DEB_TARGET_GNU_TYPE=x86_64-linux-gnu" "WAYLAND_DISPLAY=wayland-0" "SSL_CERT_DIR=/home/jas/.guix-profile/etc/ssl/certs" "BUILDRESULTGID=1000" "DEB_TARGET_ARCH_ABI=base" "DEBEMAIL=simon <at> josefsson.org" "DDU_BUILD_TRIXIE_AMD64_TRIGGER_TOKEN=glptt-2a3e7330e1058e0277bd9059ca81a4e345d4b0c5" "GNOME_TERMINAL_SCREEN=/org/gnome/Terminal/screen/362e78af_0476_4b94_a421_1f9b387c96e6" "CPPFLAGS=-Wdate-time -D_FO
2025-07-06 20:02:59 RTIFY_SOURCE=2" "OBJCFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "DDU_BUILD_SCRATCH_ACCESS_TOKEN=glpat-1Xa2gjzbxdcGb_2WWiaS" "GUILE_LOAD_COMPILED_PATH=/build/shepherd-1.0.5/modules:/build/shepherd-1.0.5/modules:" "DEB_TARGET_ARCH=amd64" "DEB_BUILD_ARCH=amd64" "GUILE=/usr/bin/guile-3.0" "DOTNET_BUNDLE_EXTRACT_BASE_DIR=/home/jas/.cache/dotnet_bundle_extract" "PBCURRENTCOMMANDLINEOPERATION=b
2025-07-06 20:02:59 uild" "PBUILDER_PKGDATADIR=/usr/share/pbuilder" "DEB_TARGET_ARCH_OS=linux" "MFLAGS=" "XDG_CACHE_HOME=/home/jas/.cache" "PBUILDER_OPERATION=build" "INFOPATH=/home/jas/.guix-home/profile/share/info:/home/jas/.guix-profile/share/info:/home/jas/.guix-profile/share/info:/home/jas/.config/guix/current/share/info:" "GNOME_SETUP_DISPLAY=:1" "DDU_BUILD_BOOKWORM_ARM64_TRIGGER_TOKEN=glptt-56595017909976c40a98bdc789a725e6a6c3e11f" "FCFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstac
2025-07-06 20:02:59 k-clash-protection -fcf-protection" "XDG_SESSION_CLASS=user" "MAKEFLAGS= -- TEST_LOGS=tests/services/log-rotation.log VERBOSE=1 TESTS=tests/services/log-rotation.sh" "TERM=xterm-256color" "DEB_TARGET_MULTIARCH=x86_64-linux-gnu" "FCFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -fcf-protection" "DEB_BUILD_ARCH_CPU=amd64" "DEB_BUILD_ARCH_LIBC=gnu" "OBJCFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-cla
2025-07-06 20:02:59 sh-protection -Wformat -Werror=format-security -fcf-protection" "ACLOCAL_PATH=/home/jas/.guix-profile/share/aclocal:/home/jas/.guix-profile/share/aclocal" "LIBVIRT_DEFAULT_URI=qemu:///system" "USER=pbuilder" "GBP_BUILD_DIR=/home/jas/dpkg/shepherd" "CURL_CA_BUNDLE=/home/jas/.guix-profile/etc/ssl/certs/ca-certificates.crt" "DEB_HOST_ARCH_BITS=64" "GNOME_TERMINAL_SERVICE=:1.91" "FFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -fcf-protection" 
2025-07-06 20:02:59 "DEB_BUILD_GNU_TYPE=x86_64-linux-gnu" "CXXFLAGS_FOR_BUILD=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "DEB_BUILD_OPTIONS=parallel=16" "SHLVL=7" "GUIX_LOCPATH=/home/jas/.guix-home/profile/lib/locale:/home/jas/.guix-profile/lib/locale" "MAKELEVEL=7" "DEB_BUILD_GNU_SYSTEM=linux-gnu" "DH_INTERNAL_OPTIONS=" "QT_IM_MODULE=ibus" "LC_MESSAGES=C" "DFLAGS_FOR_BUILD=-frelease" "DEB_BUILD_MAINT_OPTIONS=hardening=+bi
2025-07-06 20:02:59 ndnow" "DEB_TARGET_GNU_CPU=x86_64" "BUILDRESULTUID=1000" "DEB_TARGET_ARCH_ENDIAN=little" "DEB_HOST_ARCH=amd64" "XDG_STATE_HOME=/home/jas/.local/state" "GUIX_PROFILE=/home/jas/.guix-profile" "DDU_BUILD_DEBIAN_BOOKWORM_ARM64_STAGE0_GIT_TOKEN=glpat-X5P7zy3H9u7QPXesxJSh" "DEB_HOST_ARCH_ENDIAN=little" "XDG_RUNTIME_DIR=/run/user/1000" "SSL_CERT_FILE=/home/jas/.guix-profile/etc/ssl/certs/ca-certificates.crt" "DEB_HOST_GNU_TYPE=x86_64-linux-gnu" "DDU_BUILD_DEBIAN_TRIXIE_ARM64_STAGE0_PIPELINE_PROJECT=69108209" "LC_A
2025-07-06 20:02:59 LL=C" "DISTS_DEBIAN=/home/jas/src/dists/debian" "DISTS_UBUNTU=/home/jas/src/dists/ubuntu" "XDG_DATA_DIRS=/home/jas/.guix-home/profile/share:/home/jas/.guix-profile/share:/usr/share/gnome:/usr/local/share/:/usr/share/" "ICECAT_SYSTEM_DIR=/home/jas/.guix-home/profile/lib/icecat" "CONFIG_SITE=/home/jas/moln/dot-files/config.site" "PATH=/build/shepherd-1.0.5:/usr/lib/ccache:/usr/sbin:/usr/bin:/sbin:/bin" "DEB_BUILD_ARCH_ENDIAN=little" "DEB_HOST_ARCH_CPU=amd64" "DDU_ARCHIVES_DEBIAN_STAGE0_BOOKWORM_AMD64_GIT_TOKE
2025-07-06 20:02:59 N=glpat-xtGhb85bTtLgXqHyohEB" "CC=gcc" "GDMSESSION=gnome" "TESTS=tests/services/log-rotation.sh" "CFLAGS=-g -O2 -Werror=implicit-function-declaration -ffile-prefix-map=/build/shepherd-1.0.5=. -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "SUDO_UID=1000" "DBUS_SESSION_BUS_ADDRESS=unix:path=/run/user/1000/bus" "DDU_BUILD_BOOKWORM_AMD64_TRIGGER_TOKEN=glptt-4d6dfa0a133b0d35bb3b7640b6d48f554bd3b868" "OBJCXXFLAGS=-g -O2 -ffile-prefix-map=/build/shepherd-1.0.5=
2025-07-06 20:02:59 . -fstack-protector-strong -fstack-clash-protection -Wformat -Werror=format-security -fcf-protection" "PASSWORD_STORE_DIR=/home/jas/moln/password-store/" "EMACSLOADPATH=/home/jas/.guix-profile/share/emacs/site-lisp:/home/jas/.guix-profile/share/emacs/site-lisp" "GBP_PBUILDER_OPTIONS=--source-only-changes" "DFLAGS=-frelease" "DISTS_TRISQUEL=/home/jas/src/dists/trisquel" "DEB_HOST_GNU_CPU=x86_64" "DEB_HOST_ARCH_OS=linux" "DEB_BUILD_GNU_CPU=x86_64" "DEBIAN_FRONTEND=noninteractive" "DEB_BUILD_ARCH_ABI=base" "DH
2025-07-06 20:02:59 _INTERNAL_BUILDFLAGS=1" "OLDPWD=/" "VERBOSE=1" "ASFLAGS=" "_=/build/shepherd-1.0.5/shepherd") directory: "/build/shepherd-1.0.5" resource-limits: ()> 7f23948ff0c0>.
2025-07-06 20:02:59 Triggering timer.
2025-07-06 20:02:59 Timer 'three' spawned process 2797970.
2025-07-06 20:02:59 Process 2797970 of timer 'three' terminated with status 0 after 0 seconds.
2025-07-06 20:02:59 /build/shepherd-1.0.5/t-service-log3-2781150	three
2025-07-06 20:02:59 /build/shepherd-1.0.5/t-service-log2-2781150	two
2025-07-06 20:02:59 /build/shepherd-1.0.5/t-service-log1-2781150	one
2025-07-06 20:02:59 /build/shepherd-1.0.5/t-log-2781150	root
2025-07-06 20:02:59 /build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
2025-07-06 20:02:59 /build/shepherd-1.0.5/t-service-extlog-2781150	(external)
2025-07-06 20:02:59 Triggering timer.
2025-07-06 20:02:59 Rotating '/build/shepherd-1.0.5/t-service-log3-2781150' to '/build/shepherd-1.0.5/t-service-log3-2781150.1'.
2025-07-06 20:02:59 Registering new logger for log-rotation.
2025-07-06 20:02:59 Rotated '/build/shepherd-1.0.5/t-service-log3-2781150'.
2025-07-06 20:02:59 Not rotating '/build/shepherd-1.0.5/t-service-log2-2781150', which is below the 0 B threshold.
2025-07-06 20:02:59 Rotating '/build/shepherd-1.0.5/t-service-log1-2781150' to '/build/shepherd-1.0.5/t-service-log1-2781150.1'.
2025-07-06 20:02:59 Registering new logger for log-rotation.
2025-07-06 20:02:59 Rotated '/build/shepherd-1.0.5/t-service-log1-2781150'.

2025-07-06 20:02:59 Rotating log.
2025-07-06 20:02:58 Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
2025-07-06 20:02:58 Registering new logger for log-rotation.
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-log-2781150'.
2025-07-06 20:02:58 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-2781150', which is not a regular file.
2025-07-06 20:02:58 Not rotating '/build/shepherd-1.0.5/t-service-extlog-2781150', which is below the 0 B threshold.
2025-07-06 20:02:59 Triggering timer.
2025-07-06 20:02:59 Not rotating '/build/shepherd-1.0.5/t-service-log2-2781150', which is below the 0 B threshold.
2025-07-06 20:02:59 Deleting old log file '/build/shepherd-1.0.5/t-service-log1-2781150.2.gz'.
2025-07-06 20:02:59 Rotating '/build/shepherd-1.0.5/t-service-log1-2781150' to '/build/shepherd-1.0.5/t-service-log1-2781150.1'.
2025-07-06 20:02:59 Registering new logger for log-rotation.
2025-07-06 20:02:59 Rotated '/build/shepherd-1.0.5/t-service-log1-2781150'.

2025-07-06 20:02:59 Rotating log.
2025-07-06 20:02:58 Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
2025-07-06 20:02:58 Registering new logger for log-rotation.
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-log-2781150'.
2025-07-06 20:02:58 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-2781150', which is not a regular file.
2025-07-06 20:02:58 Registering new logger for log-rotation.
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-service-extlog-2781150'.
2025-07-06 20:02:58 Triggering timer.
2025-07-06 20:02:58 Not rotating '/build/shepherd-1.0.5/t-service-log2-2781150', which is below the 0 B threshold.
2025-07-06 20:02:58 Rotating '/build/shepherd-1.0.5/t-service-log1-2781150' to '/build/shepherd-1.0.5/t-service-log1-2781150.1'.
2025-07-06 20:02:58 Registering new logger for log-rotation.
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-service-log1-2781150'.

2025-07-06 20:02:58 Rotating log.
2025-07-06 20:02:57 GNU Shepherd 1.0.5 (Guile 3.0.10, x86_64-pc-linux-gnu)
2025-07-06 20:02:57 Starting service root...
2025-07-06 20:02:57 Service root started.
2025-07-06 20:02:57 Service root running with value #<<process> id: 2781604 command: #f>.
2025-07-06 20:02:57 Service root has been started.
2025-07-06 20:02:57 Configuration successfully loaded from 't-conf-2781150'.
2025-07-06 20:02:57 Starting service one...
2025-07-06 20:02:57 Service one has been started.
2025-07-06 20:02:57 Service one started.
2025-07-06 20:02:57 Service one running with value #<<process> id: 2784212 command: ("/bin/bash" "-c" "while true; do echo logging things; sleep 0.2; done")>.
2025-07-06 20:02:57 Starting service two...
2025-07-06 20:02:57 Service two has been started.
2025-07-06 20:02:57 Service two started.
2025-07-06 20:02:57 Service two running with value #<<process> id: 2784406 command: ("sleep" "600")>.
2025-07-06 20:02:57 Starting service log-rotation...
2025-07-06 20:02:57 Service log-rotation started.
2025-07-06 20:02:57 Service log-rotation running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (6) days-of-week: (0 1 2 3 4 5 6)> #<procedure rotation ()> 7f239d58dea
2025-07-06 20:02:57 0>.
2025-07-06 20:02:57 Service log-rotation has been started.
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log2-2781150	two
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log1-2781150	one
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-log-2781150	root
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log2-2781150	two
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log1-2781150	one
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-log-2781150	root
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log2-2781150	two
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log1-2781150	one
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-log-2781150	root
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log2-2781150	two
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log1-2781150	one
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-log-2781150	root
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log2-2781150	two
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-log1-2781150	one
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-log-2781150	root
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-invalid-extlog-2781150	(external)
2025-07-06 20:02:58 /build/shepherd-1.0.5/t-service-extlog-2781150	(external)
2025-07-06 20:02:58 Triggering timer.
2025-07-06 20:02:58 Not rotating '/build/shepherd-1.0.5/t-service-log2-2781150', which is below the 0 B threshold.
2025-07-06 20:02:58 Rotating '/build/shepherd-1.0.5/t-service-log1-2781150' to '/build/shepherd-1.0.5/t-service-log1-2781150.1'.
2025-07-06 20:02:58 Rotated '/build/shepherd-1.0.5/t-service-log1-2781150'.

2025-07-06 20:02:58 Rotating log.
+ cat t-log-2781150
2025-07-06 20:03:00 Rotating '/build/shepherd-1.0.5/t-log-2781150' to '/build/shepherd-1.0.5/t-log-2781150.1'.
2025-07-06 20:03:00 Registering new logger for log-rotation.
2025-07-06 20:03:00 Rotated '/build/shepherd-1.0.5/t-log-2781150'.
2025-07-06 20:03:00 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-2781150', which is not a regular file.
2025-07-06 20:03:00 Not rotating '/build/shepherd-1.0.5/t-service-extlog-2781150', which is below the 0 B threshold.
2025-07-06 20:03:00 Stopping service three...
2025-07-06 20:03:00 Terminating timer 'three' with 0 processes running.
2025-07-06 20:03:00 Service three stopped.
2025-07-06 20:03:00 Service three is now stopped.
+ rm -f t-socket-2781150 t-conf-2781150 t-log-2781150 t-log-2781150.1.gz t-log-2781150.2.gz t-log-2781150.3.gz t-log-2781150.4.gz t-log-2781150.5.gz /build/shepherd-1.0.5/t-service-log1-2781150 /build/shepherd-1.0.5/t-service-log1-2781150.1.gz /build/shepherd-1.0.5/t-service-log1-2781150.2.gz /build/shepherd-1.0.5/t-service-log1-2781150.3.gz /build/shepherd-1.0.5/t-service-log1-2781150.4.gz /build/shepherd-1.0.5/t-service-log2-2781150 /build/shepherd-1.0.5/t-service-log3-2781150 /build/shepherd-1.0.5/t-service-log3-2781150.1.gz /build/shepherd-1.0.5/t-service-log3-2781150.2.gz /build/shepherd-1.0.5/t-service-extlog-2781150 /build/shepherd-1.0.5/t-service-extlog-2781150.1.gz
+ rmdir /build/shepherd-1.0.5/t-service-invalid-extlog-2781150
+ test -f t-pid-2781150
++ cat t-pid-2781150
+ kill 2781604
+ rm -f t-pid-2781150
Stopping service root...
Exiting shepherd...
FAIL tests/services/log-rotation.sh (exit status: 1)
Service three is not running.
Exiting.

[signature.asc (application/pgp-signature, inline)]

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

From: Simon Josefsson <simon <at> josefsson.org>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Sun, 06 Jul 2025 22:10:33 +0200

[Message part 1 (text/plain, inline)]

Ludovic Courtès <ludo <at> gnu.org> writes:

> Also, I wonder if the problem could be a race condition, which would be
> fixed like this:
>
> diff --git a/tests/services/log-rotation.sh b/tests/services/log-rotation.sh
> index 375f563..178bb49 100644
> --- a/tests/services/log-rotation.sh
> +++ b/tests/services/log-rotation.sh
> @@ -182,6 +182,6 @@ $herd trigger log-rotation
>  until test -f "$service_log3.2.gz"; do sleep 0.2; done
>  $herd status three
>  $herd stop three
> -test $(file_descriptor_count) -le $initial_fd_count
> +until test $(file_descriptor_count) -le $initial_fd_count; do sleep 0.3; done
>  
>  $herd stop log-rotation
>
>
> Could you also give that a try?

That just infloops and times out after 3 minutes...

/Simon

[Message part 2 (text/plain, inline)]

FAIL: tests/services/log-rotation
=================================

+ shepherd --version
shepherd (GNU Shepherd) 1.0.5
Copyright (C) 2025 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) 1.0.5
Copyright (C) 2025 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-147839
+ conf=t-conf-147839
+ log=t-log-147839
+ pid=t-pid-147839
+ service_log1=/build/shepherd-1.0.5/t-service-log1-147839
+ service_log2=/build/shepherd-1.0.5/t-service-log2-147839
+ service_log3=/build/shepherd-1.0.5/t-service-log3-147839
+ external_log=/build/shepherd-1.0.5/t-service-extlog-147839
+ invalid_external_log=/build/shepherd-1.0.5/t-service-invalid-extlog-147839
+ herd='herd -s t-socket-147839'
+ trap 'zcat t-log-147839.* || true; cat t-log-147839 || true;
      rm -f t-socket-147839 t-conf-147839 t-log-147839* /build/shepherd-1.0.5/t-service-log1-147839* /build/shepherd-1.0.5/t-service-log2-147839* /build/shepherd-1.0.5/t-service-log3-147839* /build/shepherd-1.0.5/t-service-extlog-147839*;
      rmdir /build/shepherd-1.0.5/t-service-invalid-extlog-147839;
      test -f t-pid-147839 && kill `cat t-pid-147839` || true; rm -f t-pid-147839' EXIT
+ cat
+ rm -f t-pid-147839
+ test -f t-pid-147839
+ sleep 0.3
+ shepherd -I -s t-socket-147839 -c t-conf-147839 -l t-log-147839 --pid=t-pid-147839
GNU Shepherd 1.0.5 (Guile 3.0.10, x86_64-pc-linux-gnu)
Starting service root...
Service root started.
Service root running with value #<<process> id: 148599 command: #f>.
Service root has been started.
Configuration successfully loaded from 't-conf-147839'.
+ test -f t-pid-147839
++ cat t-pid-147839
+ shepherd_pid=148599
+ herd -s t-socket-147839 start one
Starting service one...
Service one has been started.
+ herd -s t-socket-147839 start two
Starting service two...
Service two has been started.
+ herd -s t-socket-147839 start log-rotation
Starting service log-rotation...
Service log-rotation started.
Service log-rotation running with value #<timer #<<calendar-event> seconds: (0) minutes: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59) hours: (0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23) days-of-month: (1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31) months: (6) days-of-week: (0 1 2 3 4 5 6)> #<procedure rotation ()> 7fb8e5934dc0>.
Service log-rotation has been started.
+ sleep 0.5
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-147839 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log1-147839
/build/shepherd-1.0.5/t-service-log1-147839	one
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-147839 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log2-147839
/build/shepherd-1.0.5/t-service-log2-147839	two
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-147839 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-extlog-147839
/build/shepherd-1.0.5/t-service-extlog-147839	(external)
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ grep /build/shepherd-1.0.5/t-service-invalid-extlog-147839
+ herd -s t-socket-147839 files log-rotation
/build/shepherd-1.0.5/t-service-invalid-extlog-147839	(external)
+ for file in "$service_log1" "$service_log2" "$external_log" "$invalid_external_log" "$log"
+ herd -s t-socket-147839 files log-rotation
+ grep t-log-147839
/build/shepherd-1.0.5/t-log-147839	root
+ test -f /build/shepherd-1.0.5/t-service-log1-147839
+ test -f /build/shepherd-1.0.5/t-service-log2-147839
+ echo 'This is an external log file.'
+ mkdir /build/shepherd-1.0.5/t-service-invalid-extlog-147839
+ herd -s t-socket-147839 trigger log-rotation
Triggering timer.
+ grep 'Rotated ' t-log-147839
+ sleep 0.5
Rotating '/build/shepherd-1.0.5/t-log-147839' to '/build/shepherd-1.0.5/t-log-147839.1'.
+ grep 'Rotated ' t-log-147839
2025-07-06 20:06:31 Rotated '/build/shepherd-1.0.5/t-log-147839'.
2025-07-06 20:06:31 Rotated '/build/shepherd-1.0.5/t-service-extlog-147839'.
+ test -f /build/shepherd-1.0.5/t-service-log1-147839
+ test -f /build/shepherd-1.0.5/t-service-log2-147839
+ test -f t-log-147839
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.1.gz
+ test -f t-log-147839.1.gz
+ test -f /build/shepherd-1.0.5/t-service-log2-147839.1.gz
+ test -f /build/shepherd-1.0.5/t-service-extlog-147839.1.gz
+ gunzip
+ grep 'external log file'
This is an external log file.
+ test -f /build/shepherd-1.0.5/t-service-extlog-147839
+ guile -c '(exit (zero? (stat:size (stat "/build/shepherd-1.0.5/t-service-extlog-147839"))))'
+ zgrep 'Not rotating .*/build/shepherd-1.0.5/t-service-invalid-extlog-147839' t-log-147839 t-log-147839.1.gz
t-log-147839:2025-07-06 20:06:31 Not rotating '/build/shepherd-1.0.5/t-service-invalid-extlog-147839', which is not a regular file.
+ herd -s t-socket-147839 trigger log-rotation
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.1.gz
+ sleep 0.5
Rotating '/build/shepherd-1.0.5/t-log-147839' to '/build/shepherd-1.0.5/t-log-147839.1'.
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.1.gz
+ test -f t-log-147839.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-147839
+ test -f /build/shepherd-1.0.5/t-service-log2-147839.1.gz
+ touch -d 2017-10-01 /build/shepherd-1.0.5/t-service-log1-147839.2.gz
+ test -s /build/shepherd-1.0.5/t-service-log1-147839
+ herd -s t-socket-147839 trigger log-rotation
Triggering timer.
+ zgrep 'Deleting .*/build/shepherd-1.0.5/t-service-log1-147839.2.gz' t-log-147839 t-log-147839.1.gz t-log-147839.2.gz
t-log-147839:2025-07-06 20:06:32 Deleting old log file '/build/shepherd-1.0.5/t-service-log1-147839.2.gz'.
Rotating '/build/shepherd-1.0.5/t-log-147839' to '/build/shepherd-1.0.5/t-log-147839.1'.
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.2.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.1.gz
+ test -f /build/shepherd-1.0.5/t-service-log1-147839.3.gz
++ file_descriptor_count
++ wc -l
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/15 /proc/148599/fd/16 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
+ initial_fd_count=19
+ herd -s t-socket-147839 start three
Service three has been started.
+ herd -s t-socket-147839 trigger three
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-147839
+ herd -s t-socket-147839 status three
+ grep 'Child process'
+ herd -s t-socket-147839 status three
+ grep 'Timer triggered from /build/shepherd-1.0.5'
  2025-07-06 20:06:32 Timer triggered from /build/shepherd-1.0.5.
+ herd -s t-socket-147839 files log-rotation
+ grep /build/shepherd-1.0.5/t-service-log3-147839
/build/shepherd-1.0.5/t-service-log3-147839	three
+ herd -s t-socket-147839 trigger log-rotation
Rotating '/build/shepherd-1.0.5/t-service-log3-147839' to '/build/shepherd-1.0.5/t-service-log3-147839.1'.
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-147839.1.gz
+ sleep 0.2
Rotating '/build/shepherd-1.0.5/t-log-147839' to '/build/shepherd-1.0.5/t-log-147839.1'.
+ test -f /build/shepherd-1.0.5/t-service-log3-147839.1.gz
+ herd -s t-socket-147839 status three
Status of three:
  It is running since 20:06:32 (0 seconds ago).
  Timed service.
  Periodically running: sh -c "echo Timer triggered from $PWD."
  It is enabled.
  Provides: three
  Custom action: trigger
  Will not be respawned.
  Log file: /build/shepherd-1.0.5/t-service-log3-147839

Recent runs:
  2025-07-06 20:06:32 Process exited successfully after 0 seconds.

Recent messages (use '-n' to view more or less):
  2025-07-06 20:06:32 Timer triggered from /build/shepherd-1.0.5.

Upcoming timer alarms:
  Tue Jan  6 20:07:00 2026 (in 184 days)
  Tue Jan  6 20:08:00 2026 (in 184 days)
  Tue Jan  6 20:09:00 2026 (in 184 days)
  Tue Jan  6 20:10:00 2026 (in 184 days)
  Tue Jan  6 20:11:00 2026 (in 184 days)
+ herd -s t-socket-147839 status three
+ grep 'Timer triggered from /build/shepherd-1.0.5'
  2025-07-06 20:06:32 Timer triggered from /build/shepherd-1.0.5.
+ herd -s t-socket-147839 trigger three
Triggering timer.
+ herd -s t-socket-147839 trigger log-rotation
Rotating '/build/shepherd-1.0.5/t-service-log3-147839' to '/build/shepherd-1.0.5/t-service-log3-147839.1'.
Triggering timer.
+ test -f /build/shepherd-1.0.5/t-service-log3-147839.2.gz
+ herd -s t-socket-147839 status three
Rotating '/build/shepherd-1.0.5/t-log-147839' to '/build/shepherd-1.0.5/t-log-147839.1'.
Status of three:
  It is running since 20:06:32 (1 second ago).
  Timed service.
  Periodically running: sh -c "echo Timer triggered from $PWD."
  It is enabled.
  Provides: three
  Custom action: trigger
  Will not be respawned.
  Log file: /build/shepherd-1.0.5/t-service-log3-147839

Recent runs:
  2025-07-06 20:06:32 Process exited successfully after 0 seconds.
  2025-07-06 20:06:33 Process exited successfully after 0 seconds.

Recent messages (use '-n' to view more or less):
  2025-07-06 20:06:33 Timer triggered from /build/shepherd-1.0.5.

Upcoming timer alarms:
  Tue Jan  6 20:07:00 2026 (in 184 days)
  Tue Jan  6 20:08:00 2026 (in 184 days)
  Tue Jan  6 20:09:00 2026 (in 184 days)
  Tue Jan  6 20:10:00 2026 (in 184 days)
  Tue Jan  6 20:11:00 2026 (in 184 days)
+ herd -s t-socket-147839 stop three
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ wc -l
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ wc -l
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ wc -l
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
++ file_descriptor_count
++ ls -l /proc/148599/fd/0 /proc/148599/fd/1 /proc/148599/fd/10 /proc/148599/fd/11 /proc/148599/fd/12 /proc/148599/fd/13 /proc/148599/fd/14 /proc/148599/fd/16 /proc/148599/fd/17 /proc/148599/fd/18 /proc/148599/fd/19 /proc/148599/fd/2 /proc/148599/fd/20 /proc/148599/fd/21 /proc/148599/fd/22 /proc/148599/fd/3 /proc/148599/fd/4 /proc/148599/fd/5 /proc/148599/fd/6 /proc/148599/fd/7 /proc/148599/fd/8 /proc/148599/fd/9
++ wc -l
+ test 22 -le 19
+ sleep 0.3
...

[signature.asc (application/pgp-signature, inline)]

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

From: Ludovic Courtès <ludo <at> gnu.org>
To: Simon Josefsson <simon <at> josefsson.org>
Cc: 77132 <at> debbugs.gnu.org
Subject: Re: Shepherd: flaky self tests
Date: Fri, 11 Jul 2025 11:51:35 +0200

Simon Josefsson <simon <at> josefsson.org> writes:

> Ludovic Courtès <ludo <at> gnu.org> writes:
>
>> Also, I wonder if the problem could be a race condition, which would be
>> fixed like this:
>>
>> diff --git a/tests/services/log-rotation.sh b/tests/services/log-rotation.sh
>> index 375f563..178bb49 100644
>> --- a/tests/services/log-rotation.sh
>> +++ b/tests/services/log-rotation.sh
>> @@ -182,6 +182,6 @@ $herd trigger log-rotation
>>  until test -f "$service_log3.2.gz"; do sleep 0.2; done
>>  $herd status three
>>  $herd stop three
>> -test $(file_descriptor_count) -le $initial_fd_count
>> +until test $(file_descriptor_count) -le $initial_fd_count; do sleep 0.3; done
>>  
>>  $herd stop log-rotation
>>
>>
>> Could you also give that a try?
>
> That just infloops and times out after 3 minutes...

So it’s not a timing issue…  The 3 extra file descriptors we see are
pipes, which may have been created by Fibers, but finding out why/where
they were created is going to be tedious; we’ll need at least an strace
of the ‘shepherd’ process to get some clues.

Thanks for testing this!

Ludo’.

Previous Next

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