From 898f0dcc996c01f19b800ccaff1d2082fb422cd5 Mon Sep 17 00:00:00 2001 From: Josh Duffney Date: Tue, 9 Jan 2024 21:01:02 +0000 Subject: [PATCH 01/10] handle stderr and stdout messages from plugin Fixes #1022 --- pkg/common/plugin/exec.go | 49 +++++++++++++++++++++++++++++-- plugins/verifier/sample/sample.go | 8 +++++ 2 files changed, 55 insertions(+), 2 deletions(-) diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go index 27693172c..d18be15d7 100644 --- a/pkg/common/plugin/exec.go +++ b/pkg/common/plugin/exec.go @@ -16,10 +16,13 @@ limitations under the License. package plugin import ( + "bufio" "bytes" "context" + "encoding/json" "fmt" "io" + "os" "os/exec" "strings" "time" @@ -96,10 +99,52 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, // stdout and stderr for some reason. Ignore failures as stderr is // only informational. if e.Stderr != nil && stderr.Len() > 0 { - _, _ = stderr.WriteTo(e.Stderr) + scanner := bufio.NewScanner(stderr) + for scanner.Scan() { + line := scanner.Text() + + switch { + case strings.HasPrefix(strings.ToLower(line), "info"): + line = strings.Replace(line, "info: ", "", -1) + logrus.Infof("[Plugin] %s", line) + case strings.HasPrefix(strings.ToLower(line), "warn"): + line = strings.Replace(line, "warn: ", "", -1) + logrus.Warnf("[Plugin] %s", line) + case strings.HasPrefix(strings.ToLower(line), "debug"): + line = strings.Replace(line, "debug: ", "", -1) + logrus.Debugf("[Plugin] %s", line) + default: + fmt.Fprintf(os.Stderr, "[Plugin] %s,", line) + } + } + // TODO: Should this be removed since the msgs are processed? + //_, _ = stderr.WriteTo(e.Stderr) + } + + var obj interface{} + var resultsBuffer bytes.Buffer + + scanner := bufio.NewScanner(stdout) + for scanner.Scan() { + line := scanner.Text() + if strings.Contains(line, "{") { + + err := json.NewDecoder(strings.NewReader(line)).Decode(&obj) + if err != nil { + continue + } + + jsonString, _ := json.Marshal(obj) + resultsBuffer.WriteString(string(jsonString)) + + } else { + fmt.Printf("[Plugin] %s \n", line) + } } + // TODO stdout reader - return stdout.Bytes(), nil + return resultsBuffer.Bytes(), nil + } func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error { diff --git a/plugins/verifier/sample/sample.go b/plugins/verifier/sample/sample.go index 51ce8f658..0e8c9815c 100644 --- a/plugins/verifier/sample/sample.go +++ b/plugins/verifier/sample/sample.go @@ -18,6 +18,7 @@ package main import ( "encoding/json" "fmt" + "os" "github.com/deislabs/ratify/pkg/common" "github.com/deislabs/ratify/pkg/ocispecs" @@ -37,7 +38,14 @@ type PluginInputConfig struct { } func main() { + // send info and debug messages to stderr + fmt.Fprintln(os.Stderr, "info: initialized plugin") + fmt.Fprintf(os.Stderr, "debug: plugin %s %s \n", "sample", "1.0.0") + skel.PluginMain("sample", "1.0.0", VerifyReference, []string{"1.0.0"}) + + // send message to stdout + fmt.Fprintln(os.Stdout, "finished executing plugin...") } func parseInput(stdin []byte) (*PluginConfig, error) { From e4cf215315a559f27b287d81d38a7200042e0637 Mon Sep 17 00:00:00 2001 From: Josh Duffney Date: Wed, 10 Jan 2024 19:58:09 +0000 Subject: [PATCH 02/10] remove unnecessary newlines --- pkg/common/plugin/exec.go | 3 --- 1 file changed, 3 deletions(-) diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go index d18be15d7..fd85187ae 100644 --- a/pkg/common/plugin/exec.go +++ b/pkg/common/plugin/exec.go @@ -128,7 +128,6 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, for scanner.Scan() { line := scanner.Text() if strings.Contains(line, "{") { - err := json.NewDecoder(strings.NewReader(line)).Decode(&obj) if err != nil { continue @@ -136,7 +135,6 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, jsonString, _ := json.Marshal(obj) resultsBuffer.WriteString(string(jsonString)) - } else { fmt.Printf("[Plugin] %s \n", line) } @@ -144,7 +142,6 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, // TODO stdout reader return resultsBuffer.Bytes(), nil - } func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error { From 6f4c58bfd36fcd0a5e9e33e26b97564463cf80de Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Thu, 25 Jan 2024 19:32:35 +0000 Subject: [PATCH 03/10] Add Plugin componentType --- internal/logger/logger.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/internal/logger/logger.go b/internal/logger/logger.go index 32f355224..15a5a78d7 100644 --- a/internal/logger/logger.go +++ b/internal/logger/logger.go @@ -72,6 +72,8 @@ const ( PolicyProvider componentType = "policyProvider" // Verifier is the component type for verifier. Verifier componentType = "verifier" + // Plugin is the component type for plugin. + Plugin componentType = "plugin" traceIDHeaderName = "traceIDHeaderName" ) From e8d08fe5abbf0eaad506a65b082c7b5e42cce1e1 Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Thu, 25 Jan 2024 19:35:52 +0000 Subject: [PATCH 04/10] customer logger for plugin output --- pkg/common/plugin/logger/logger.go | 55 ++++++++++++++++++++++++++++++ 1 file changed, 55 insertions(+) create mode 100644 pkg/common/plugin/logger/logger.go diff --git a/pkg/common/plugin/logger/logger.go b/pkg/common/plugin/logger/logger.go new file mode 100644 index 000000000..7095f33e3 --- /dev/null +++ b/pkg/common/plugin/logger/logger.go @@ -0,0 +1,55 @@ +package logger + +import ( + "fmt" + "io" + "log" + "os" +) + +type Logger struct { + infoLogger *log.Logger + debugLogger *log.Logger + warnLogger *log.Logger +} + +func NewLogger() *Logger { + return &Logger{ + infoLogger: log.New(os.Stderr, "INFO: ", 0), + debugLogger: log.New(os.Stderr, "DEBUG: ", 0), + warnLogger: log.New(os.Stderr, "WARN: ", 0), + } +} + +func (l *Logger) SetOutput(out io.Writer) { + l.infoLogger.SetOutput(out) + l.debugLogger.SetOutput(out) + l.warnLogger.SetOutput(out) +} + +func (l *Logger) Info(message string) { + l.infoLogger.Println(message) +} + +func (l *Logger) Infof(format string, args ...interface{}) { + message := fmt.Sprintf(format, args...) + l.infoLogger.Println(message) +} + +func (l *Logger) Debug(message string) { + l.debugLogger.Println(message) +} + +func (l *Logger) Debugf(format string, args ...interface{}) { + message := fmt.Sprintf(format, args...) + l.debugLogger.Println(message) +} + +func (l *Logger) Warn(message string) { + l.warnLogger.Println(message) +} + +func (l *Logger) Warnf(format string, args ...interface{}) { + message := fmt.Sprintf(format, args...) + l.warnLogger.Println(message) +} From b43a4bc05935a039ae0afe6877ec4950ea236565 Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Thu, 25 Jan 2024 19:37:29 +0000 Subject: [PATCH 05/10] mod: replace fmt output with pluginlogger --- plugins/verifier/sample/sample.go | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/plugins/verifier/sample/sample.go b/plugins/verifier/sample/sample.go index 0e8c9815c..cc8317b88 100644 --- a/plugins/verifier/sample/sample.go +++ b/plugins/verifier/sample/sample.go @@ -21,6 +21,7 @@ import ( "os" "github.com/deislabs/ratify/pkg/common" + "github.com/deislabs/ratify/pkg/common/plugin/logger" "github.com/deislabs/ratify/pkg/ocispecs" "github.com/deislabs/ratify/pkg/referrerstore" "github.com/deislabs/ratify/pkg/verifier" @@ -38,14 +39,18 @@ type PluginInputConfig struct { } func main() { - // send info and debug messages to stderr - fmt.Fprintln(os.Stderr, "info: initialized plugin") - fmt.Fprintf(os.Stderr, "debug: plugin %s %s \n", "sample", "1.0.0") + // create a plugin logger + pluginlogger := logger.NewLogger() + + // output to stderr + pluginlogger.Info("initialized plugin") + pluginlogger.Debugf("plugin %s %s", "sample", "1.0.0") skel.PluginMain("sample", "1.0.0", VerifyReference, []string{"1.0.0"}) - // send message to stdout - fmt.Fprintln(os.Stdout, "finished executing plugin...") + // set output to stdout + pluginlogger.SetOutput(os.Stdout) + pluginlogger.Warn("example warning message...") } func parseInput(stdin []byte) (*PluginConfig, error) { From 3da76229aff21f6dec0da0e8c86e9fd12acf4b38 Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Thu, 25 Jan 2024 19:39:07 +0000 Subject: [PATCH 06/10] mod: extracted scan loops and log messages with internal ratify logger --- pkg/common/plugin/exec.go | 104 ++++++++++++++++++++------------- pkg/common/plugin/exec_test.go | 63 ++++++++++++++++++++ 2 files changed, 126 insertions(+), 41 deletions(-) diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go index fd85187ae..68ec8777d 100644 --- a/pkg/common/plugin/exec.go +++ b/pkg/common/plugin/exec.go @@ -27,6 +27,7 @@ import ( "strings" "time" + "github.com/deislabs/ratify/internal/logger" "github.com/sirupsen/logrus" ) @@ -35,6 +36,10 @@ const ( waitDuration = time.Second ) +var logOpt = logger.Option{ + ComponentType: logger.Plugin, +} + // Executor is an interface that defines methods to lookup a plugin and execute it. type Executor interface { // ExecutePlugin executes the plugin with the given parameters @@ -95,53 +100,39 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, return nil, e.pluginErr(err, stdout.Bytes(), stderr.Bytes()) } - // Copy stderr to caller's buffer in case plugin printed to both - // stdout and stderr for some reason. Ignore failures as stderr is - // only informational. - if e.Stderr != nil && stderr.Len() > 0 { - scanner := bufio.NewScanner(stderr) - for scanner.Scan() { - line := scanner.Text() - - switch { - case strings.HasPrefix(strings.ToLower(line), "info"): - line = strings.Replace(line, "info: ", "", -1) - logrus.Infof("[Plugin] %s", line) - case strings.HasPrefix(strings.ToLower(line), "warn"): - line = strings.Replace(line, "warn: ", "", -1) - logrus.Warnf("[Plugin] %s", line) - case strings.HasPrefix(strings.ToLower(line), "debug"): - line = strings.Replace(line, "debug: ", "", -1) - logrus.Debugf("[Plugin] %s", line) - default: - fmt.Fprintf(os.Stderr, "[Plugin] %s,", line) - } + pluginOutputJson, pluginOutputMsgs := parsePluginOutput(stdout, stderr) + + for _, msg := range pluginOutputMsgs { + msg := strings.ToLower(msg) + switch { + case strings.HasPrefix(msg, "info"): + msg = strings.Replace(msg, "info: ", "", -1) + logger.GetLogger(ctx, logOpt).Infof("[Plugin] %s", msg) + case strings.HasPrefix(msg, "warn"): + msg = strings.Replace(msg, "warn: ", "", -1) + logger.GetLogger(ctx, logOpt).Warnf("[Plugin] %s", msg) + case strings.HasPrefix(msg, "debug"): + msg = strings.Replace(msg, "debug: ", "", -1) + logger.GetLogger(ctx, logOpt).Debugf("[Plugin] %s", msg) + default: + fmt.Fprintf(os.Stderr, "[Plugin] %s,", msg) } - // TODO: Should this be removed since the msgs are processed? - //_, _ = stderr.WriteTo(e.Stderr) } - var obj interface{} - var resultsBuffer bytes.Buffer - - scanner := bufio.NewScanner(stdout) - for scanner.Scan() { - line := scanner.Text() - if strings.Contains(line, "{") { - err := json.NewDecoder(strings.NewReader(line)).Decode(&obj) - if err != nil { - continue - } + // Copy stderr to caller's buffer in case plugin printed to both + // stdout and stderr for some reason. Ignore failures as stderr is + // only informational. + // if e.Stderr != nil && stderr.Len() > 0 { + // processStdError(ctx, stderr) + // //outputPluginMessage(ctx, stderr.String()) + // } - jsonString, _ := json.Marshal(obj) - resultsBuffer.WriteString(string(jsonString)) - } else { - fmt.Printf("[Plugin] %s \n", line) - } - } + //TODO output stdout plugin messages + // jsonBytes := processStdOut(ctx, stdout) // TODO stdout reader - return resultsBuffer.Bytes(), nil + //return processStdOut(ctx, stdout), nil + return pluginOutputJson, nil } func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error { @@ -160,3 +151,34 @@ func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error { func (e *DefaultExecutor) FindInPaths(plugin string, paths []string) (string, error) { return FindInPaths(plugin, paths) } + +func parsePluginOutput(stdout *bytes.Buffer, stderr *bytes.Buffer) ([]byte, []string) { + var obj interface{} + var outputBuffer bytes.Buffer + var jsonBuffer bytes.Buffer + var messages []string + + // Combine stderr and stdout + outputBuffer.Write(stderr.Bytes()) + outputBuffer.Write(stdout.Bytes()) + + scanner := bufio.NewScanner(&outputBuffer) + for scanner.Scan() { + line := scanner.Text() + // Assumes a single JSON object is returned somewhere in the output + // does not handle multiple JSON objects + if strings.Contains(line, "{") { + err := json.NewDecoder(strings.NewReader(line)).Decode(&obj) + if err != nil { + continue + } + + jsonString, _ := json.Marshal(obj) + jsonBuffer.WriteString(string(jsonString)) + } else { + messages = append(messages, line) + } + } + + return jsonBuffer.Bytes(), messages +} diff --git a/pkg/common/plugin/exec_test.go b/pkg/common/plugin/exec_test.go index 95847c6d4..3a506ada4 100644 --- a/pkg/common/plugin/exec_test.go +++ b/pkg/common/plugin/exec_test.go @@ -16,6 +16,7 @@ limitations under the License. package plugin import ( + "bytes" "strings" "testing" ) @@ -44,3 +45,65 @@ func TestPluginErr(t *testing.T) { t.Fatalf("error msg should contain stdErr msg, actual '%v'", err.Error()) } } + +func TestParsePluginOutput_EmptyBuffers(t *testing.T) { + stdOut := bytes.NewBufferString("") + stdErr := bytes.NewBufferString("") + + json, messages := parsePluginOutput(stdOut, stdErr) + + if len(messages) != 0 { + t.Fatalf("unexpected messages, expected 0, got %d", len(messages)) + } + + if len(json) != 0 { + t.Fatalf("unexpected json, expected empty, got '%s'", json) + } +} + +func TestParsePluginOutput_StdErrNonEmpty(t *testing.T) { + stdOut := bytes.NewBufferString("") + stdErr := bytes.NewBufferString("This is a string from std err\n") + + json, messages := parsePluginOutput(stdOut, stdErr) + + if len(messages) != 1 { + t.Fatalf("unexpected messages, expected 1, got %d", len(messages)) + } + + if len(json) != 0 { + t.Fatalf("unexpected json, expected empty, got '%s'", json) + } +} + +func TestParsePluginOutput_StdOutNonEmpty(t *testing.T) { + stdOut := bytes.NewBufferString("{\"key\":\"value\"}\n") + stdErr := bytes.NewBufferString("") + + expectedJSON := []byte(`{"key":"value"}`) + + json, messages := parsePluginOutput(stdOut, stdErr) + + if len(messages) != 0 { + t.Fatalf("unexpected messages, expected 0, got %d", len(messages)) + } + + if !bytes.Equal(expectedJSON, json) { + t.Fatalf("unexpected json, expected '%s', got '%s'", expectedJSON, json) + } +} + +func TestParsePluginOutput_InvalidJson(t *testing.T) { + stdOut := bytes.NewBufferString("This is not a valid json\n") + stdErr := bytes.NewBufferString("") + + json, messages := parsePluginOutput(stdOut, stdErr) + + if len(messages) != 1 { + t.Fatalf("unexpected messages, expected 1, got %d", len(messages)) + } + + if len(json) != 0 { + t.Fatalf("unexpected json, expected empty, got '%s'", json) + } +} From 734c7af6042d57fa42888a6e71c5b7d4e07d11db Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Fri, 26 Jan 2024 15:23:36 +0000 Subject: [PATCH 07/10] Mod: rename pluginOutputjson to pluginOutputJSON --- pkg/common/plugin/exec.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go index 68ec8777d..3805a3ddb 100644 --- a/pkg/common/plugin/exec.go +++ b/pkg/common/plugin/exec.go @@ -100,7 +100,7 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, return nil, e.pluginErr(err, stdout.Bytes(), stderr.Bytes()) } - pluginOutputJson, pluginOutputMsgs := parsePluginOutput(stdout, stderr) + pluginOutputJSON, pluginOutputMsgs := parsePluginOutput(stdout, stderr) for _, msg := range pluginOutputMsgs { msg := strings.ToLower(msg) @@ -132,7 +132,7 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, // TODO stdout reader //return processStdOut(ctx, stdout), nil - return pluginOutputJson, nil + return pluginOutputJSON, nil } func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error { From 229832378872748da379662563f544c0a6ca5acb Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Fri, 26 Jan 2024 15:23:57 +0000 Subject: [PATCH 08/10] Mod: add license header --- pkg/common/plugin/logger/logger.go | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/pkg/common/plugin/logger/logger.go b/pkg/common/plugin/logger/logger.go index 7095f33e3..70f5e740f 100644 --- a/pkg/common/plugin/logger/logger.go +++ b/pkg/common/plugin/logger/logger.go @@ -1,3 +1,18 @@ +/* +Copyright The Ratify Authors. +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + +http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + package logger import ( From 56295fde4c40e5436b3493fb1bfa4722f53194db Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Tue, 30 Jan 2024 15:38:06 +0000 Subject: [PATCH 09/10] Mod: clean up comments --- pkg/common/plugin/exec.go | 13 ------------- 1 file changed, 13 deletions(-) diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go index 3805a3ddb..bb12f18ae 100644 --- a/pkg/common/plugin/exec.go +++ b/pkg/common/plugin/exec.go @@ -119,19 +119,6 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, } } - // Copy stderr to caller's buffer in case plugin printed to both - // stdout and stderr for some reason. Ignore failures as stderr is - // only informational. - // if e.Stderr != nil && stderr.Len() > 0 { - // processStdError(ctx, stderr) - // //outputPluginMessage(ctx, stderr.String()) - // } - - //TODO output stdout plugin messages - // jsonBytes := processStdOut(ctx, stdout) - - // TODO stdout reader - //return processStdOut(ctx, stdout), nil return pluginOutputJSON, nil } From 3757608fb600ab30e8c02be673b52f698a0e106b Mon Sep 17 00:00:00 2001 From: Joshua Duffney Date: Thu, 1 Feb 2024 17:33:44 +0000 Subject: [PATCH 10/10] Mod: include stdout stderr behavior comments --- pkg/common/plugin/exec.go | 1 + plugins/verifier/sample/sample.go | 5 +++-- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/pkg/common/plugin/exec.go b/pkg/common/plugin/exec.go index bb12f18ae..9cbfdd065 100644 --- a/pkg/common/plugin/exec.go +++ b/pkg/common/plugin/exec.go @@ -102,6 +102,7 @@ func (e *DefaultExecutor) ExecutePlugin(ctx context.Context, pluginPath string, pluginOutputJSON, pluginOutputMsgs := parsePluginOutput(stdout, stderr) + // Disregards plugin source stream and logs the plugin messages to stderr for _, msg := range pluginOutputMsgs { msg := strings.ToLower(msg) switch { diff --git a/plugins/verifier/sample/sample.go b/plugins/verifier/sample/sample.go index cc8317b88..8fc48554a 100644 --- a/plugins/verifier/sample/sample.go +++ b/plugins/verifier/sample/sample.go @@ -42,14 +42,15 @@ func main() { // create a plugin logger pluginlogger := logger.NewLogger() - // output to stderr + // output info and Debug to stderr pluginlogger.Info("initialized plugin") pluginlogger.Debugf("plugin %s %s", "sample", "1.0.0") skel.PluginMain("sample", "1.0.0", VerifyReference, []string{"1.0.0"}) - // set output to stdout + // By default, the pluginlogger writes to stderr. To change the output, use SetOutput pluginlogger.SetOutput(os.Stdout) + // output warning to stdout pluginlogger.Warn("example warning message...") }