fix: Plugins should respect verbosity

Signed-off-by: Kim Christensen <[email protected]>

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.Warn,
+		Level:      hclog.Debug,
 		JSONFormat: true,
 	})
 	c.client = plugin.NewClient(&plugin.ClientConfig{
@@ -337,6 +337,13 @@ func (c *PluginConnection) collectPluginLogs(ctx context.Context) {
 				continue
 			}
 
+			// This message is always printed when a plugin exists
+			// polluting the output. This is hardcoded in hashicorp/go-plugin.
+			// Always convert it to a debug log.
+			if msg == "plugin process exited" {
+				pluginLog["@level"] = "debug"
+			}
+
 			switch pluginLog["@level"] {
 			case "error":
 				_ = span.Error(fmt.Errorf(msg))

tests/integration/plugin_log_level_test.go

@@ -0,0 +1,67 @@
+//go:build integration
+
+package integration
+
+import (
+	"fmt"
+	"testing"
+
+	"get.porter.sh/porter/tests/tester"
+	"github.com/carolynvs/magex/shx"
+	"github.com/stretchr/testify/require"
+)
+
+func TestPluginDebugLogsVerbosityArgument(t *testing.T) {
+	testcases := []struct {
+		name              string
+		verbosity         string
+		shouldContain     bool
+		expectedPluginLog string
+	}{
+		{"plugin debug logs", "debug", true, "plugin started"},
+		{"plugin info logs doesn't contain plugin process exited", "info", false, "plugin process exited"},
+		{"plugin debug logs contains plugin process exited", "debug", true, "plugin process exited"},
+		{"plugin info logs", "info", false, "plugin started"},
+	}
+	for _, tc := range testcases {
+		test, err := tester.NewTest(t)
+		require.NoError(t, err, "test setup failed")
+		defer test.Close()
+
+		output, _ := test.RequirePorter("list", "--verbosity", tc.verbosity)
+		if tc.shouldContain {
+			require.Contains(t, output, tc.expectedPluginLog)
+		} else {
+			require.NotContains(t, output, tc.expectedPluginLog)
+		}
+	}
+}
+
+func TestPluginDebugLogsVerbosityEnvironmentVariable(t *testing.T) {
+	testcases := []struct {
+		name              string
+		verbosity         string
+		shouldContain     bool
+		expectedPluginLog string
+	}{
+		{"plugin debug logs", "debug", true, "plugin started"},
+		{"plugin info logs doesn't contain plugin process exited", "info", false, "plugin process exited"},
+		{"plugin debug logs contains plugin process exited", "debug", true, "plugin process exited"},
+		{"plugin info logs", "info", false, "plugin started"},
+	}
+	for _, tc := range testcases {
+		test, err := tester.NewTest(t)
+		require.NoError(t, err, "test setup failed")
+		defer test.Close()
+
+		output, _, err := test.RunPorterWith(func(cmd *shx.PreparedCommand) {
+			cmd.Args("list")
+			cmd.Env(fmt.Sprintf("PORTER_VERBOSITY=%s", tc.verbosity))
+		})
+		if tc.shouldContain {
+			require.Contains(t, output, tc.expectedPluginLog)
+		} else {
+			require.NotContains(t, output, tc.expectedPluginLog)
+		}
+	}
+}