From 7cd0c91d0474206fdcea46bf0e058dfcb84936c7 Mon Sep 17 00:00:00 2001 From: Div Arora Date: Thu, 16 Sep 2021 13:56:50 +0800 Subject: [PATCH] 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 | 32 ++++++++++++++++---------- child/child_test.go | 55 +++++++++++++++++++++++++++++++++++++++++++++ go.mod | 1 + go.sum | 2 ++ 4 files changed, 78 insertions(+), 12 deletions(-) diff --git a/child/child.go b/child/child.go index aa9e039b5..ff0b4251e 100644 --- a/child/child.go +++ b/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,8 +262,7 @@ 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() @@ -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 } diff --git a/child/child_test.go b/child/child_test.go index 50bdb96c7..2502055af 100644 --- a/child/child_test.go +++ b/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) + } +} diff --git a/go.mod b/go.mod index 80ce70718..111a3e3ff 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 51b030de9..bd2f929aa 100644 --- a/go.sum +++ b/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=