From faa098403ba65942c1dccd2b7b7439d2fdd31cb2 Mon Sep 17 00:00:00 2001 From: Kim Christensen <2461567+kichristensen@users.noreply.github.com> Date: Tue, 21 May 2024 23:46:22 +0200 Subject: [PATCH] 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 * 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 * Everything but errors should be written to standard output Signed-off-by: Kim Christensen * Make failing tests handle the changes to the logging configuration Signed-off-by: Kim Christensen --------- Signed-off-by: Kim Christensen Co-authored-by: schristoff <28318173+schristoff@users.noreply.github.com> --- pkg/build/dockerfile-generator_test.go | 2 +- pkg/manifest/manifest_test.go | 4 ++-- pkg/porter/credentials.go | 2 +- pkg/porter/parameters.go | 2 +- pkg/porter/reconcile_test.go | 14 +++++++------- pkg/portercontext/context.go | 25 +++++++++++++++++++++++-- pkg/portercontext/context_test.go | 4 ++-- pkg/portercontext/helpers.go | 12 ++++++++++-- tests/smoke/desiredstate_test.go | 4 ++-- tests/smoke/hello_test.go | 2 +- tests/tester/helpers.go | 3 ++- 11 files changed, 52 insertions(+), 22 deletions(-) diff --git a/pkg/build/dockerfile-generator_test.go b/pkg/build/dockerfile-generator_test.go index fadedaebb..1aac43613 100644 --- a/pkg/build/dockerfile-generator_test.go +++ b/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 diff --git a/pkg/manifest/manifest_test.go b/pkg/manifest/manifest_test.go index 03af35007..b30bf6f4b 100644 --- a/pkg/manifest/manifest_test.go +++ b/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", ) diff --git a/pkg/porter/credentials.go b/pkg/porter/credentials.go index ea3b3e775..441eba7be 100644 --- a/pkg/porter/credentials.go +++ b/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 } diff --git a/pkg/porter/parameters.go b/pkg/porter/parameters.go index 18e086593..4d035a3ef 100644 --- a/pkg/porter/parameters.go +++ b/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 } diff --git a/pkg/porter/reconcile_test.go b/pkg/porter/reconcile_test.go index 385a8a6b8..8a1243d90 100644 --- a/pkg/porter/reconcile_test.go +++ b/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") }) } diff --git a/pkg/portercontext/context.go b/pkg/portercontext/context.go index 45b13d6b2..2962763e5 100644 --- a/pkg/portercontext/context.go +++ b/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) { diff --git a/pkg/portercontext/context_test.go b/pkg/portercontext/context_test.go index 4603349a6..0b66dc4f1 100644 --- a/pkg/portercontext/context_test.go +++ b/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()) } } diff --git a/pkg/portercontext/helpers.go b/pkg/portercontext/helpers.go index 8a3baa3fb..485e30a25 100644 --- a/pkg/portercontext/helpers.go +++ b/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) diff --git a/tests/smoke/desiredstate_test.go b/tests/smoke/desiredstate_test.go index cbde9ef56..675c5ebd3 100644 --- a/tests/smoke/desiredstate_test.go +++ b/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) diff --git a/tests/smoke/hello_test.go b/tests/smoke/hello_test.go index 485457000..0d80f3ed3 100644 --- a/tests/smoke/hello_test.go +++ b/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") diff --git a/tests/tester/helpers.go b/tests/tester/helpers.go index f5290fbd9..10d3fb92c 100644 --- a/tests/tester/helpers.go +++ b/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")