Information messages should be written to stdout (#3005)

* 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>

* Change to use stdout directly

These two places it is the actual output of the command, and it should
not be suppressed by setting the log level higher than Info.

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

* Everything but errors should be written to standard output

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

* Make failing tests handle the changes to the logging configuration

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

---------

Signed-off-by: Kim Christensen <kimworking@gmail.com>
Co-authored-by: schristoff <28318173+schristoff@users.noreply.github.com>

pkg/build/dockerfile-generator_test.go

@@ -170,7 +170,7 @@ func TestPorter_generateDockerfile(t *testing.T) {
 	require.NoError(t, err)
 
 	// Verify that we logged the dockerfile contents
-	tests.RequireOutputContains(t, c.TestContext.GetError(), string(gotDockerfile), "expected the dockerfile to be printed to the logs")
+	tests.RequireOutputContains(t, c.TestContext.GetOutput(), string(gotDockerfile), "expected the dockerfile to be printed to the logs")
 	test.CompareGoldenFile(t, "testdata/buildkit.Dockerfile", string(gotDockerfile))
 
 	// Verify that we didn't generate a Dockerfile at the root of the bundle dir

pkg/manifest/manifest_test.go

@@ -310,7 +310,7 @@ func TestManifest_Validate_SchemaVersion(t *testing.T) {
 
 		// Check that a warning is printed
 		// We aren't returning an error because we want to give it a chance to work first. Later we may turn this into a hard error after people have had time to migrate.
-		assert.Contains(t, cfg.TestContext.GetError(), invalidVersionErr)
+		assert.Contains(t, cfg.TestContext.GetOutput(), invalidVersionErr)
 	})
 }
 
@@ -549,7 +549,7 @@ func TestSetDefaults(t *testing.T) {
 		err := m.validateMetadata(ctx, cfg.Config)
 		require.NoError(t, err)
 		require.Contains(t,
-			cfg.TestContext.GetError(),
+			cfg.TestContext.GetOutput(),
 			"WARNING: both registry and reference were provided; using the reference value of getporter/org/mybun:v1.2.3 for the bundle reference\n",
 		)
 

pkg/porter/credentials.go

@@ -397,7 +397,7 @@ func (p *Porter) CredentialsApply(ctx context.Context, o ApplyOptions) error {
 		return err
 	}
 
-	span.Infof("Applied %s credential set", creds)
+	fmt.Fprintf(p.Out, "Applied %s credential set\n", creds)
 	return nil
 }
 

pkg/porter/parameters.go

@@ -557,7 +557,7 @@ func (p *Porter) ParametersApply(ctx context.Context, o ApplyOptions) error {
 		return err
 	}
 
-	span.Infof("Applied %s parameter set", params)
+	fmt.Fprintf(p.Out, "Applied %s parameter set\n", params)
 	return nil
 }
 

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) {
@@ -104,7 +104,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) {
@@ -123,7 +123,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")
 
 	})
 
@@ -146,7 +146,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")
 
 	})
 
@@ -165,7 +165,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) {
@@ -185,6 +185,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.ErrorLevel && 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

@@ -58,8 +58,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)

tests/smoke/desiredstate_test.go

@@ -64,8 +64,8 @@ func TestDesiredState(t *testing.T) {
 	// This also tests out that --allow-docker-host-access is being defaulted properly from the Porter config file
 	output, stderr, err := test.RunPorter("installation", "apply", "mybuns.yaml", "--namespace", "operator")
 	require.NoError(t, err)
-	require.Contains(t, stderr, "The installation is out-of-sync, running the install action")
-	require.Contains(t, stderr, "Triggering because the installation has not completed successfully yet")
+	require.Contains(t, output, "The installation is out-of-sync, running the install action")
+	require.Contains(t, output, "Triggering because the installation has not completed successfully yet")
 	installation := test.RequireInstallationExists("operator", "mybuns")
 	require.Equal(t, "succeeded", installation.Status.ResultStatus)
 

tests/smoke/hello_test.go

@@ -29,7 +29,7 @@ func TestHelloBundle(t *testing.T) {
 	// This also does a quick regression test to validate that we can change the verbosity to a different value than what is in the config file and have it respected
 	_, output := test.RequirePorter("plugins", "install", "-f", "plugins.yaml", "--verbosity=info")
 	require.Contains(t, output, "installed azure plugin", "expected to see plugin successfully installed")
-	require.NotContainsf(t, output, "Downloading https://cdn.porter.sh/plugins/atom.xml", "Debug information should not have been printed because verbosity is set to info")
+	require.Containsf(t, output, "Downloading https://cdn.porter.sh/plugins/atom.xml", "Debug information should be printed because verbosity is set to info")
 
 	// Run a stateless action before we install and make sure nothing is persisted
 	_, output = test.RequirePorter("invoke", testdata.MyBuns, "--action=dry-run", "--reference", testdata.MyBunsRef, "-c=mybuns")

tests/tester/helpers.go

@@ -55,7 +55,7 @@ func (t Tester) MakeTestBundle(name string, ref string) {
 }
 
 func (t Tester) ShowInstallation(namespace string, name string) (porter.DisplayInstallation, error) {
-	stdout, _, err := t.RunPorter("show", name, "--namespace", namespace, "--output=json")
+	stdout, _, err := t.RunPorter("show", name, "--namespace", namespace, "--output=json", "--verbosity=info")
 	if err != nil {
 		return porter.DisplayInstallation{}, err
 	}
@@ -91,6 +91,7 @@ func (t Tester) ListInstallations(allNamespaces bool, namespace string, name str
 		"list",
 		"--output=json",
 		"--name", name,
+		"--verbosity=info",
 	}
 	if allNamespaces {
 		args = append(args, "--all-namespaces")