Multi-level logging (#185)

Closes #93

Summary of changes:

- Adds the [uber-go-/zap](https://github.com/uber-go/zap) library for leveled logging (69040996e0bcbd2f211d0d8d576147027e928e3b)
- A new CLI arg `--log-level` which can take the values `debug` `info` `warn` `error` `fatal` `panic`. The default is `info`, and the existing `--quiet` flag is treated as `--log-level warn`
- All `helm.exec` calls are preceded by a one-line summary. The current information on the full helm command line arguments `exec: helm exec ... ` is only output at `debug` level. This means sensitive command line arguments which may include passwords and `--set` arguments should be hidden by default.

helmexec/exec_test.go

@@ -2,9 +2,11 @@ package helmexec
 
 import (
 	"bytes"
-	"io"
+	"os"
 	"reflect"
 	"testing"
+
+	"go.uber.org/zap"
 )
 
 // Mocking the command-line runner
@@ -18,8 +20,8 @@ func (mock *mockRunner) Execute(cmd string, args []string) ([]byte, error) {
 	return []byte{}, nil
 }
 
-func MockExecer(writer io.Writer, kubeContext string) *execer {
-	execer := New(writer, kubeContext)
+func MockExecer(logger *zap.SugaredLogger, kubeContext string) *execer {
+	execer := New(logger, kubeContext)
 	execer.runner = &mockRunner{}
 	return execer
 }
@@ -28,7 +30,8 @@ func MockExecer(writer io.Writer, kubeContext string) *execer {
 
 func TestNewHelmExec(t *testing.T) {
 	buffer := bytes.NewBufferString("something")
-	helm := New(buffer, "dev")
+	logger := NewLogger(buffer, "debug")
+	helm := New(logger, "dev")
 	if helm.kubeContext != "dev" {
 		t.Error("helmexec.New() - kubeContext")
 	}
@@ -41,7 +44,7 @@ func TestNewHelmExec(t *testing.T) {
 }
 
 func Test_SetExtraArgs(t *testing.T) {
-	helm := New(new(bytes.Buffer), "dev")
+	helm := New(NewLogger(os.Stdout, "info"), "dev")
 	helm.SetExtraArgs()
 	if len(helm.extra) != 0 {
 		t.Error("helmexec.SetExtraArgs() - passing no arguments should not change extra field")
@@ -57,7 +60,7 @@ func Test_SetExtraArgs(t *testing.T) {
 }
 
 func Test_SetHelmBinary(t *testing.T) {
-	helm := New(new(bytes.Buffer), "dev")
+	helm := New(NewLogger(os.Stdout, "info"), "dev")
 	if helm.helmBinary != "helm" {
 		t.Error("helmexec.command - default command is not helm")
 	}
@@ -69,23 +72,30 @@ func Test_SetHelmBinary(t *testing.T) {
 
 func Test_AddRepo(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.AddRepo("myRepo", "https://repo.example.com/", "cert.pem", "key.pem", "", "")
-	expected := "exec: helm repo add myRepo https://repo.example.com/ --cert-file cert.pem --key-file key.pem --kube-context dev\n"
+	expected := `Adding repo myRepo https://repo.example.com/
+exec: helm repo add myRepo https://repo.example.com/ --cert-file cert.pem --key-file key.pem --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.AddRepo()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 
 	buffer.Reset()
 	helm.AddRepo("myRepo", "https://repo.example.com/", "", "", "", "")
-	expected = "exec: helm repo add myRepo https://repo.example.com/ --kube-context dev\n"
+	expected = `Adding repo myRepo https://repo.example.com/
+exec: helm repo add myRepo https://repo.example.com/ --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.AddRepo()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 
 	buffer.Reset()
 	helm.AddRepo("myRepo", "https://repo.example.com/", "", "", "example_user", "example_password")
-	expected = "exec: helm repo add myRepo https://repo.example.com/ --username example_user --password example_password --kube-context dev\n"
+	expected = `Adding repo myRepo https://repo.example.com/
+exec: helm repo add myRepo https://repo.example.com/ --username example_user --password example_password --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.AddRepo()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -93,9 +103,12 @@ func Test_AddRepo(t *testing.T) {
 
 func Test_UpdateRepo(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.UpdateRepo()
-	expected := "exec: helm repo update --kube-context dev\n"
+	expected := `Updating repo
+exec: helm repo update --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.UpdateRepo()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -103,16 +116,21 @@ func Test_UpdateRepo(t *testing.T) {
 
 func Test_SyncRelease(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.SyncRelease("release", "chart", "--timeout 10", "--wait")
-	expected := "exec: helm upgrade --install --reset-values release chart --timeout 10 --wait --kube-context dev\n"
+	expected := `Upgrading chart
+exec: helm upgrade --install --reset-values release chart --timeout 10 --wait --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.SyncRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 
 	buffer.Reset()
 	helm.SyncRelease("release", "chart")
-	expected = "exec: helm upgrade --install --reset-values release chart --kube-context dev\n"
+	expected = `Upgrading chart
+exec: helm upgrade --install --reset-values release chart --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.SyncRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -120,17 +138,22 @@ func Test_SyncRelease(t *testing.T) {
 
 func Test_UpdateDeps(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.UpdateDeps("./chart/foo")
-	expected := "exec: helm dependency update ./chart/foo --kube-context dev\n"
+	expected := `Updating dependency ./chart/foo
+exec: helm dependency update ./chart/foo --kube-context dev
+`
 	if buffer.String() != expected {
-		t.Errorf("helmexec.SyncRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
+		t.Errorf("helmexec.UpdateDeps()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 
 	buffer.Reset()
 	helm.SetExtraArgs("--verify")
 	helm.UpdateDeps("./chart/foo")
-	expected = "exec: helm dependency update ./chart/foo --verify --kube-context dev\n"
+	expected = `Updating dependency ./chart/foo
+exec: helm dependency update ./chart/foo --verify --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.AddRepo()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -138,9 +161,12 @@ func Test_UpdateDeps(t *testing.T) {
 
 func Test_DecryptSecret(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.DecryptSecret("secretName")
-	expected := "exec: helm secrets dec secretName --kube-context dev\n"
+	expected := `Decrypting secret secretName
+exec: helm secrets dec secretName --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.DecryptSecret()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -148,16 +174,21 @@ func Test_DecryptSecret(t *testing.T) {
 
 func Test_DiffRelease(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.DiffRelease("release", "chart", "--timeout 10", "--wait")
-	expected := "exec: helm diff upgrade --allow-unreleased release chart --timeout 10 --wait --kube-context dev\n"
+	expected := `Comparing release chart
+exec: helm diff upgrade --allow-unreleased release chart --timeout 10 --wait --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.DiffRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 
 	buffer.Reset()
 	helm.DiffRelease("release", "chart")
-	expected = "exec: helm diff upgrade --allow-unreleased release chart --kube-context dev\n"
+	expected = `Comparing release chart
+exec: helm diff upgrade --allow-unreleased release chart --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.DiffRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -165,18 +196,24 @@ func Test_DiffRelease(t *testing.T) {
 
 func Test_DeleteRelease(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.DeleteRelease("release")
-	expected := "exec: helm delete release --kube-context dev\n"
+	expected := `Deleting release
+exec: helm delete release --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.DeleteRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 }
 func Test_DeleteRelease_Flags(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.DeleteRelease("release", "--purge")
-	expected := "exec: helm delete release --purge --kube-context dev\n"
+	expected := `Deleting release
+exec: helm delete release --purge --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.DeleteRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -184,18 +221,24 @@ func Test_DeleteRelease_Flags(t *testing.T) {
 
 func Test_TestRelease(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.TestRelease("release")
-	expected := "exec: helm test release --kube-context dev\n"
+	expected := `Testing release
+exec: helm test release --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.TestRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 }
 func Test_TestRelease_Flags(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.TestRelease("release", "--cleanup", "--timeout", "60")
-	expected := "exec: helm test release --cleanup --timeout 60 --kube-context dev\n"
+	expected := `Testing release
+exec: helm test release --cleanup --timeout 60 --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.TestRelease()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -203,9 +246,12 @@ func Test_TestRelease_Flags(t *testing.T) {
 
 func Test_ReleaseStatus(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.ReleaseStatus("myRelease")
-	expected := "exec: helm status myRelease --kube-context dev\n"
+	expected := `Getting status myRelease
+exec: helm status myRelease --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.ReleaseStatus()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -213,21 +259,22 @@ func Test_ReleaseStatus(t *testing.T) {
 
 func Test_exec(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "")
 	helm.exec("version")
 	expected := "exec: helm version\n"
 	if buffer.String() != expected {
 		t.Errorf("helmexec.exec()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 
-	helm = MockExecer(nil, "dev")
+	helm = MockExecer(logger, "dev")
 	ret, _ := helm.exec("diff")
 	if len(ret) != 0 {
 		t.Error("helmexec.exec() - expected empty return value")
 	}
 
 	buffer.Reset()
-	helm = MockExecer(&buffer, "dev")
+	helm = MockExecer(logger, "dev")
 	helm.exec("diff", "release", "chart", "--timeout 10", "--wait")
 	expected = "exec: helm diff release chart --timeout 10 --wait --kube-context dev\n"
 	if buffer.String() != expected {
@@ -250,7 +297,7 @@ func Test_exec(t *testing.T) {
 	}
 
 	buffer.Reset()
-	helm = MockExecer(&buffer, "")
+	helm = MockExecer(logger, "")
 	helm.SetHelmBinary("overwritten")
 	helm.exec("version")
 	expected = "exec: overwritten version\n"
@@ -261,9 +308,12 @@ func Test_exec(t *testing.T) {
 
 func Test_Lint(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.Lint("path/to/chart", "--values", "file.yml")
-	expected := "exec: helm lint path/to/chart --values file.yml --kube-context dev\n"
+	expected := `Linting path/to/chart
+exec: helm lint path/to/chart --values file.yml --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.Lint()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
@@ -271,10 +321,35 @@ func Test_Lint(t *testing.T) {
 
 func Test_Fetch(t *testing.T) {
 	var buffer bytes.Buffer
-	helm := MockExecer(&buffer, "dev")
+	logger := NewLogger(&buffer, "debug")
+	helm := MockExecer(logger, "dev")
 	helm.Fetch("chart", "--version", "1.2.3", "--untar", "--untardir", "/tmp/dir")
-	expected := "exec: helm fetch chart --version 1.2.3 --untar --untardir /tmp/dir --kube-context dev\n"
+	expected := `Fetching chart
+exec: helm fetch chart --version 1.2.3 --untar --untardir /tmp/dir --kube-context dev
+`
 	if buffer.String() != expected {
 		t.Errorf("helmexec.Lint()\nactual = %v\nexpect = %v", buffer.String(), expected)
 	}
 }
+
+var logLevelTests = map[string]string{
+	"debug": `Adding repo myRepo https://repo.example.com/
+exec: helm repo add myRepo https://repo.example.com/ --username example_user --password example_password
+`,
+	"info": `Adding repo myRepo https://repo.example.com/
+`,
+	"warn": ``,
+}
+
+func Test_LogLevels(t *testing.T) {
+	var buffer bytes.Buffer
+	for logLevel, expected := range logLevelTests {
+		buffer.Reset()
+		logger := NewLogger(&buffer, logLevel)
+		helm := MockExecer(logger, "")
+		helm.AddRepo("myRepo", "https://repo.example.com/", "", "", "example_user", "example_password")
+		if buffer.String() != expected {
+			t.Errorf("helmexec.AddRepo()\nactual = %v\nexpect = %v", buffer.String(), expected)
+		}
+	}
+}