feat: handle stderr and stdout messages from plugins #1258

duffney · 2024-01-09T21:04:57Z

Description

What this PR does / why we need it:

Improves the plugin experience by processing additional messages that are sent to stderr and stdout.

Which issue(s) this PR

fixes #1022

Type of change

Please delete options that are not relevant.

Bug fix (non-breaking change which fixes an issue)
[ x] New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
Helm Chart Change (any edit/addition/update that is necessary for changes merged to the main branch)
This change requires a documentation update

How Has This Been Tested?

Please describe the tests that you ran to verify your changes. Please also list any relevant details for your test configuration

Test A
Test B

Checklist:

Does the affected code have corresponding tests?
Are the changes documented, not just with inline documentation, but also with conceptual documentation such as an overview of a new feature, or task-based documentation like a tutorial? Consider if this change should be announced on your project blog.
Does this introduce breaking changes that would require an announcement or bumping the major version?
Do all new files have appropriate license header?

Post Merge Requirements

MAINTAINERS: manually trigger the "Publish Package" workflow after merging any PR that indicates Helm Chart Change

codecov · 2024-01-09T21:08:43Z

Codecov Report

Attention: 11 lines in your changes are missing coverage. Please review.

Comparison is base (45c0f81) 61.60% compared to head (bb8a4f4) 64.07%.
Report is 4 commits behind head on main.

Files	Patch %	Lines
pkg/common/plugin/exec.go	68.57%	10 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #1258      +/-   ##
==========================================
+ Coverage   61.60%   64.07%   +2.46%     
==========================================
  Files          98       98              
  Lines        6248     5038    -1210     
==========================================
- Hits         3849     3228     -621     
+ Misses       2066     1476     -590     
- Partials      333      334       +1

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

duffney · 2024-01-10T15:02:15Z

I'll get those whitespaces cleaned up today before the community call :)

susanshi · 2024-01-10T23:43:10Z

"Please describe the tests that you ran to verify your changes. Please also list any relevant details for your test configuration" , Some scenarios i have in mind are ( please choose what you think is relevant):

Plugin execution with verification report ( success true/false)
when Plugin returning an error
Wondering any difference between builtin/ external plugins

susanshi

thanks so much for improving the plugin experience, change looks great overall, i left some minor comments.

pkg/common/plugin/exec.go

susanshi · 2024-01-10T23:32:12Z

plugins/verifier/sample/sample.go

