From ddf7d68def645adc506c7a8516ff363692270eaa Mon Sep 17 00:00:00 2001 From: Kim Christensen <2461567+kichristensen@users.noreply.github.com> Date: Sun, 4 Aug 2024 22:47:45 +0200 Subject: [PATCH] Correct plugin logging (#3185) * The plugin logger should use verbosity level The log level is meant to be used only for log files. Signed-off-by: Kim Christensen * Correctly detect log level from plugin logs The constants used before was numbers, causing the writing to always fall back to writing as debug Signed-off-by: Kim Christensen * Correct the documentation Signed-off-by: Kim Christensen * Do not log information messages from the plugin infrastructure Signed-off-by: Kim Christensen --------- Signed-off-by: Kim Christensen Co-authored-by: schristoff <28318173+schristoff@users.noreply.github.com> --- .../docs/configuration/configuration.md | 2 +- .../intro-configuration.md | 2 +- pkg/plugins/pluggable/connection.go | 8 +-- pkg/portercontext/context_test.go | 68 +++++++++++++++++++ pkg/portercontext/plugins.go | 2 +- 5 files changed, 75 insertions(+), 7 deletions(-) diff --git a/docs/content/docs/configuration/configuration.md b/docs/content/docs/configuration/configuration.md index bfb4022f7..70be7b547 100644 --- a/docs/content/docs/configuration/configuration.md +++ b/docs/content/docs/configuration/configuration.md @@ -256,7 +256,7 @@ The following log settings are available: | ---------------- | ----------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | logs.log-to-file | PORTER_LOGS_LOG_TO_FILE | Specifies if a logfile should be written for each command. | | logs.structured | PORTER_LOGS_STRUCTURED | Specifies if the logs printed to the console should include a timestamp and log level | -| logs.level | PORTER_LOGS_LEVEL | Filters the logs to the specified level and higher. The log level controls both the logs written to file, and the logs output to the console when porter is run. Allowed values are: debug, info, warn, error. | +| logs.level | PORTER_LOGS_LEVEL | Filters the logs to the specified level and higher. The log level controls the logs written to file when porter is run. Allowed values are: debug, info, warn, error. | #### Telemetry diff --git a/docs/content/docs/introduction/concepts-and-components/intro-configuration.md b/docs/content/docs/introduction/concepts-and-components/intro-configuration.md index dfd0ee019..d75f4f9f3 100644 --- a/docs/content/docs/introduction/concepts-and-components/intro-configuration.md +++ b/docs/content/docs/introduction/concepts-and-components/intro-configuration.md @@ -232,7 +232,7 @@ The following log settings are available: | ---------------- | ----------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | | logs.log-to-file | PORTER_LOGS_LOG_TO_FILE | Specifies if a logfile should be written for each command. | | logs.structured | PORTER_LOGS_STRUCTURED | Specifies if the logs printed to the console should include a timestamp and log level | -| logs.level | PORTER_LOGS_LEVEL | Filters the logs to the specified level and higher. The log level controls both the logs written to file, and the logs output to the console when porter is run. Allowed values are: debug, info, warn, error. | +| logs.level | PORTER_LOGS_LEVEL | Filters the logs to the specified level and higher. The log level controls the logs written to file when porter is run. Allowed values are: debug, info, warn, error. | #### Telemetry diff --git a/pkg/plugins/pluggable/connection.go b/pkg/plugins/pluggable/connection.go index d11b4c5bb..51ab41123 100644 --- a/pkg/plugins/pluggable/connection.go +++ b/pkg/plugins/pluggable/connection.go @@ -122,7 +122,7 @@ func (c *PluginConnection) Start(ctx context.Context, pluginCfg io.Reader) error logger := hclog.New(&hclog.LoggerOptions{ Name: "porter", Output: c.logsWriter, - Level: hclog.Debug, + Level: hclog.Warn, JSONFormat: true, }) c.client = plugin.NewClient(&plugin.ClientConfig{ @@ -338,11 +338,11 @@ func (c *PluginConnection) collectPluginLogs(ctx context.Context) { } switch pluginLog["@level"] { - case hclog.Error: + case "error": _ = span.Error(fmt.Errorf(msg)) - case hclog.Warn: + case "warn": span.Warn(msg) - case hclog.Info: + case "info": span.Infof(msg) default: span.Debug(msg) diff --git a/pkg/portercontext/context_test.go b/pkg/portercontext/context_test.go index 0b66dc4f1..6b60896b5 100644 --- a/pkg/portercontext/context_test.go +++ b/pkg/portercontext/context_test.go @@ -4,6 +4,7 @@ import ( "context" "errors" "runtime" + "strings" "testing" "github.com/stretchr/testify/assert" @@ -63,3 +64,70 @@ func TestContext_LogToFile(t *testing.T) { c.CompareGoldenFile("testdata/expected-output.txt", c.GetAllLogs()) } } + +func TestContext_PluginVerbosityLevel(t *testing.T) { + testcases := []struct { + name string + verbosityLevel zapcore.Level + wantNumberOfLogLines int + }{ + {"debug level", zapcore.DebugLevel, 4}, + {"info level", zapcore.InfoLevel, 3}, + {"warn level", zapcore.WarnLevel, 2}, + {"error level", zapcore.ErrorLevel, 1}, + } + + for _, tc := range testcases { + t.Run(tc.name, func(t *testing.T) { + c := NewTestContext(t) + c.IsInternalPlugin = true + c.ConfigureLogging(context.Background(), LogConfiguration{ + Verbosity: tc.verbosityLevel, + }) + + _, log := c.StartRootSpan(context.Background(), t.Name()) + log.Debug("debug log") + log.Info("info log") + log.Warn("warning log") + //throwing away error here because it is a test + // we do not return it + _ = log.Error(errors.New("error log")) + + log.EndSpan() + c.Close() + + lines := strings.Split(c.captureLogs.String(), "\n") + lines = lines[:len(lines)-1] // Remove last line as it will be empty + require.Len(t, lines, tc.wantNumberOfLogLines) + }) + } +} + +func TestContext_PluginLogCollectorLevel(t *testing.T) { + c := NewTestContext(t) + c.IsInternalPlugin = true + c.ConfigureLogging(context.Background(), LogConfiguration{ + Verbosity: zapcore.DebugLevel, + }) + + _, log := c.StartRootSpan(context.Background(), t.Name()) + log.Debug("debug log") + log.Info("info log") + log.Warn("warning log") + //throwing away error here because it is a test + // we do not return it + _ = log.Error(errors.New("error log")) + + log.EndSpan() + c.Close() + + lines := strings.Split(c.captureLogs.String(), "\n") + require.Contains(t, lines[0], "\"@level\":\"debug\"") + require.Contains(t, lines[0], "\"@message\":\"debug log\"") + require.Contains(t, lines[1], "\"@level\":\"info\"") + require.Contains(t, lines[1], "\"@message\":\"info log\"") + require.Contains(t, lines[2], "\"@level\":\"warn\"") + require.Contains(t, lines[2], "\"@message\":\"warning log\"") + require.Contains(t, lines[3], "\"@level\":\"error\"") + require.Contains(t, lines[3], "\"@message\":\"error log\"") +} diff --git a/pkg/portercontext/plugins.go b/pkg/portercontext/plugins.go index 25708af8f..190b88369 100644 --- a/pkg/portercontext/plugins.go +++ b/pkg/portercontext/plugins.go @@ -22,7 +22,7 @@ func (c *Context) makePluginLogger(pluginKey string, cfg LogConfiguration) zapco enc := zap.NewProductionEncoderConfig() jsonEncoder := zapcore.NewJSONEncoder(enc) - return zapcore.NewCore(jsonEncoder, zapcore.AddSync(pluginLogger), cfg.LogLevel) + return zapcore.NewCore(jsonEncoder, zapcore.AddSync(pluginLogger), cfg.Verbosity) } // Accepts zap log commands and translates them to a format that hclog understands