From 158fba5d9b1ce5b30b3e17a50178962abc61cc8f Mon Sep 17 00:00:00 2001 From: Kim Christensen Date: Thu, 29 Feb 2024 14:52:04 +0100 Subject: [PATCH 1/4] 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 --- pkg/porter/reconcile_test.go | 14 +++++++------- pkg/portercontext/context.go | 25 +++++++++++++++++++++++-- pkg/portercontext/context_test.go | 4 ++-- pkg/portercontext/helpers.go | 12 ++++++++++-- 4 files changed, 42 insertions(+), 13 deletions(-) diff --git a/pkg/porter/reconcile_test.go b/pkg/porter/reconcile_test.go index 426315029..0e914dc02 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) { @@ -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") }) } diff --git a/pkg/portercontext/context.go b/pkg/portercontext/context.go index 45b13d6b2..09ef9668e 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.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) { diff --git a/pkg/portercontext/context_test.go b/pkg/portercontext/context_test.go index f7b4e8516..bcf4edf47 100644 --- a/pkg/portercontext/context_test.go +++ b/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()) } } diff --git a/pkg/portercontext/helpers.go b/pkg/portercontext/helpers.go index 3e8e14097..8d7d0d466 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) From 13221dd2fd8b3a822c6c53102780ea718d919c80 Mon Sep 17 00:00:00 2001 From: Kim Christensen Date: Sat, 4 May 2024 22:44:50 +0200 Subject: [PATCH 2/4] 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 --- pkg/porter/credentials.go | 2 +- pkg/porter/parameters.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/pkg/porter/credentials.go b/pkg/porter/credentials.go index 8dcf261b1..5a28d5fcc 100644 --- a/pkg/porter/credentials.go +++ b/pkg/porter/credentials.go @@ -393,7 +393,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 c2f27445f..2a026c130 100644 --- a/pkg/porter/parameters.go +++ b/pkg/porter/parameters.go @@ -553,7 +553,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 } From c2001be65ff8a7348c67c9252962220a32f0fe1d Mon Sep 17 00:00:00 2001 From: Kim Christensen Date: Sat, 4 May 2024 22:47:18 +0200 Subject: [PATCH 3/4] Everything but errors should be written to standard output Signed-off-by: Kim Christensen --- pkg/portercontext/context.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/portercontext/context.go b/pkg/portercontext/context.go index 09ef9668e..2962763e5 100644 --- a/pkg/portercontext/context.go +++ b/pkg/portercontext/context.go @@ -237,7 +237,7 @@ func (c *Context) makeConsoleLogger() zapcore.Core { consoleEncoder := zapcore.NewConsoleEncoder(encoding) isInformational := func(lvl zapcore.Level) bool { - return lvl >= zapcore.InfoLevel && lvl < zapcore.WarnLevel && lvl >= c.logCfg.Verbosity + return lvl < zapcore.ErrorLevel && lvl >= c.logCfg.Verbosity } stdoutEnabler := zap.LevelEnablerFunc(isInformational) stderrEnabler := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { From 75c7a7c5806d869c0ece4f7732a04bb07c183072 Mon Sep 17 00:00:00 2001 From: Kim Christensen Date: Tue, 7 May 2024 11:40:51 +0200 Subject: [PATCH 4/4] Make failing tests handle the changes to the logging configuration Signed-off-by: Kim Christensen --- pkg/build/dockerfile-generator_test.go | 2 +- pkg/manifest/manifest_test.go | 4 ++-- tests/smoke/desiredstate_test.go | 4 ++-- tests/smoke/hello_test.go | 2 +- tests/tester/helpers.go | 3 ++- 5 files changed, 8 insertions(+), 7 deletions(-) diff --git a/pkg/build/dockerfile-generator_test.go b/pkg/build/dockerfile-generator_test.go index 54cdbcf26..bcdaac324 100644 --- a/pkg/build/dockerfile-generator_test.go +++ b/pkg/build/dockerfile-generator_test.go @@ -166,7 +166,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/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")