Allow the child to be provided a custom logger.

If one is not provided, a default go-hclog instance is used
instead. While this doesn't retain byte-for-byte back-compat in terms
of logging output, the doesn't seem like an unreasonable change when
weighed against the simplified implementation.

child/child.go

@@ -68,6 +68,9 @@ type Child struct {
 
 	// whether to set process group id or not (default on)
 	setpgid bool
+
+	// a logger that can be used for messages pertinent to this child process
+	logger *log.Logger
 }
 
 // NewInput is input to the NewChild function.
@@ -111,6 +114,9 @@ type NewInput struct {
 	// prevents multiple processes from all signaling at the same time. This value
 	// 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 *log.Logger
 }
 
 // New creates a new child process for management with high-level APIs for
@@ -139,6 +145,7 @@ func New(i *NewInput) (*Child, error) {
 		splay:        i.Splay,
 		stopCh:       make(chan struct{}, 1),
 		setpgid:      true,
+		logger:       i.Logger,
 	}
 
 	return child, nil
@@ -173,7 +180,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.log("[INFO] (child) spawning: %s", c.Command())
 	c.Lock()
 	defer c.Unlock()
 	return c.start()
@@ -182,18 +189,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 {
-	log.Printf("[INFO] (child) receiving signal %q", s.String())
+	c.log("[INFO] (child) receiving signal %q", s.String())
 	c.RLock()
 	defer c.RUnlock()
 	return c.signal(s)
 }
 
