From 4a0df353a9a7f146da329812f0285891a5d701b3 Mon Sep 17 00:00:00 2001 From: Kim Christensen Date: Mon, 30 Sep 2024 23:17:22 +0200 Subject: [PATCH 1/2] fix: Plugins should respect verbosity Signed-off-by: Kim Christensen --- .github/workflows/porter-integration-pr.yml | 30 +++++++++ .../workflows/porter-integration-release.yml | 60 +++++++++++++++++ pkg/plugins/pluggable/connection.go | 9 ++- tests/integration/plugin_log_level_test.go | 67 +++++++++++++++++++ 4 files changed, 165 insertions(+), 1 deletion(-) create mode 100644 tests/integration/plugin_log_level_test.go diff --git a/.github/workflows/porter-integration-pr.yml b/.github/workflows/porter-integration-pr.yml index 1f17d194f..4670214e0 100644 --- 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/checkout@v4.1.0 + - 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/login-action@v3.0.0 + 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 index d2bb40643..13c514e45 100644 --- 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/checkout@v4.1.0 + - 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/login-action@v3.0.0 + 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/checkout@v4.1.0 + - 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/login-action@v3.0.0 + 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 index 51ab41123..b2b7d01d2 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.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)) diff --git a/tests/integration/plugin_log_level_test.go b/tests/integration/plugin_log_level_test.go new file mode 100644 index 000000000..36c5cd514 --- /dev/null +++ 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) + } + } +} From 96c5a13d8b491a060976f06104155f2085575c66 Mon Sep 17 00:00:00 2001 From: Kim Christensen Date: Thu, 3 Oct 2024 22:55:56 +0200 Subject: [PATCH 2/2] Only check info level logs for the process exited message Signed-off-by: Kim Christensen --- pkg/plugins/pluggable/connection.go | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/pkg/plugins/pluggable/connection.go b/pkg/plugins/pluggable/connection.go index b2b7d01d2..9605850e8 100644 --- a/pkg/plugins/pluggable/connection.go +++ b/pkg/plugins/pluggable/connection.go @@ -337,20 +337,20 @@ 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)) 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) }