Plugins should respect verbosity (#3226)

* fix: Plugins should respect verbosity Signed-off-by: Kim Christensen <[email protected]> --------- Signed-off-by: Kim Christensen <[email protected]>
getporter · Oct 4, 2024 · 0f4d976 · 0f4d976
1 parent 3fb92b7
commit 0f4d976
Show file tree

Hide file tree

Showing 4 changed files with 166 additions and 2 deletions.
diff --git a/.github/workflows/porter-integration-pr.yml b/.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
diff --git a/.github/workflows/porter-integration-release.yml b/.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
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.Warn,
+		Level:      hclog.Debug,
 		JSONFormat: true,
 	})
 	c.client = plugin.NewClient(&plugin.ClientConfig{
@@ -343,7 +343,14 @@ func (c *PluginConnection) collectPluginLogs(ctx context.Context) {
 			case "warn":
 				span.Warn(msg)
 			case "info":
-				span.Infof(msg)
+				// 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" {
+					span.Debug(msg) // Log at debug level instead of info
+				} else {
+					span.Info(msg)
+				}
 			default:
 				span.Debug(msg)
 			}

diff --git a/tests/integration/plugin_log_level_test.go b/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)
+		}
+	}
+}