@@ -37,7 +38,14 @@ type PluginInputConfig struct {
 }

 func main() {
+	// send info and debug messages to stderr
+	fmt.Fprintln(os.Stderr, "info: initialized plugin")


Wondering if the following statement is true? "stdOut should only be used for VerifierReport response, all informational should be written to stderr". What is the best place to document this

It's not entirely true. 😅I wrote the feature to handle multiple messages form stdout and stderr that way plugin developers could write to either. The comment is there to explain what the following 2 lines are doing, so maybe it's more accurate to say "sends info and debug messages to stderr" I could also add that it's acceptable to also write to stdout.

I'm open to suggestions though.

@duffney does this mean the user could do something like this: fmt.Fprintln(os.Stdout, "info: initialized plugin") and it would work equivalently?

Currently only stderr adds the extra information to stderr messages. But that makes the assumption that people always put those messages there and no in stdout, which isn't always the case.

I'll start looking at the ratify logger to working on use that to display the error messages.

QQ: is it important to distinguish between info, debug, and warn etc?

If not, then I can just return the message sent by the plugin with the ratify logger and remove the switch that adds the log prefix.

I think it would be nice if we could. We have issues already where the logs are just too verbose and being able to only display info vs debug will be very helpful.

pkg/common/plugin/exec.go

akashsinghal · 2024-01-18T20:59:51Z

pkg/common/plugin/exec.go

+			switch {
+			case strings.HasPrefix(strings.ToLower(line), "info"):
+				line = strings.Replace(line, "info: ", "", -1)
+				logrus.Infof("[Plugin] %s", line)


Suggestion: Instead of using the logrus package directly, can we consider using the ratify internal context logger found here. Basically, this is an implementation that uses the context passed down to store extra information like the correlationid. and the GetLogger method allows the component to be specified making it match the format of other logs. The correlationid is particular helpful to correlate which plugin logs correspond to which http request. You can follow an example hereof how to fetch the logger and use it

cc: @binbin-li

I see, so I could pass the context that's passed to the ExecutePlugin function to the internal logger to provide that additional information? I'll start working on replace logrus with this.

QQ: Should I add another compontent type for plugin, or use the executor type for the logopt?

I think you can introduce a new component type called plugin or something similar

akashsinghal · 2024-01-18T21:06:07Z

pkg/common/plugin/exec.go

+
+			jsonString, _ := json.Marshal(obj)
+			resultsBuffer.WriteString(string(jsonString))
+		} else {


Would we need to add the same debug vs info vs warning etc checks for os.Stdout as well?

akashsinghal · 2024-01-18T21:12:18Z

plugins/verifier/sample/sample.go

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


suggestion: It would be nice if we had a plugin logger that could be used here instead of having to know the exact syntax to append to the front of the logs debug: or info: for the parsing to work.

Idea would be that if a plugin author wanted to info log something: pluginlogger.Info("blah blah blah") and the logger would translate to --> fmt.Print(os.Stdout, "info: " + inputString)

Otherwise, there's more burden on plugin authors and we will need to have some good documentation about this

Great idea, that makes a lot of sense. In your opinion, where's a good place to put this package? Or should it just be added to the skel package?

yeah good question. My opinion would be to stick it in pkg/common/plugin. That way it can be used by verifier + store + (cert store very soon)

pkg/common/plugin/exec.go

plugins/verifier/sample/sample.go

susanshi · 2024-01-30T01:38:26Z

plugins/verifier/sample/sample.go

 	skel.PluginMain("sample", "1.0.0", VerifyReference, []string{"1.0.0"})
+
+	// set output to stdout
+	pluginlogger.SetOutput(os.Stdout)


wondering when should we use std out vs err

From what I've seen stderr is the default for messages, but most logging packages provide the option for redirecting to stdout. Tbh, I don't know which is best but wanted to give the flexibility to use both like logrus does. If the team has a strong opinion, I can add comments to nudge people to use stderr, which is the default for the pluginlogger I added.

I see, thanks for the clarification. :) if we could just add these comment to the sample would be good. Exactly what you have mentioned. " stderr is the default for messages, but we do provide the option to redirecting to stdout"

Comments added to the latest commit. :) Thanks for the feedback!

susanshi

thanks so much for the improvements!

binbin-li · 2024-02-02T14:44:22Z

pkg/common/plugin/logger/logger.go

