package children
import (
"context"
"errors"
"fmt"
"strings"
"sync"
"testing"
"time"
)
type logBuf struct {
mu sync.Mutex
lines []string
}
func (l *logBuf) printf(format string, args ...any) {
l.mu.Lock()
defer l.mu.Unlock()
l.lines = append(l.lines, fmt.Sprintf(format, args...))
}
func (l *logBuf) find(parts ...string) (string, bool) {
l.mu.Lock()
defer l.mu.Unlock()
for _, line := range l.lines {
all := true
for _, p := range parts {
if !strings.Contains(line, p) {
all = false
break
}
}
if all {
return line, true
}
}
return "", false
}
// start runs a tracked child the way zitcli does: the set builds the
// command, the caller runs it, then calls done once it has been waited.
func start(t *testing.T, s *Set, repo, name string, args ...string) <-chan struct{} {
t.Helper()
cmd, done, err := s.Command(context.Background(), repo, name, name, args...)
if err != nil {
t.Fatal(err)
}
if err := cmd.Start(); err != nil {
t.Fatal(err)
}
finished := make(chan struct{})
go func() {
cmd.Wait()
done()
close(finished)
}()
return finished
}
// A stop waits for a child that is still running, and logs how it
// ended: which repository, which process, its exit and how long it ran.
func TestWaitHoldsForALiveChildAndLogsIt(t *testing.T) {
var lg logBuf
s := New(lg.printf)
finished := start(t, s, "demo", "sleep", "0.4")
s.Stopping()
began := time.Now()
left := s.Wait(5*time.Second, time.Second)
took := time.Since(began)
if left != 0 {
t.Fatalf("FAIL: %d children left", left)
}
select {
case <-finished:
default:
t.Fatal("FAIL: Wait returned before the child had ended")
}
if took < 300*time.Millisecond {
t.Fatalf("FAIL: Wait returned after %v with a child of 400ms", took)
}
t.Logf("ok: waited %v for the child", took.Round(time.Millisecond))
line, ok := lg.find("repo=demo", "verb=sleep", "pid=", "exit=exit status 0", "took=")
if !ok {
t.Fatalf("FAIL: no log of the child ending: %q", lg.lines)
}
t.Logf("ok: logged %q", line)
}
// A child that outlives the wait is asked to stop, and one that ignores
// that too is named in the log rather than silently left behind.
func TestAChildThatOutlivesTheWaitIsTerminated(t *testing.T) {
var lg logBuf
s := New(lg.printf)
finished := start(t, s, "slow", "sleep", "30")
s.Stopping()
began := time.Now()
left := s.Wait(200*time.Millisecond, 2*time.Second)
if left != 0 {
t.Fatalf("FAIL: %d children left after SIGTERM", left)
}
<-finished
if took := time.Since(began); took > 3*time.Second {
t.Fatalf("FAIL: the wait ran %v", took)
}
t.Log("ok: the survivor was terminated inside the grace")
if _, ok := lg.find("repo=slow", "exit=signal: terminated"); !ok {
t.Fatalf("FAIL: no log of the terminated child: %q", lg.lines)
}
t.Log("ok: its end was logged")
}
// Once a stop has begun waiting, a new child is refused rather than
// extending the wait, and stays refused until the process exits: the
// refusal is armed even when nothing was running. Reset reopens the set
// for a test that ran a stop in-process.
func TestNewChildrenAreRefusedOnceTheStopWaits(t *testing.T) {
s := New(func(string, ...any) {})
s.Wait(time.Second, time.Second)
cmd, _, err := s.Command(context.Background(), "demo", "late", "true")
if !errors.Is(err, ErrStopping) {
t.Fatalf("FAIL: a child after the stop was not refused: %v", err)
}
if runErr := cmd.Run(); !errors.Is(runErr, ErrStopping) {
t.Fatalf("FAIL: a refused command still ran: %v", runErr)
}
t.Log("ok: a child after the stop is refused, and its command cannot run")
s.Reset()
_, done, err := s.Command(context.Background(), "demo", "after", "true")
if err != nil {
t.Fatalf("FAIL: Reset did not reopen the set: %v", err)
}
done()
t.Log("ok: Reset reopens the set")
}
// A stop that coincides with spawns reads nothing a starting command is
// still writing; run under -race, this is the race the reviewer found.
func TestAStopCoincidingWithSpawnsIsRaceFree(t *testing.T) {
s := New(func(string, ...any) {})
var wg sync.WaitGroup
for i := 0; i < 8; i++ {
wg.Add(1)
go func() {
defer wg.Done()
for j := 0; j < 5; j++ {
cmd, done, err := s.Command(context.Background(), "demo", "sleep", "sleep", "0.05")
if err != nil {
return
}
cmd.Run()
done()
}
}()
}
time.Sleep(20 * time.Millisecond)
s.Stopping()
s.Wait(50*time.Millisecond, 2*time.Second)
wg.Wait()
t.Log("ok: no race between the stop and starting children")
}
// A child built before the wait but started a moment later is still
// asked to stop when it outlives the wait, and its pid is known then.
func TestAChildStartedDuringTheWaitIsStillTerminated(t *testing.T) {
var lg logBuf
s := New(lg.printf)
cmd, done, err := s.Command(context.Background(), "late", "sleep", "sleep", "30")
if err != nil {
t.Fatal(err)
}
finished := make(chan struct{})
go func() {
time.Sleep(50 * time.Millisecond)
if err := cmd.Start(); err == nil {
cmd.Wait()
}
done()
close(finished)
}()
began := time.Now()
if left := s.Wait(200*time.Millisecond, 2*time.Second); left != 0 {
t.Fatalf("FAIL: %d children left", left)
}
<-finished
if took := time.Since(began); took > 3*time.Second {
t.Fatalf("FAIL: the wait ran %v", took)
}
if _, ok := lg.find("repo=late", "exit=signal: terminated"); !ok {
t.Fatalf("FAIL: the late child was not terminated: %q", lg.lines)
}
t.Log("ok: the late child was terminated")
line, ok := lg.find("repo=late", "SIGTERM")
if !ok || strings.Contains(line, "pid=0") {
t.Fatalf("FAIL: the SIGTERM line lacks the child's pid: %q", lg.lines)
}
t.Logf("ok: %q", line)
}
// Outside a stop, children come and go without a line each: the log is
// for proving the order of a stop, not for every listing.
func TestChildrenAreLoggedOnlyDuringAStop(t *testing.T) {
var lg logBuf
s := New(lg.printf)
<-start(t, s, "demo", "true")
if len(lg.lines) != 0 {
t.Fatalf("FAIL: a child outside a stop was logged: %q", lg.lines)
}
t.Log("ok: quiet outside a stop")
if n := s.Live(); n != 0 {
t.Fatalf("FAIL: %d finished children still tracked", n)
}
t.Log("ok: finished children are forgotten")
}