Correct plugin logging (getporter#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 <[email protected]> * 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 <[email protected]> * Correct the documentation Signed-off-by: Kim Christensen <[email protected]> * Do not log information messages from the plugin infrastructure Signed-off-by: Kim Christensen <[email protected]> --------- Signed-off-by: Kim Christensen <[email protected]> Co-authored-by: schristoff <[email protected]> Signed-off-by: John Cudd <[email protected]>
jmcudd · Aug 19, 2024 · ba06c9d · ba06c9d
1 parent 6292541
commit ba06c9d
Show file tree

Hide file tree

Showing 5 changed files with 75 additions and 7 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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