Unify loggers and add test.

Maintain back-compat with the current logging scheme by falling back
to it if an optional logger instance is not provided.

child/child.go

@@ -4,6 +4,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
+	"log"
 	"math/rand"
 	"os"
 	"os/exec"
@@ -70,6 +71,7 @@ type Child struct {
 	// whether to set process group id or not (default on)
 	setpgid bool
 
+	// an optional logger that can be used for messages pertinent to this child process
 	logger *logrus.Entry
 }
 
@@ -115,6 +117,7 @@ type NewInput struct {
 	// may be zero (which disables the splay entirely).
 	Splay time.Duration
 
+	// an optional logger that can be used for messages pertinent to the child process
 	Logger *logrus.Entry
 }
 
@@ -179,8 +182,7 @@ func (c *Child) Command() string {
 // as the second error argument, but any errors returned by the command after
 // execution will be returned as a non-zero value over the exit code channel.
 func (c *Child) Start() error {
-	log.Printf("[INFO] (child) spawning: %s", c.Command())
-	c.logger.Info(fmt.Sprintf("(child) spawning %q %q", c.command, c.args))
+	c.log(logrus.InfoLevel, "(child) spawning: %s", c.Command())
 	c.Lock()
 	defer c.Unlock()
 	return c.start()
@@ -189,18 +191,26 @@ func (c *Child) Start() error {
 // Signal sends the signal to the child process, returning any errors that
 // occur.
 func (c *Child) Signal(s os.Signal) error {
-	c.logger.Info(fmt.Sprintf("(child) receiving signal %q", s.String()))
+	c.log(logrus.InfoLevel, "(child) receiving signal %q", s.String())
 	c.RLock()
 	defer c.RUnlock()
 	return c.signal(s)
 }
 
+func (c *Child) log(level logrus.Level, format string, args ...interface{}) {
+	if c.logger != nil {
+		c.logger.Logf(level, format, args...)
+		return
+	}
+	log.Printf("[%s] %s", strings.ToUpper(level.String()), fmt.Sprintf(format, args...))
+}
+
 // Reload sends the reload signal to the child process and does not wait for a
 // response. If no reload signal was provided, the process is restarted and
 // replaces the process attached to this Child.
 func (c *Child) Reload() error {
 	if c.reloadSignal == nil {
-		c.logger.Info("(child) restarting process")
+		c.log(logrus.InfoLevel, "(child) restarting process")
 
 		// Take a full lock because start is going to replace the process. We also
 		// want to make sure that no other routines attempt to send reload signals
@@ -211,8 +221,7 @@ func (c *Child) Reload() error {
 		c.kill(false)
 		return c.start()
 	}
-	c.logger.Info("(child) reloading process")
-	log.Printf("[INFO] (child) reloading process")
+	c.log(logrus.InfoLevel, "(child) reloading process")
 
 	// We only need a read lock here because neither the process nor the exit
 	// channel are changing.
@@ -231,7 +240,7 @@ func (c *Child) Reload() error {
 // does not return any errors because it guarantees the process will be dead by
 // the return of the function call.
 func (c *Child) Kill() {
-	c.logger.Info("(child) killing process")
+	c.log(logrus.InfoLevel, "(child) killing process")
 	c.Lock()
 	defer c.Unlock()
 	c.kill(false)
@@ -253,16 +262,15 @@ func (c *Child) StopImmediately() {
 }
 
 func (c *Child) internalStop(immediately bool) {
-	log.Printf("[INFO] (child) stopping process")
-	c.logger.Info(fmt.Sprintf("(child) stopping process"))
+	c.log(logrus.InfoLevel, "(child) stopping process")
 
 	c.Lock()
 	defer c.Unlock()
 
 	c.stopLock.Lock()
 	defer c.stopLock.Unlock()
 	if c.stopped {
-		c.logger.Warn("(child) already stopped")
+		c.log(logrus.InfoLevel, "(child) already stopped")
 		return
 	}
 	c.kill(immediately)
@@ -398,10 +406,10 @@ func (c *Child) reload() error {
 func (c *Child) kill(immediately bool) {
 
 	if !c.running() {
-		log.Printf("[DEBUG] (child) Kill() called but process dead; not waiting for splay.")
+		c.log(logrus.DebugLevel, "(child) Kill() called but process dead; not waiting for splay.")
 		return
 	} else if immediately {
-		log.Printf("[DEBUG] (child) Kill() called but performing immediate shutdown; not waiting for splay.")
+		c.log(logrus.DebugLevel, "(child) Kill() called but performing immediate shutdown; not waiting for splay.")
 	} else {
 		select {
 		case <-c.stopCh:
@@ -422,7 +430,7 @@ func (c *Child) kill(immediately bool) {
 	}
 
 	if err := c.signal(c.killSignal); err != nil {
-		log.Printf("[ERR] (child) Kill failed: %s", err)
+		c.log(logrus.ErrorLevel, "(child) Kill failed: %s", err)
 		if processNotFoundErr(err) {
 			exited = true // checked in defer
 		}
@@ -461,7 +469,7 @@ func (c *Child) randomSplay() <-chan time.Time {
 	offset := rand.Int63n(ns)
 	t := time.Duration(offset)
 
-	c.logger.Debug(fmt.Sprintf("(child) waiting %.2fs for random splay", t.Seconds()))
+	c.log(logrus.DebugLevel, fmt.Sprintf("(child) waiting %.2fs for random splay", t.Seconds()))
 
 	return time.After(t)
 }

child/child_test.go

@@ -1,9 +1,13 @@
 package child
 
 import (
+	"bytes"
+	"github.com/sirupsen/logrus"
 	"io/ioutil"
+	"log"
 	"os"
 	"reflect"
+	"strings"
 	"syscall"
 	"testing"
 	"time"
@@ -472,3 +476,54 @@ func TestSetpgid(t *testing.T) {
 		}
 	})
 }
+
+func TestLog(t *testing.T) {
+	var buf bytes.Buffer
+	log.SetOutput(&buf)
+	defer func() {
+		log.SetOutput(os.Stderr)
+	}()
+
+	c := testChild(t)
+	c.command = "sh"
+	c.args = []string{"-c", "echo 1"}
+
+	if err := c.Start(); err != nil {
+		t.Fatal(err)
+	}
+	defer c.Stop()
+	expected := "[INFO] (child) spawning: sh -c echo 1\n"
+	actual := buf.String()
+
+	// trim off leading timestamp
+	index := strings.Index(actual, "[")
+	actual = actual[index:]
+	if actual != expected {
+		t.Fatalf("Expected '%s' to be '%s'", actual, expected)
+	}
+}
+
+func TestCustomLogger(t *testing.T) {
+	var buf bytes.Buffer
+
+	c := testChild(t)
+	c.command = "sh"
+	c.args = []string{"-c", "echo 1"}
+	logger := logrus.New()
+	logger.SetOutput(&buf)
+	c.logger = logger.WithField("child-name", "echo")
+
+	if err := c.Start(); err != nil {
+		t.Fatal(err)
+	}
+	defer c.Stop()
+	expected := " level=info msg=\"(child) spawning: sh -c echo 1\" child-name=echo\n"
+	actual := buf.String()
+
+	// trim off leading timestamp
+	index := strings.Index(actual, " ")
+	actual = actual[index:]
+	if actual != expected {
+		t.Fatalf("Expected '%s' to be '%s'", actual, expected)
+	}
+}

go.mod

@@ -33,6 +33,7 @@ require (
 	github.com/mitchellh/mapstructure v1.3.3
 	github.com/pierrec/lz4 v2.5.2+incompatible // indirect
 	github.com/pkg/errors v0.9.1
+	github.com/sirupsen/logrus v1.4.2
 	github.com/stretchr/testify v1.4.0
 	golang.org/x/crypto v0.0.0-20210817164053-32db794688a5 // indirect
 	golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1

go.sum

@@ -127,6 +127,7 @@ github.com/imdario/mergo v0.3.12/go.mod h1:jmQim1M+e3UYxmgPu/WyfjB3N3VflVyUjjjwH
 github.com/json-iterator/go v1.1.6/go.mod h1:+SdeFBvtyEkXs7REEP0seUULqWtbJapLOCVDaaPEHmU=
 github.com/json-iterator/go v1.1.9/go.mod h1:KdQUCv79m/52Kvf8AW2vK1V8akMuk1QjK/uOdHXbAo4=
 github.com/julienschmidt/httprouter v1.2.0/go.mod h1:SYymIcj16QtmaHHD7aYtjjsJG7VTCxuUUipMqKk8s4w=
+github.com/konsorten/go-windows-terminal-sequences v1.0.1 h1:mweAR1A6xJ3oS2pRaGiHgQ4OO8tzTaLawm8vnODuwDk=
 github.com/konsorten/go-windows-terminal-sequences v1.0.1/go.mod h1:T0+1ngSBFLxvqU3pZ+m/2kptfBszLMUkC4ZK/EgS/cQ=
 github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
@@ -206,6 +207,7 @@ github.com/ryanuber/go-glob v1.0.0/go.mod h1:807d1WSdnB0XRJzKNil9Om6lcp/3a0v4qIH
 github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529 h1:nn5Wsu0esKSJiIVhscUtVbo7ada43DJhG55ua/hjS5I=
 github.com/sean-/seed v0.0.0-20170313163322-e2103e2c3529/go.mod h1:DxrIzT+xaE7yg65j358z/aeFdxmN0P9QXhEzd20vsDc=
 github.com/sirupsen/logrus v1.2.0/go.mod h1:LxeOpSwHxABJmUn/MG1IvRgCAasNZTLOkJPxbbu5VWo=
+github.com/sirupsen/logrus v1.4.2 h1:SPIRibHv4MatM3XXNO2BJeFLZwZ2LvZgfQ5+UNI2im4=
 github.com/sirupsen/logrus v1.4.2/go.mod h1:tLMulIdttU9McNUspp0xgXVQah82FyeX6MwdIuYE2rE=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.1.1/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=