fix: Send log messages to STDERR (#583)

And only useful outputs from helm commands like ones from `helm template` to STDOUT.

Fixes #551

helmexec/exec.go

@@ -1,6 +1,7 @@
 package helmexec
 
 import (
+	"fmt"
 	"io"
 	"io/ioutil"
 	"os"
@@ -48,7 +49,9 @@ func New(logger *zap.SugaredLogger, kubeContext string) *execer {
 		helmBinary:  command,
 		logger:      logger,
 		kubeContext: kubeContext,
-		runner:      &ShellRunner{},
+		runner: &ShellRunner{
+			logger: logger,
+		},
 	}
 }
 
@@ -71,21 +74,21 @@ func (helm *execer) AddRepo(name, repository, certfile, keyfile, username, passw
 	}
 	helm.logger.Infof("Adding repo %v %v", name, repository)
 	out, err := helm.exec(args, map[string]string{})
-	helm.write(out)
+	helm.info(out)
 	return err
 }
 
 func (helm *execer) UpdateRepo() error {
 	helm.logger.Info("Updating repo")
 	out, err := helm.exec([]string{"repo", "update"}, map[string]string{})
-	helm.write(out)
+	helm.info(out)
 	return err
 }
 
 func (helm *execer) UpdateDeps(chart string) error {
 	helm.logger.Infof("Updating dependency %v", chart)
 	out, err := helm.exec([]string{"dependency", "update", chart}, map[string]string{})
-	helm.write(out)
+	helm.info(out)
 	return err
 }
 
@@ -194,7 +197,7 @@ func (helm *execer) Lint(chart string, flags ...string) error {
 func (helm *execer) Fetch(chart string, flags ...string) error {
 	helm.logger.Infof("Fetching %v", chart)
 	out, err := helm.exec(append([]string{"fetch", chart}, flags...), map[string]string{})
-	helm.write(out)
+	helm.info(out)
 	return err
 }
 
@@ -228,8 +231,14 @@ func (helm *execer) exec(args []string, env map[string]string) ([]byte, error) {
 	return helm.runner.Execute(helm.helmBinary, cmdargs, env)
 }
 
-func (helm *execer) write(out []byte) {
+func (helm *execer) info(out []byte) {
 	if len(out) > 0 {
 		helm.logger.Infof("%s", out)
 	}
 }
+
+func (helm *execer) write(out []byte) {
+	if len(out) > 0 {
+		fmt.Printf("%s\n", out)
+	}
+}

helmexec/runner.go

@@ -1,6 +1,10 @@
 package helmexec
 
 import (
+	"bytes"
+	"errors"
+	"fmt"
+	"go.uber.org/zap"
 	"os"
 	"os/exec"
 	"strings"
@@ -19,6 +23,8 @@ type Runner interface {
 // ShellRunner implemention for shell commands
 type ShellRunner struct {
 	Dir string
+
+	logger *zap.SugaredLogger
 }
 
 // Execute a shell command
@@ -26,7 +32,39 @@ func (shell ShellRunner) Execute(cmd string, args []string, env map[string]strin
 	preparedCmd := exec.Command(cmd, args...)
 	preparedCmd.Dir = shell.Dir
 	preparedCmd.Env = mergeEnv(os.Environ(), env)
-	return preparedCmd.CombinedOutput()
+	return combinedOutput(preparedCmd, shell.logger)
+}
+
+func combinedOutput(c *exec.Cmd, logger *zap.SugaredLogger) ([]byte, error) {
+	if c.Stdout != nil {
+		return nil, errors.New("exec: Stdout already set")
+	}
+	if c.Stderr != nil {
+		return nil, errors.New("exec: Stderr already set")
+	}
+	var stdout bytes.Buffer
+	var stderr bytes.Buffer
+	c.Stdout = &stdout
+	c.Stderr = &stderr
+	err := c.Run()
+
+	o := stdout.Bytes()
+	e := stderr.Bytes()
+
+	if len(e) > 0 {
+		logger.Debugf("%s\n", e)
+	}
+
+	if err != nil {
+		// TrimSpace is necessary, because otherwise helmfile prints the redundant new-lines after each error like:
+		//
+		//   err: release "envoy2" in "helmfile.yaml" failed: exit status 1: Error: could not find a ready tiller pod
+		//   <redundant new line!>
+		//   err: release "envoy" in "helmfile.yaml" failed: exit status 1: Error: could not find a ready tiller pod
+		err = fmt.Errorf("%v: %s", err, strings.TrimSpace(string(e)))
+	}
+
+	return o, err
 }
 
 func mergeEnv(orig []string, new map[string]string) []string {

main.go

@@ -30,7 +30,7 @@ func configureLogging(c *cli.Context) error {
 	if err != nil {
 		return err
 	}
-	logger = helmexec.NewLogger(os.Stdout, logLevel)
+	logger = helmexec.NewLogger(os.Stderr, logLevel)
 	if c.App.Metadata == nil {
 		// Auto-initialised in 1.19.0
 		// https://github.com/urfave/cli/blob/master/CHANGELOG.md#1190---2016-11-19

pkg/app/app.go

@@ -396,9 +396,9 @@ func clean(st *state.HelmState, errs []error) error {
 		for _, err := range errs {
 			switch e := err.(type) {
 			case *state.ReleaseError:
-				fmt.Printf("err: release \"%s\" in \"%s\" failed: %v\n", e.Name, st.FilePath, e)
+				fmt.Fprintf(os.Stderr, "err: release \"%s\" in \"%s\" failed: %v\n", e.Name, st.FilePath, e)
 			default:
-				fmt.Printf("err: %v\n", e)
+				fmt.Fprintf(os.Stderr, "err: %v\n", e)
 			}
 		}
 		return errs[0]