Information messages should be written to stdout

The current behaviour is that `span.Info` messages are written to stderr
instead of stdout. This is going against what is describe the
[contributor document](https://github.com/getporter/porter/blob/main/CONTRIBUTING.md#logging).

closes #2889

Signed-off-by: Kim Christensen <kimworking@gmail.com>

pkg/porter/reconcile_test.go

@@ -35,7 +35,7 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, nil, opts)
 		require.NoError(t, err)
 		assert.True(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Ignoring because installation.uninstalled is true but the installation doesn't exist yet")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Ignoring because installation.uninstalled is true but the installation doesn't exist yet")
 	})
 
 	t.Run("new installation with uninstalled false", func(t *testing.T) {
@@ -51,7 +51,7 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, nil, opts)
 		require.NoError(t, err)
 		assert.False(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Triggering because the installation has not completed successfully yet")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Triggering because the installation has not completed successfully yet")
 	})
 
 	t.Run("installed - no changes", func(t *testing.T) {
@@ -105,7 +105,7 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, &run, upgradeOpts)
 		require.NoError(t, err)
 		assert.False(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Triggering because the bundle definition has changed")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Triggering because the bundle definition has changed")
 	})
 
 	t.Run("installed - param changed", func(t *testing.T) {
@@ -125,7 +125,7 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, &run, upgradeOpts)
 		require.NoError(t, err)
 		assert.False(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Triggering because the parameters have changed")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Triggering because the parameters have changed")
 
 	})
 
@@ -149,7 +149,7 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, &run, upgradeOpts)
 		require.NoError(t, err)
 		assert.False(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Triggering because the credential set names have changed")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Triggering because the credential set names have changed")
 
 	})
 
@@ -168,7 +168,7 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, nil, opts)
 		require.NoError(t, err)
 		assert.False(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Triggering because installation.uninstalled is true")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Triggering because installation.uninstalled is true")
 	})
 
 	t.Run("uninstalled: uninstalled set to back to false", func(t *testing.T) {
@@ -188,6 +188,6 @@ func TestPorter_IsInstallationInSync(t *testing.T) {
 		insync, err := p.IsInstallationInSync(p.RootContext, i, nil, NewUninstallOptions())
 		require.NoError(t, err)
 		assert.True(t, insync)
-		assert.Contains(t, p.TestConfig.TestContext.GetError(), "Ignoring because the installation is uninstalled")
+		assert.Contains(t, p.TestConfig.TestContext.GetOutput(), "Ignoring because the installation is uninstalled")
 	})
 }

pkg/portercontext/context.go

@@ -213,10 +213,18 @@ func (c *Context) configureLoggingWith(ctx context.Context, baseLogger zapcore.C
 func (c *Context) makeConsoleLogger() zapcore.Core {
 	encoding := c.makeLogEncoding()
 
+	stdout := c.Out
 	stderr := c.Err
+	if f, ok := stdout.(*os.File); ok {
+		if isatty.IsTerminal(f.Fd()) {
+			stdout = colorable.NewColorable(f)
+			encoding.EncodeLevel = zapcore.LowercaseColorLevelEncoder
+		}
+	}
+
 	if f, ok := stderr.(*os.File); ok {
 		if isatty.IsTerminal(f.Fd()) {
-			stderr = colorable.NewColorable(f)
+			stdout = colorable.NewColorable(f)
 			encoding.EncodeLevel = zapcore.LowercaseColorLevelEncoder
 		}
 	}
@@ -227,7 +235,20 @@ func (c *Context) makeConsoleLogger() zapcore.Core {
 		encoding.LevelKey = ""
 	}
 	consoleEncoder := zapcore.NewConsoleEncoder(encoding)
-	return zapcore.NewCore(consoleEncoder, zapcore.AddSync(stderr), c.logCfg.Verbosity)
+
+	isInformational := func(lvl zapcore.Level) bool {
+		return lvl >= zapcore.InfoLevel && lvl < zapcore.WarnLevel && lvl >= c.logCfg.Verbosity
+	}
+	stdoutEnabler := zap.LevelEnablerFunc(isInformational)
+	stderrEnabler := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
+		return !isInformational(lvl)
+	})
+
+	return zapcore.NewTee(
+		zapcore.NewCore(consoleEncoder, zapcore.AddSync(stdout), stdoutEnabler),
+		zapcore.NewCore(consoleEncoder, zapcore.AddSync(stderr), stderrEnabler),
+	)
+	// return zapcore.NewCore(consoleEncoder, zapcore.AddSync(stdout), c.logCfg.Verbosity)
 }
 
 func (c *Context) configureFileLog(dir string) (zapcore.Core, error) {

pkg/portercontext/context_test.go

@@ -55,8 +55,8 @@ func TestContext_LogToFile(t *testing.T) {
 
 	// Compare the human readable logs sent to stderr
 	if runtime.GOOS == "windows" {
-		c.CompareGoldenFile("testdata/expected-output-windows.txt", c.GetError())
+		c.CompareGoldenFile("testdata/expected-output-windows.txt", c.GetAllLogs())
 	} else {
-		c.CompareGoldenFile("testdata/expected-output.txt", c.GetError())
+		c.CompareGoldenFile("testdata/expected-output.txt", c.GetAllLogs())
 	}
 }

pkg/portercontext/helpers.go

@@ -28,6 +28,7 @@ type TestContext struct {
 	cleanupDirs []string
 	capturedErr *bytes.Buffer
 	capturedOut *bytes.Buffer
+	captureLogs *bytes.Buffer
 	T           *testing.T
 }
 
@@ -37,10 +38,11 @@ type TestContext struct {
 func NewTestContext(t *testing.T) *TestContext {
 	// Provide a way for tests to provide and capture stdin and stdout
 	// Copy output to the test log simultaneously, use go test -v to see the output
+	logs := &bytes.Buffer{}
 	err := &bytes.Buffer{}
-	aggErr := io.MultiWriter(err, test.Logger{T: t})
+	aggErr := io.MultiWriter(err, test.Logger{T: t}, logs)
 	out := &bytes.Buffer{}
-	aggOut := io.MultiWriter(out, test.Logger{T: t})
+	aggOut := io.MultiWriter(out, test.Logger{T: t}, logs)
 
 	innerContext := New()
 	innerContext.correlationId = "0"
@@ -64,6 +66,7 @@ func NewTestContext(t *testing.T) *TestContext {
 		Context:     innerContext,
 		capturedOut: out,
 		capturedErr: err,
+		captureLogs: logs,
 		T:           t,
 	}
 
@@ -266,6 +269,11 @@ func (c *TestContext) GetError() string {
 	return c.capturedErr.String()
 }
 
+// GetAllLogs returns all text logged both on stdout and stderr
+func (c *TestContext) GetAllLogs() string {
+	return c.captureLogs.String()
+}
+
 func (c *TestContext) ClearOutputs() {
 	c.capturedOut.Truncate(0)
 	c.capturedErr.Truncate(0)