package children
import (
"errors"
"fmt"
"os/exec"
"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 cmd as a tracked child the way zitcli does: track, run,
// then call done once the process has been waited for.
func start(t *testing.T, s *Set, repo string, cmd *exec.Cmd) <-chan struct{} {
t.Helper()
done, err := s.Track(repo, cmd.Args[0], cmd)
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", exec.Command("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", exec.Command("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")
}
// While the stop waits, a new child is refused rather than extending the
// wait; once the wait is over the set takes children again.
func TestNewChildrenAreRefusedWhileWaiting(t *testing.T) {
s := New(func(string, ...any) {})
finished := start(t, s, "demo", exec.Command("sleep", "0.3"))
refused := make(chan error, 1)
go func() {
time.Sleep(100 * time.Millisecond)
_, err := s.Track("demo", "late", exec.Command("true"))
refused <- err
}()
s.Wait(5*time.Second, time.Second)
<-finished
if err := <-refused; !errors.Is(err, ErrStopping) {
t.Fatalf("FAIL: a child started during the wait was not refused: %v", err)
}
t.Log("ok: a child started during the wait is refused")
done, err := s.Track("demo", "after", exec.Command("true"))
if err != nil {
t.Fatalf("FAIL: the set refuses children after the wait: %v", err)
}
done()
t.Log("ok: the set takes children again after the wait")
}
// 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", exec.Command("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")
}