backport fix for dropped logs to v2 (#297)

backends/backends.go

@@ -39,7 +39,8 @@ func NewBackends(raw []interface{}, disc discovery.ServiceBackend) ([]*Backend,
 			return nil, fmt.Errorf("`onChange` is required in backend %s",
 				b.Name)
 		}
-		cmd, err := commands.NewCommand(b.OnChangeExec, b.Timeout)
+		cmd, err := commands.NewCommand(b.OnChangeExec, b.Timeout,
+			log.Fields{"process": "onChange", "backend": b.Name})
 		if err != nil {
 			return nil, fmt.Errorf("Could not parse `onChange` in backend %s: %s",
 				b.Name, err)
@@ -72,9 +73,11 @@ func (b *Backend) PollAction() {
 	}
 }
 
-// PollStop does nothing in a Backend
+// PollStop closes the Backends logs
 func (b *Backend) PollStop() {
-	// Nothing to do
+	if b.onChangeCmd != nil {
+		b.onChangeCmd.CloseLogs()
+	}
 }
 
 // CheckForUpstreamChanges checks the service discovery endpoint for any changes
@@ -85,6 +88,5 @@ func (b *Backend) CheckForUpstreamChanges() bool {
 
 // OnChange runs the backend's onChange command, returning the results
 func (b *Backend) OnChange() error {
-	return commands.RunWithTimeout(b.onChangeCmd, log.Fields{
-		"process": "onChange", "backend": b.Name})
+	return commands.RunWithTimeout(b.onChangeCmd)
 }

backends/backends_test.go

@@ -9,7 +9,7 @@ import (
 )
 
 func TestOnChangeCmd(t *testing.T) {
-	cmd1, _ := commands.NewCommand("./testdata/test.sh doStuff --debug", "1s")
+	cmd1, _ := commands.NewCommand("./testdata/test.sh doStuff --debug", "1s", nil)
 	backend := &Backend{
 		onChangeCmd: cmd1,
 	}

commands/commands.go

@@ -25,11 +25,12 @@ type Command struct {
 	Timeout         string
 	TimeoutDuration time.Duration
 	ticker          *time.Ticker
-	logWriters      []io.WriteCloser
+	logger          io.WriteCloser
+	logFields       log.Fields
 }
 
 // NewCommand parses JSON config into a Command
-func NewCommand(rawArgs interface{}, timeoutFmt string) (*Command, error) {
+func NewCommand(rawArgs interface{}, timeoutFmt string, fields log.Fields) (*Command, error) {
 	exec, args, err := ParseArgs(rawArgs)
 	if err != nil {
 		return nil, err
@@ -44,7 +45,9 @@ func NewCommand(rawArgs interface{}, timeoutFmt string) (*Command, error) {
 		Args:            args,
 		Timeout:         timeoutFmt,
 		TimeoutDuration: timeout,
-	} // cmd, ticker, logWriters all created at RunAndWait or RunWithTimeout
+		logger:          log.StandardLogger().Writer(),
+		logFields:       fields,
+	} // Cmd and ticker all created at RunAndWait or RunWithTimeout
 	return cmd, nil
 }
 
@@ -62,18 +65,14 @@ func getTimeout(timeoutFmt string) (time.Duration, error) {
 }
 
 // RunAndWait runs the given command and blocks until completed
-func RunAndWait(c *Command, fields log.Fields) (int, error) {
+func RunAndWait(c *Command) (int, error) {
 	if c == nil {
 		// sometimes this will be ok but we should return an error
 		// anyway in case the caller cares
 		return 1, errors.New("Command for RunAndWait was nil")
 	}
 	log.Debugf("%s.RunAndWait start", c.Name)
-	c.setUpCmd(fields)
-	if fields == nil {
-		c.Cmd.Stdout = os.Stdout
-		c.Cmd.Stderr = os.Stderr
-	}
+	c.setUpCmd()
 	log.Debugf("%s.Cmd.Run", c.Name)
 	if err := c.Cmd.Start(); err != nil {
 		// the stdlib almost certainly won't include the underlying error
@@ -115,7 +114,7 @@ func RunAndWaitForOutput(c *Command) (string, error) {
 		return "", errors.New("Command for RunAndWaitForOutput was nil")
 	}
 	log.Debugf("%s.RunAndWaitForOutput start", c.Name)
-	c.setUpCmd(nil)
+	c.setUpCmd()
 
 	// we'll pass stderr to the container's stderr, but stdout must
 	// be "clean" and not have anything other than what we intend
@@ -132,15 +131,14 @@ func RunAndWaitForOutput(c *Command) (string, error) {
 
 // RunWithTimeout runs the given command and blocks until completed
 // or until the timeout expires
-func RunWithTimeout(c *Command, fields log.Fields) error {
+func RunWithTimeout(c *Command) error {
 	if c == nil {
 		// sometimes this will be ok but we should return an error
 		// anyway in case the caller cares
 		return errors.New("Command for RunWithTimeout was nil")
 	}
 	log.Debugf("%s.RunWithTimeout start", c.Name)
-	c.setUpCmd(fields)
-	defer c.closeLogs()
+	c.setUpCmd()
 	log.Debugf("%s.Cmd.Start", c.Name)
 	if err := c.Cmd.Start(); err != nil {
 		log.Errorf("Unable to start %s: %v", c.Name, err)
@@ -152,14 +150,13 @@ func RunWithTimeout(c *Command, fields log.Fields) error {
 	return err
 }
 
-func (c *Command) setUpCmd(fields log.Fields) {
+func (c *Command) setUpCmd() {
 	cmd := ArgsToCmd(c.Exec, c.Args)
-	if fields != nil {
-		stdout := utils.NewLogWriter(fields, log.InfoLevel)
-		stderr := utils.NewLogWriter(fields, log.DebugLevel)
-		c.logWriters = []io.WriteCloser{stdout, stderr}
-		cmd.Stdout = stdout
-		cmd.Stderr = stderr
+	if c.logFields == nil {
+		cmd.Stderr = os.Stderr
+	} else {
+		cmd.Stdout = c.logger
+		cmd.Stderr = c.logger
 	}
 	c.Cmd = cmd
 }
@@ -226,13 +223,9 @@ func (c *Command) waitForTimeout() error {
 	return nil
 }
 
-func (c *Command) closeLogs() {
-	if c.logWriters == nil {
-		return
-	}
-	for _, w := range c.logWriters {
-		if err := w.Close(); err != nil {
-			log.Errorf("unable to close log writer : %v", err)
-		}
+// CloseLogs closes logs, duh
+func (c *Command) CloseLogs() {
+	if c.logger != nil {
+		c.logger.Close()
 	}
 }

commands/commands_test.go

@@ -13,9 +13,9 @@ import (
 )
 
 func TestRunAndWaitSuccess(t *testing.T) {
-	cmd, _ := NewCommand("./testdata/test.sh doStuff --debug", "0")
+	cmd, _ := NewCommand("./testdata/test.sh doStuff --debug", "0", nil)
 	cmd.Name = "APP"
-	if exitCode, _ := RunAndWait(cmd, nil); exitCode != 0 {
+	if exitCode, _ := RunAndWait(cmd); exitCode != 0 {
 		t.Errorf("Expected exit code 0 but got %d", exitCode)
 	}
 	if pid := os.Getenv("CONTAINERPILOT_APP_PID"); pid == "" {
@@ -24,37 +24,37 @@ func TestRunAndWaitSuccess(t *testing.T) {
 }
 
 func BenchmarkRunAndWaitSuccess(b *testing.B) {
-	cmd, _ := NewCommand("./testdata/test.sh doNothing", "0")
+	cmd, _ := NewCommand("./testdata/test.sh doNothing", "0", nil)
 	for i := 0; i < b.N; i++ {
-		RunAndWait(cmd, nil)
+		RunAndWait(cmd)
 	}
 }
 
 func TestRunAndWaitFailed(t *testing.T) {
-	cmd, _ := NewCommand("./testdata/test.sh failStuff --debug", "0")
-	if exitCode, _ := RunAndWait(cmd, nil); exitCode != 255 {
+	cmd, _ := NewCommand("./testdata/test.sh failStuff --debug", "0", nil)
+	if exitCode, _ := RunAndWait(cmd); exitCode != 255 {
 		t.Errorf("Expected exit code 255 but got %d", exitCode)
 	}
 }
 
 func TestRunAndWaitInvalidCommand(t *testing.T) {
-	cmd, _ := NewCommand("./testdata/invalidCommand", "0")
-	if exitCode, _ := RunAndWait(cmd, nil); exitCode != 127 {
+	cmd, _ := NewCommand("./testdata/invalidCommand", "0", nil)
+	if exitCode, _ := RunAndWait(cmd); exitCode != 127 {
 		t.Errorf("Expected exit code 127 but got %d", exitCode)
 	}
 }
 
 func TestRunAndWaitForOutput(t *testing.T) {
 
-	cmd, _ := NewCommand("./testdata/test.sh doStuff --debug", "0")
+	cmd, _ := NewCommand("./testdata/test.sh doStuff --debug", "0", nil)
 	if out, err := RunAndWaitForOutput(cmd); err != nil {
 		t.Fatalf("Unexpected error from 'test.sh doStuff': %s", err)
 	} else if out != "Running doStuff with args: --debug\n" {
 		t.Fatalf("Unexpected output from 'test.sh doStuff': %s", out)
 	}
 
 	// Ensure bad commands return error
-	cmd2, _ := NewCommand("./testdata/doesNotExist.sh", "0")
+	cmd2, _ := NewCommand("./testdata/doesNotExist.sh", "0", nil)
 	if out, err := RunAndWaitForOutput(cmd2); err == nil {
 		t.Fatalf("Expected error from 'doesNotExist.sh' but got %s", out)
 	} else if err.Error() != "fork/exec ./testdata/doesNotExist.sh: no such file or directory" {
@@ -63,9 +63,9 @@ func TestRunAndWaitForOutput(t *testing.T) {
 }
 
 func TestRunWithTimeout(t *testing.T) {
-	cmd, _ := NewCommand("./testdata/test.sh sleepStuff", "200ms")
-	fields := log.Fields{"process": "test"}
-	RunWithTimeout(cmd, fields)
+	cmd, _ := NewCommand("./testdata/test.sh sleepStuff", "200ms",
+		log.Fields{"process": "test"})
+	RunWithTimeout(cmd)
 
 	// Ensure the task has time to start
 	runtime.Gosched()
@@ -97,9 +97,9 @@ func TestRunWithTimeoutFailed(t *testing.T) {
 	log.SetOutput(tmp)
 	defer log.SetOutput(os.Stdout)
 
-	cmd, _ := NewCommand("./testdata/test.sh failStuff --debug", "100ms")
 	fields := log.Fields{"process": "test"}
-	if err := RunWithTimeout(cmd, fields); err == nil {
+	cmd, _ := NewCommand("./testdata/test.sh failStuff --debug", "100ms", fields)
+	if err := RunWithTimeout(cmd); err == nil {
 		t.Errorf("Expected error but got nil")
 	}
 	time.Sleep(200 * time.Millisecond)
@@ -113,25 +113,25 @@ func TestRunWithTimeoutFailed(t *testing.T) {
 }
 
 func TestRunWithTimeoutInvalidCommand(t *testing.T) {
-	cmd, _ := NewCommand("./testdata/invalidCommand", "100ms")
 	fields := log.Fields{"process": "test"}
-	if err := RunWithTimeout(cmd, fields); err == nil {
+	cmd, _ := NewCommand("./testdata/invalidCommand", "100ms", fields)
+	if err := RunWithTimeout(cmd); err == nil {
 		t.Errorf("Expected error but got nil")
 	}
 }
 
 func TestEmptyCommand(t *testing.T) {
-	if cmd, err := NewCommand("", "0"); cmd != nil || err == nil {
+	if cmd, err := NewCommand("", "0", nil); cmd != nil || err == nil {
 		t.Errorf("Expected exit (nil, err) but got %s, %s", cmd, err)
 	}
 }
 
 func TestReuseCmd(t *testing.T) {
-	cmd, _ := NewCommand("true", "0")
-	if code, err := RunAndWait(cmd, nil); code != 0 || err != nil {
+	cmd, _ := NewCommand("true", "0", nil)
+	if code, err := RunAndWait(cmd); code != 0 || err != nil {
 		t.Errorf("Expected exit (0,nil) but got (%d,%s)", code, err)
 	}
-	if code, err := RunAndWait(cmd, nil); code != 0 || err != nil {
+	if code, err := RunAndWait(cmd); code != 0 || err != nil {
 		t.Errorf("Expected exit (0,nil) but got (%d,%s)", code, err)
 	}
 }

config/commands.go

@@ -33,7 +33,7 @@ func parseCommand(name string, args interface{}) (*commands.Command, error) {
 	if args == nil {
 		return nil, nil
 	}
-	cmd, err := commands.NewCommand(args, "0")
+	cmd, err := commands.NewCommand(args, "0", nil)
 	if err != nil {
 		return nil, fmt.Errorf("Could not parse `%s`: %s", name, err)
 	}

coprocesses/coprocess.go

@@ -51,7 +51,8 @@ func parseCoprocess(coprocess *Coprocess) error {
 	if coprocess.Command == nil {
 		return fmt.Errorf("Coprocess did not provide a command")
 	}
-	cmd, err := commands.NewCommand(coprocess.Command, "0")
+	cmd, err := commands.NewCommand(coprocess.Command, "0",
+		log.Fields{"process": "coprocess", "coprocess": coprocess.Name})
 	if err != nil {
 		return fmt.Errorf("Could not parse `coprocess` command %s: %s",
 			coprocess.Name, err)
@@ -115,7 +116,6 @@ func parseCoprocessRestarts(coprocess *Coprocess) error {
 // Start runs the coprocess
 func (c *Coprocess) Start() {
 	log.Debugf("coprocess[%s].Start", c.Name)
-	fields := log.Fields{"process": "coprocess", "coprocess": c.Name}
 
 	// always reset restartsRemain when we load the config
 	c.restartsRemain = c.restartLimit
@@ -124,7 +124,7 @@ func (c *Coprocess) Start() {
 			c.restartsRemain <= haltRestarts {
 			break
 		}
-		if code, err := commands.RunAndWait(c.cmd, fields); err != nil {
+		if code, err := commands.RunAndWait(c.cmd); err != nil {
 			log.Errorf("coprocess[%s] exited (%s): %s", c.Name, code, err)
 		}
 		log.Debugf("coprocess[%s] exited", c.Name)
@@ -141,5 +141,8 @@ func (c *Coprocess) Stop() {
 	c.restartsRemain = haltRestarts
 	c.restartLimit = haltRestarts
 	c.restart = false
-	c.cmd.Kill()
+	if c.cmd != nil {
+		c.cmd.Kill()
+		c.cmd.CloseLogs()
+	}
 }

core/app.go

@@ -154,7 +154,7 @@ func (a *App) Run() {
 		reapChildren()
 	}
 	args := getArgs(flag.Args())
-	cmd, err := commands.NewCommand(args, "0")
+	cmd, err := commands.NewCommand(args, "0", nil)
 	if err != nil {
 		log.Errorf("Unable to parse command arguments: %v", err)
 	}
@@ -164,8 +164,7 @@ func (a *App) Run() {
 
 	if a.PreStartCmd != nil {
 		// Run the preStart handler, if any, and exit if it returns an error
-		fields := log.Fields{"process": "PreStart"}
-		if code, err := commands.RunAndWait(a.PreStartCmd, fields); err != nil {
+		if code, err := commands.RunAndWait(a.PreStartCmd); err != nil {
 			os.Exit(code)
 		}
 	}
@@ -177,14 +176,13 @@ func (a *App) Run() {
 		// Run our main application and capture its stdout/stderr.
 		// This will block until the main application exits and then os.Exit
 		// with the exit code of that application.
-		code, err := commands.RunAndWait(a.Command, nil)
+		code, err := commands.RunAndWait(a.Command)
 		if err != nil {
 			log.Println(err)
 		}
 		// Run the PostStop handler, if any, and exit if it returns an error
 		if a.PostStopCmd != nil {
-			fields := log.Fields{"process": "PostStop"}
-			if postStopCode, err := commands.RunAndWait(a.PostStopCmd, fields); err != nil {
+			if postStopCode, err := commands.RunAndWait(a.PostStopCmd); err != nil {
 				os.Exit(postStopCode)
 			}
 		}
@@ -242,7 +240,7 @@ func (a *App) Terminate() {
 
 	// Run and wait for preStop command to exit (continues
 	// unconditionally so we don't worry about returned errors here)
-	commands.RunAndWait(a.PreStopCmd, log.Fields{"process": "PreStop"})
+	commands.RunAndWait(a.PreStopCmd)
 	if a.Command == nil || a.Command.Cmd == nil ||
 		a.Command.Cmd.Process == nil {
 		// Not managing the process, so don't do anything

core/signals_test.go

@@ -31,7 +31,7 @@ func getSignalTestConfig() *App {
 	app := EmptyApp()
 	cmd, _ := commands.NewCommand([]string{
 		"./testdata/test.sh",
-		"interruptSleep"}, "0")
+		"interruptSleep"}, "0", nil)
 	app.Command = cmd
 	app.StopTimeout = 5
 	app.Services = []*services.Service{service}
@@ -67,7 +67,7 @@ func TestTerminateSignal(t *testing.T) {
 	app := getSignalTestConfig()
 	startTime := time.Now()
 	go func() {
-		if exitCode, _ := commands.RunAndWait(app.Command, nil); exitCode != 2 {
+		if exitCode, _ := commands.RunAndWait(app.Command); exitCode != 2 {
 			t.Fatalf("Expected exit code 2 but got %d", exitCode)
 		}
 	}()