fix: Plugins should respect verbosity

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

.github/workflows/porter-integration-pr.yml

@@ -184,3 +184,33 @@ jobs:
         PORTER_INTEG_FILE: upgrade_test.go
       run: go run mage.go -v TestIntegration
       shell: bash
+  plugin_log_level_test_integ:
+    runs-on: ubuntu-latest
+    steps:
+    - name: checkout
+      uses: actions/[email protected]
+    - uses: actions/setup-go@v4
+      with:
+        go-version: "${{ env.GOVERSION }}"
+        cache: true
+    - name: Set up Docker Buildx
+      uses: docker/setup-buildx-action@v3
+    - name: Cache Docker layers
+      uses: actions/cache@v3
+      with:
+        path: /tmp/.buildx-cache
+        key: ${{ runner.os }}-buildx-${{ github.sha }}
+    - name: Docker Login
+      uses: docker/[email protected]
+      with:
+        registry: ghcr.io
+        username: ${{ github.actor }}
+        password: ${{ secrets.GITHUB_TOKEN }}
+    - name: Configure Agent
+      run: go run mage.go build
+      shell: bash
+    - name: Integration Test
+      env:
+        PORTER_INTEG_FILE: plugin_log_level_test.go
+      run: go run mage.go -v TestIntegration
+      shell: bash

.github/workflows/porter-integration-release.yml

@@ -193,3 +193,63 @@ jobs:
         PORTER_INTEG_FILE: signing_test.go
       run: go run mage.go -v TestIntegration
       shell: bash
+  upgrade_test_integ:
+    runs-on: ubuntu-latest
+    steps:
+    - name: checkout
+      uses: actions/[email protected]
+    - uses: actions/setup-go@v4
+      with:
+        go-version: "${{ env.GOVERSION }}"
+        cache: true
+    - name: Set up Docker Buildx
+      uses: docker/setup-buildx-action@v3
+    - name: Cache Docker layers
+      uses: actions/cache@v3
+      with:
+        path: /tmp/.buildx-cache
+        key: ${{ runner.os }}-buildx-${{ github.sha }}
+    - name: Docker Login
+      uses: docker/[email protected]
+      with:
+        registry: ghcr.io
+        username: ${{ github.actor }}
+        password: ${{ secrets.GITHUB_TOKEN }}
+    - name: Configure Agent
+      run: go run mage.go build
+      shell: bash
+    - name: Integration Test
+      env:
+        PORTER_INTEG_FILE: upgrade_test.go
+      run: go run mage.go -v TestIntegration
+      shell: bash
+  plugin_log_level_test_integ:
+    runs-on: ubuntu-latest
+    steps:
+    - name: checkout
+      uses: actions/[email protected]
+    - uses: actions/setup-go@v4
+      with:
+        go-version: "${{ env.GOVERSION }}"
+        cache: true
+    - name: Set up Docker Buildx
+      uses: docker/setup-buildx-action@v3
+    - name: Cache Docker layers
+      uses: actions/cache@v3
+      with:
+        path: /tmp/.buildx-cache
+        key: ${{ runner.os }}-buildx-${{ github.sha }}
+    - name: Docker Login
+      uses: docker/[email protected]
+      with:
+        registry: ghcr.io
+        username: ${{ github.actor }}
+        password: ${{ secrets.GITHUB_TOKEN }}
+    - name: Configure Agent
+      run: go run mage.go build
+      shell: bash
+    - name: Integration Test
+      env:
+        PORTER_INTEG_FILE: plugin_log_level_test.go
+      run: go run mage.go -v TestIntegration
+      shell: bash

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)
+		}
+	}
+}