X-Git-Url: https://git.arvados.org/arvados.git/blobdiff_plain/508bcab6bd1a7ca34a929d7314f5ad5c2e48ce26..093ec98e4a065acfc537ea22c08c337c115fe273:/services/crunchstat/crunchstat_test.go diff --git a/services/crunchstat/crunchstat_test.go b/services/crunchstat/crunchstat_test.go index dff323e718..eb02395f00 100644 --- a/services/crunchstat/crunchstat_test.go +++ b/services/crunchstat/crunchstat_test.go @@ -1,61 +1,36 @@ +// Copyright (C) The Arvados Authors. All rights reserved. +// +// SPDX-License-Identifier: AGPL-3.0 + package main import ( "bufio" "bytes" + "fmt" "io" + "io/ioutil" "log" "math/rand" "os" - "regexp" + "os/exec" + "sync" + "syscall" "testing" "time" ) -func TestReadAllOrWarnFail(t *testing.T) { - rcv := captureLogs() - defer uncaptureLogs() - go func() { - // The special file /proc/self/mem can be opened for - // reading, but reading from byte 0 returns an error. - f, err := os.Open("/proc/self/mem") - if err != nil { - t.Fatalf("Opening /proc/self/mem: %s", err) - } - if x, err := ReadAllOrWarn(f); err == nil { - t.Fatalf("Expected error, got %v", x) - } - }() - if msg, err := rcv.ReadBytes('\n'); err != nil { - t.Fatal(err) - } else if matched, err := regexp.MatchString("^crunchstat: .*error.*", string(msg)); err != nil || !matched { - t.Fatalf("Expected error message about unreadable file, got \"%s\"", msg) - } -} - -func TestReadAllOrWarnSuccess(t *testing.T) { - f, err := os.Open("./crunchstat_test.go") - if err != nil { - t.Fatalf("Opening ./crunchstat_test.go: %s", err) - } - data, err := ReadAllOrWarn(f) - if err != nil { - t.Fatalf("got error %s", err) - } - if matched, err := regexp.MatchString("^package main\n", string(data)); err != nil || !matched { - t.Fatalf("data failed regexp: %s", err) - } -} - // Test that CopyPipeToChildLog works even on lines longer than // bufio.MaxScanTokenSize. func TestCopyPipeToChildLogLongLines(t *testing.T) { - rcv := captureLogs() - defer uncaptureLogs() + logger, logBuf := bufLogger() - control := make(chan bool) pipeIn, pipeOut := io.Pipe() - go CopyPipeToChildLog(pipeIn, control) + copied := make(chan bool) + go func() { + copyPipeToChildLog(pipeIn, logger) + close(copied) + }() sentBytes := make([]byte, bufio.MaxScanTokenSize+MaxLogLine+(1<<22)) go func() { @@ -72,14 +47,14 @@ func TestCopyPipeToChildLogLongLines(t *testing.T) { pipeOut.Close() }() - if before, err := rcv.ReadBytes('\n'); err != nil || string(before) != "before\n" { + if before, err := logBuf.ReadBytes('\n'); err != nil || string(before) != "before\n" { t.Fatalf("\"before\n\" not received (got \"%s\", %s)", before, err) } var receivedBytes []byte done := false for !done { - line, err := rcv.ReadBytes('\n') + line, err := logBuf.ReadBytes('\n') if err != nil { t.Fatal(err) } @@ -89,7 +64,7 @@ func TestCopyPipeToChildLogLongLines(t *testing.T) { } line = line[5:] } - if len(line) >= 6 && string(line[len(line)-6:len(line)]) == "[...]\n" { + if len(line) >= 6 && string(line[len(line)-6:]) == "[...]\n" { line = line[:len(line)-6] } else { done = true @@ -97,30 +72,167 @@ func TestCopyPipeToChildLogLongLines(t *testing.T) { receivedBytes = append(receivedBytes, line...) } if bytes.Compare(receivedBytes, sentBytes) != 0 { - t.Fatalf("sent %d bytes, got %d different bytes", len(sentBytes)+1, len(receivedBytes)) + t.Fatalf("sent %d bytes, got %d different bytes", len(sentBytes), len(receivedBytes)) } - if after, err := rcv.ReadBytes('\n'); err != nil || string(after) != "after\n" { - t.Fatal("\"after\n\" not received (got \"%s\", %s)", after, err) + if after, err := logBuf.ReadBytes('\n'); err != nil || string(after) != "after\n" { + t.Fatalf("\"after\n\" not received (got \"%s\", %s)", after, err) } select { case <-time.After(time.Second): t.Fatal("Timeout") - case <-control: + case <-copied: // Done. } } -func captureLogs() *bufio.Reader { - // Send childLog to our bufio reader instead of stderr - stderrIn, stderrOut := io.Pipe() - childLog = log.New(stderrOut, "", 0) - statLog = log.New(stderrOut, "crunchstat: ", 0) - return bufio.NewReader(stderrIn) +func bufLogger() (*log.Logger, *bufio.Reader) { + r, w := io.Pipe() + logger := log.New(w, "", 0) + return logger, bufio.NewReader(r) +} + +func TestSignalOnDeadPPID(t *testing.T) { + if !testDeadParent(t, 0) { + t.Fatal("child should still be alive after parent dies") + } + if testDeadParent(t, 15) { + t.Fatal("child should have been killed when parent died") + } } -func uncaptureLogs() { - childLog = log.New(os.Stderr, "", 0) - statLog = log.New(os.Stderr, "crunchstat: ", 0) +// testDeadParent returns true if crunchstat's child proc is still +// alive after its parent dies. +func testDeadParent(t *testing.T, signum int) bool { + var err error + var bin, childlockfile, parentlockfile *os.File + for _, f := range []**os.File{&bin, &childlockfile, &parentlockfile} { + *f, err = ioutil.TempFile("", "crunchstat_") + if err != nil { + t.Fatal(err) + } + defer (*f).Close() + defer os.Remove((*f).Name()) + } + + bin.Close() + err = exec.Command("go", "build", "-o", bin.Name()).Run() + if err != nil { + t.Fatal(err) + } + + err = syscall.Flock(int(parentlockfile.Fd()), syscall.LOCK_EX) + if err != nil { + t.Fatal(err) + } + + cmd := exec.Command("bash", "-c", ` +set -e +"$BINFILE" -cgroup-root=/none -ppid-check-interval=10ms -signal-on-dead-ppid="$SIGNUM" bash -c ' + set -e + unlock() { + flock --unlock "$CHILDLOCKFD" + kill %1 + } + trap unlock TERM + flock --exclusive "$CHILDLOCKFD" + echo -n "$$" > "$CHILDLOCKFILE" + flock --unlock "$PARENTLOCKFD" + sleep 20 /dev/null 2>/dev/null & + wait %1 + unlock +' & + +# wait for inner bash to start, to ensure $BINFILE has seen this bash proc as its initial PPID +flock --exclusive "$PARENTLOCKFILE" true +`) + cmd.Env = append(os.Environ(), + "SIGNUM="+fmt.Sprintf("%d", signum), + "PARENTLOCKFD=3", + "PARENTLOCKFILE="+parentlockfile.Name(), + "CHILDLOCKFD=4", + "CHILDLOCKFILE="+childlockfile.Name(), + "BINFILE="+bin.Name()) + cmd.ExtraFiles = []*os.File{parentlockfile, childlockfile} + stderr, err := cmd.StderrPipe() + if err != nil { + t.Fatal(err) + } + stdout, err := cmd.StdoutPipe() + if err != nil { + t.Fatal(err) + } + cmd.Start() + defer cmd.Wait() + + var wg sync.WaitGroup + wg.Add(2) + defer wg.Wait() + for _, rdr := range []io.ReadCloser{stderr, stdout} { + go func(rdr io.ReadCloser) { + defer wg.Done() + buf := make([]byte, 1024) + for { + n, err := rdr.Read(buf) + if n > 0 { + t.Logf("%s", buf[:n]) + } + if err != nil { + return + } + } + }(rdr) + } + + // Wait until inner bash process releases parentlockfile + // (which means it has locked childlockfile and written its + // PID) + err = exec.Command("flock", "--exclusive", parentlockfile.Name(), "true").Run() + if err != nil { + t.Fatal(err) + } + + childDone := make(chan bool) + go func() { + // Notify the main thread when the inner bash process + // releases its lock on childlockfile (which means + // either its sleep process ended or it received a + // TERM signal). + t0 := time.Now() + err = exec.Command("flock", "--exclusive", childlockfile.Name(), "true").Run() + if err != nil { + t.Fatal(err) + } + t.Logf("child done after %s", time.Since(t0)) + close(childDone) + }() + + select { + case <-time.After(500 * time.Millisecond): + // Inner bash process is still alive after the timeout + // period. Kill it now, so our stdout and stderr pipes + // can finish and we don't leave a mess of child procs + // behind. + buf, err := ioutil.ReadFile(childlockfile.Name()) + if err != nil { + t.Fatal(err) + } + var childPID int + _, err = fmt.Sscanf(string(buf), "%d", &childPID) + if err != nil { + t.Fatal(err) + } + child, err := os.FindProcess(childPID) + if err != nil { + t.Fatal(err) + } + child.Signal(syscall.Signal(15)) + return true + + case <-childDone: + // Inner bash process ended soon after its grandparent + // ended. + return false + } }