feat: handle stderr and stdout messages from plugins (#1258)

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"
 )

pkg/common/plugin/exec.go

@@ -16,14 +16,18 @@ limitations under the License.
 package plugin
 
 import (
+	"bufio"
 	"bytes"
 	"context"
+	"encoding/json"
 	"fmt"
 	"io"
+	"os"
 	"os/exec"
 	"strings"
 	"time"
 
+	"github.com/deislabs/ratify/internal/logger"
 	"github.com/sirupsen/logrus"
 )
 
@@ -32,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
@@ -92,14 +100,27 @@ 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 {
-		_, _ = stderr.WriteTo(e.Stderr)
+	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 {
+		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 stdout reader
-	return stdout.Bytes(), nil
+
+	return pluginOutputJSON, nil
 }
 
 func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error {
@@ -118,3 +139,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
+}

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

pkg/common/plugin/logger/logger.go

@@ -0,0 +1,70 @@
+/*
+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 (
+	"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)
+}

plugins/verifier/sample/sample.go

@@ -18,8 +18,10 @@ package main
 import (
 	"encoding/json"
 	"fmt"
+	"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"
@@ -37,7 +39,19 @@ type PluginInputConfig struct {
 }
 
 func main() {
+	// create a plugin logger
+	pluginlogger := logger.NewLogger()
+
+	// 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"})
+
+	// 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...")
 }
 
 func parseInput(stdin []byte) (*PluginConfig, error) {