+func (c *Child) log(format string, args ...interface{}) {
+	if c.logger != nil {
+		c.logger.Printf(format, args...)
+		return
+	}
+	log.Printf(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 {
-		log.Printf("[INFO] (child) restarting process")
+		c.log("[INFO] (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
@@ -204,8 +219,7 @@ func (c *Child) Reload() error {
 		c.kill(false)
 		return c.start()
 	}
-
-	log.Printf("[INFO] (child) reloading process")
+	c.log("[INFO] (child) reloading process")
 
 	// We only need a read lock here because neither the process nor the exit
 	// channel are changing.
@@ -224,7 +238,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() {
-	log.Printf("[INFO] (child) killing process")
+	c.log("[INFO] (child) killing process")
 	c.Lock()
 	defer c.Unlock()
 	c.kill(false)
@@ -246,15 +260,15 @@ func (c *Child) StopImmediately() {
 }
 
 func (c *Child) internalStop(immediately bool) {
-	log.Printf("[INFO] (child) stopping process")
+	c.log("[INFO] (child) stopping process")
 
 	c.Lock()
 	defer c.Unlock()
 
 	c.stopLock.Lock()
 	defer c.stopLock.Unlock()
 	if c.stopped {
-		log.Printf("[WARN] (child) already stopped")
+		c.log("[INFO] (child) already stopped")
 		return
 	}
 	c.kill(immediately)
@@ -390,10 +404,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("[DEBUG] (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("[DEBUG] (child) Kill() called but performing immediate shutdown; not waiting for splay.")
 	} else {
 		select {
 		case <-c.stopCh:
@@ -414,7 +428,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("[ERR] (child) Kill failed: %s", err)
 		if processNotFoundErr(err) {
 			exited = true // checked in defer
 		}
@@ -453,7 +467,7 @@ func (c *Child) randomSplay() <-chan time.Time {
 	offset := rand.Int63n(ns)
 	t := time.Duration(offset)
 
-	log.Printf("[DEBUG] (child) waiting %.2fs for random splay", t.Seconds())
+	c.log("[DEBUG] (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/hashicorp/go-hclog"
 	"io/ioutil"
+	"log"
 	"os"
 	"reflect"
+	"strings"
 	"syscall"
 	"testing"
 	"time"
@@ -472,3 +476,57 @@ 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"}
+	c.logger = hclog.New(&hclog.LoggerOptions{
+		Output: &buf,
+	}).With("child-name", "echo").StandardLogger(&hclog.StandardLoggerOptions{
+		InferLevels: true,
+		ForceLevel:  0,
+	})
+
+	if err := c.Start(); err != nil {
+		t.Fatal(err)
+	}
+	defer c.Stop()
+	expected := " [INFO]  (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

@@ -6,14 +6,15 @@ require (
 	github.com/BurntSushi/toml v0.3.1
 	github.com/armon/go-metrics v0.3.4 // indirect
 	github.com/davecgh/go-spew v1.1.1
+	github.com/fatih/color v1.13.0 // indirect
 	github.com/frankban/quicktest v1.4.0 // indirect
 	github.com/golang/snappy v0.0.2 // indirect
 	github.com/google/btree v1.0.0 // indirect
 	github.com/hashicorp/consul/api v1.4.0
 	github.com/hashicorp/consul/sdk v0.4.1-0.20200910203702-bb2b5dd871ca
 	github.com/hashicorp/errwrap v1.1.0 // indirect
 	github.com/hashicorp/go-gatedio v0.5.0
-	github.com/hashicorp/go-hclog v0.14.1 // indirect
+	github.com/hashicorp/go-hclog v1.0.0
 	github.com/hashicorp/go-immutable-radix v1.3.0 // indirect
 	github.com/hashicorp/go-msgpack v0.5.5 // indirect
 	github.com/hashicorp/go-multierror v1.1.0
@@ -27,15 +28,15 @@ require (
 	github.com/hashicorp/serf v0.9.4 // indirect
 	github.com/hashicorp/vault/api v1.0.5-0.20190730042357-746c0b111519
 	github.com/imdario/mergo v0.3.12
-	github.com/mattn/go-colorable v0.1.7 // indirect
+	github.com/mattn/go-colorable v0.1.12 // indirect
 	github.com/mitchellh/go-homedir v1.1.0
 	github.com/mitchellh/hashstructure v1.0.0
 	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/stretchr/testify v1.4.0
 	golang.org/x/crypto v0.0.0-20210817164053-32db794688a5 // indirect
-	golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1
+	golang.org/x/sys v0.0.0-20211216021012-1d35b9e2eb4e
 	golang.org/x/time v0.0.0-20200630173020-3af7569d3a1e // indirect
 	gopkg.in/square/go-jose.v2 v2.5.1 // indirect
 	gopkg.in/yaml.v2 v2.3.0

go.sum

@@ -24,8 +24,9 @@ github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSs
 github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5KwzbycvMj4=
-github.com/fatih/color v1.9.0 h1:8xPHl4/q1VyqGIPif1F+1V3Y3lSmrq01EabUW3CoW5s=
 github.com/fatih/color v1.9.0/go.mod h1:eQcE1qtQxscV5RaZvpXrrb8Drkc3/DdQ+uUYCNjL+zU=
+github.com/fatih/color v1.13.0 h1:8LOYc1KYPPmyKMuN8QV2DNRWNbLo6LZ0iLs8+mlH53w=
+github.com/fatih/color v1.13.0/go.mod h1:kLAiJbzzSOZDVNGyDpeOxJ47H46qBXwg5ILebYFFOfk=
 github.com/fatih/structs v1.1.0/go.mod h1:9NiDSp5zOcgEDl+j00MP/WkGVPOlPRLejGD8Ga6PJ7M=
 github.com/frankban/quicktest v1.4.0 h1:rCSCih1FnSWJEel/eub9wclBSqpF2F/PuvxUWGWnbO8=
 github.com/frankban/quicktest v1.4.0/go.mod h1:36zfPVQyHxymz4cH7wlDmVwDrJuljRB60qkgn7rorfQ=
@@ -71,8 +72,8 @@ github.com/hashicorp/go-hclog v0.0.0-20180709165350-ff2cf002a8dd/go.mod h1:9bjs9
 github.com/hashicorp/go-hclog v0.8.0/go.mod h1:5CU+agLiy3J7N7QjHK5d05KxGsuXiQLrjA0H7acj2lQ=
 github.com/hashicorp/go-hclog v0.9.2/go.mod h1:5CU+agLiy3J7N7QjHK5d05KxGsuXiQLrjA0H7acj2lQ=
 github.com/hashicorp/go-hclog v0.12.0/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
-github.com/hashicorp/go-hclog v0.14.1 h1:nQcJDQwIAGnmoUWp8ubocEX40cCml/17YkF6csQLReU=
-github.com/hashicorp/go-hclog v0.14.1/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
+github.com/hashicorp/go-hclog v1.0.0 h1:bkKf0BeBXcSYa7f5Fyi9gMuQ8gNsxeiNpZjR6VxNZeo=
+github.com/hashicorp/go-hclog v1.0.0/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ=
 github.com/hashicorp/go-immutable-radix v1.0.0/go.mod h1:0y9vanUI8NX6FsYoO3zeMjhV/C5i9g4Q3DwcSNZ4P60=
 github.com/hashicorp/go-immutable-radix v1.3.0 h1:8exGP7ego3OmkfksihtSouGMZ+hQrhxx+FVELeXpVPE=
 github.com/hashicorp/go-immutable-radix v1.3.0/go.mod h1:0y9vanUI8NX6FsYoO3zeMjhV/C5i9g4Q3DwcSNZ4P60=
@@ -138,14 +139,16 @@ github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
 github.com/mattn/go-colorable v0.0.9/go.mod h1:9vuHe8Xs5qXnSaW/c/ABM9alt+Vo+STaOChaDxuIBZU=
 github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE=
 github.com/mattn/go-colorable v0.1.6/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
-github.com/mattn/go-colorable v0.1.7 h1:bQGKb3vps/j0E9GfJQ03JyhRuxsvdAanXlT9BTw3mdw=
-github.com/mattn/go-colorable v0.1.7/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
+github.com/mattn/go-colorable v0.1.9/go.mod h1:u6P/XSegPjTcexA+o6vUJrdnUu04hMope9wVRipJSqc=
+github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
+github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
 github.com/mattn/go-isatty v0.0.3/go.mod h1:M+lRXTBqGeGNdLjl/ufCoiOlB5xdOkqRJdNxMWT7Zi4=
 github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s=
 github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcMEpPG5Rm84=
 github.com/mattn/go-isatty v0.0.11/go.mod h1:PhnuNfih5lzO57/f3n+odYbM4JtupLOxQOAqxQCu2WE=
-github.com/mattn/go-isatty v0.0.12 h1:wuysRhFDzyxgEmMf5xjvJ2M9dZoWAXNNr5LSBS7uHXY=
 github.com/mattn/go-isatty v0.0.12/go.mod h1:cbi8OIDigv2wuxKPP5vlRcQ1OAZbq2CE4Kysco4FUpU=
+github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
+github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
 github.com/matttproud/golang_protobuf_extensions v1.0.1/go.mod h1:D8He9yQNgCq6Z5Ld7szi9bcBfOoFv/3dc6xSMkL2PC0=
 github.com/miekg/dns v1.0.14/go.mod h1:W1PPwlIAgtquWBMBEV9nkV9Cazfe8ScdGz/Lj7v3Nrg=
 github.com/miekg/dns v1.1.26 h1:gPxPSwALAeHJSjarOs00QjVdV9QoBvc1D2ujQUr5BzU=
@@ -263,8 +266,11 @@ golang.org/x/sys v0.0.0-20200122134326-e047566fdf82/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20200124204421-9fbb57f87de9/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200223170610-d5e6a3e2c0ae/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20201119102817-f84b799fce68/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
-golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1 h1:SrN+KX8Art/Sf4HNj6Zcz06G7VEz+7w9tdXTPOZ7+l4=
 golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.0.0-20211216021012-1d35b9e2eb4e h1:fLOSk5Q00efkSvAm+4xcoXD+RRmLmmulPn5I3Y9F2EM=
+golang.org/x/sys v0.0.0-20211216021012-1d35b9e2eb4e/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.1-0.20181227161524-e6919f6577db/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=