+
+func NewLogger() *Logger {
+	return &Logger{
+		infoLogger:  log.New(os.Stderr, "INFO: ", 0),


ratify could swith formatter between text, json and logStash: https://github.com/deislabs/ratify/blob/main/internal/logger/logger.go#L135
just curious if this logger would switch accordingly.

Hey @binbin-li, thanks for the comment. I think that would be a good thing to add to match the logging for the rest of the project.

@susanshi @akashsinghal, what do you both think? Worth adding in for this PR?

I suggest to log an issue to track this improvement for the plugin log so we could merge this one first? what do you think @binbin-li

Logged an issue to keep track of this feature request. :) #1304

binbin-li · 2024-02-02T15:12:00Z

pkg/common/plugin/exec.go

+		line := scanner.Text()
+		// Assumes a single JSON object is returned somewhere in the output
+		// does not handle multiple JSON objects
+		if strings.Contains(line, "{") {


just curious if this could handle log like:

info: test value: {some value}

Good question. The short answer is no. However, I did write code that can handle it. I'm sure it could be improved, but here's what I had come up and then decided against including it to keep it simpler.

var obj interface{} // Change: Use a generic object var resultb bytes.Buffer scanner := bufio.NewScanner(&outb) for scanner.Scan() { line := scanner.Text() if strings.Contains(line, "{") { err := json.NewDecoder(strings.NewReader(line)).Decode(&obj) if err != nil { fmt.Println("couldn't decode entire line as JSON....") fi := strings.Index(line, "{") li := strings.LastIndex(line, "}") if fi != -1 || li != -1 { err := json.NewDecoder(strings.NewReader(line[fi : li+1])).Decode(&obj) if err != nil { fmt.Println("failed to decode JSON: ", err) } pre := line[:fi] post := line[li+1:] if pre != "" { fmt.Println(pre) } jsonString, _ := json.Marshal(obj) resultb.WriteString(string(jsonString)) if post != "" { fmt.Println("post: ", post) } } continue } jsonString, _ := json.Marshal(obj) resultb.WriteString(string(jsonString)) } else { fmt.Printf("Non-JSON line: %s\n", line) } }

akashsinghal

LGTM. Thanks for the contributions @duffney

duffney · 2024-02-07T15:54:46Z

LGTM. Thanks for the contributions @duffney

You're most welcome. Thank you everyone for your time and help in getting this feature added! :)

handle stderr and stdout messages from plugin Fixes ratify-project#1022

898f0dc

duffney requested review from akashsinghal, binbin-li, jimmyraywv, luisdlp, susanshi and toddysm as code owners January 9, 2024 21:04

akashsinghal changed the title ~~Handle stderr and stdout messages from plugins~~ feat: handle stderr and stdout messages from plugins Jan 10, 2024

remove unnecessary newlines

e4cf215

susanshi reviewed Jan 10, 2024

View reviewed changes

akashsinghal reviewed Jan 18, 2024

View reviewed changes

akashsinghal assigned duffney Jan 19, 2024

duffney added 6 commits January 25, 2024 19:33

Add Plugin componentType

6f4c58b

customer logger for plugin output

e8d08fe

mod: replace fmt output with pluginlogger

b43a4bc

mod: extracted scan loops and log messages with internal ratify logger

3da7622

Mod: rename pluginOutputjson to pluginOutputJSON

734c7af

Mod: add license header

2298323

susanshi reviewed Jan 29, 2024

View reviewed changes

pkg/common/plugin/exec.go Outdated Show resolved Hide resolved

susanshi reviewed Jan 29, 2024

View reviewed changes

plugins/verifier/sample/sample.go Show resolved Hide resolved

susanshi reviewed Jan 30, 2024

View reviewed changes

duffney added 2 commits January 30, 2024 15:38

Mod: clean up comments

56295fd

Mod: include stdout stderr behavior comments

3757608

susanshi approved these changes Feb 2, 2024

View reviewed changes

Merge branch 'main' into issue-1022

3c47c0d

binbin-li reviewed Feb 2, 2024

View reviewed changes

binbin-li approved these changes Feb 7, 2024

View reviewed changes

Merge branch 'main' into issue-1022

bb8a4f4

akashsinghal approved these changes Feb 7, 2024

View reviewed changes

akashsinghal merged commit 2eacdaf into ratify-project:main Feb 7, 2024
21 checks passed

duffney mentioned this pull request Feb 7, 2024

Add support for format switching to the pluginLogger #1304

Open

1 task

duffney deleted the issue-1022 branch September 25, 2024 14:36

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: handle stderr and stdout messages from plugins #1258

feat: handle stderr and stdout messages from plugins #1258

duffney commented Jan 9, 2024

codecov bot commented Jan 9, 2024 •

edited

Loading

duffney commented Jan 10, 2024

susanshi commented Jan 10, 2024

susanshi left a comment

susanshi Jan 10, 2024

duffney Jan 12, 2024

akashsinghal Jan 18, 2024

duffney Jan 19, 2024

akashsinghal Jan 19, 2024

akashsinghal Jan 18, 2024

akashsinghal Jan 18, 2024

duffney Jan 19, 2024

duffney Jan 19, 2024

akashsinghal Jan 19, 2024

akashsinghal Jan 18, 2024

akashsinghal Jan 18, 2024 •

edited

Loading

akashsinghal Jan 18, 2024

duffney Jan 19, 2024

akashsinghal Jan 19, 2024 •

edited

Loading

susanshi Jan 30, 2024

duffney Jan 30, 2024

susanshi Feb 1, 2024

duffney Feb 1, 2024

susanshi left a comment

binbin-li Feb 2, 2024

duffney Feb 5, 2024

susanshi Feb 6, 2024

duffney Feb 7, 2024

binbin-li Feb 2, 2024

duffney Feb 5, 2024

akashsinghal left a comment

duffney commented Feb 7, 2024

feat: handle stderr and stdout messages from plugins #1258

feat: handle stderr and stdout messages from plugins #1258

Conversation

duffney commented Jan 9, 2024

Description

What this PR does / why we need it:

Which issue(s) this PR

Type of change

How Has This Been Tested?

Checklist:

Post Merge Requirements

codecov bot commented Jan 9, 2024 • edited Loading

Codecov Report

duffney commented Jan 10, 2024

susanshi commented Jan 10, 2024

susanshi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akashsinghal Jan 18, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akashsinghal Jan 19, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

susanshi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

akashsinghal left a comment

Choose a reason for hiding this comment

duffney commented Feb 7, 2024

codecov bot commented Jan 9, 2024 •

edited

Loading

akashsinghal Jan 18, 2024 •

edited

Loading

akashsinghal Jan 19, 2024 •

edited

Loading