Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

feat: handle stderr and stdout messages from plugins #1258

Merged
merged 12 commits into from
Feb 7, 2024
Merged

feat: handle stderr and stdout messages from plugins #1258

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
898f0dc
handle stderr and stdout messages from plugin Fixes #1022
duffney Jan 9, 2024
e4cf215
remove unnecessary newlines
duffney Jan 10, 2024
6f4c58b
Add Plugin componentType
duffney Jan 25, 2024
e8d08fe
customer logger for plugin output
duffney Jan 25, 2024
b43a4bc
mod: replace fmt output with pluginlogger
duffney Jan 25, 2024
3da7622
mod: extracted scan loops and log messages with internal ratify logger
duffney Jan 25, 2024
734c7af
Mod: rename pluginOutputjson to pluginOutputJSON
duffney Jan 26, 2024
2298323
Mod: add license header
duffney Jan 26, 2024
56295fd
Mod: clean up comments
duffney Jan 30, 2024
3757608
Mod: include stdout stderr behavior comments
duffney Feb 1, 2024
3c47c0d
Merge branch 'main' into issue-1022
susanshi Feb 2, 2024
bb8a4f4
Merge branch 'main' into issue-1022
susanshi Feb 7, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
46 changes: 44 additions & 2 deletions pkg/common/plugin/exec.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,10 +16,13 @@
package plugin

import (
"bufio"
"bytes"
"context"
"encoding/json"
"fmt"
"io"
"os"
"os/exec"
"strings"
"time"
Expand Down Expand Up @@ -96,10 +99,49 @@
// 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)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cc: @binbin-li

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

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)

Check warning on line 115 in pkg/common/plugin/exec.go

View check run for this annotation

Codecov / codecov/patch

pkg/common/plugin/exec.go#L107-L115 

Added lines #L107 - L115 were not covered by tests
default:
fmt.Fprintf(os.Stderr, "[Plugin] %s,", line)
}
}
// TODO: Should this be removed since the msgs are processed?
//_, _ = stderr.WriteTo(e.Stderr)
susanshi marked this conversation as resolved.
Show resolved Hide resolved
}

var obj interface{}
var resultsBuffer bytes.Buffer

scanner := bufio.NewScanner(stdout)
for scanner.Scan() {
susanshi marked this conversation as resolved.
Show resolved Hide resolved
line := scanner.Text()
if strings.Contains(line, "{") {
err := json.NewDecoder(strings.NewReader(line)).Decode(&obj)
if err != nil {
continue

Check warning on line 133 in pkg/common/plugin/exec.go

View check run for this annotation

Codecov / codecov/patch

pkg/common/plugin/exec.go#L133 

Added line #L133 was not covered by tests
}

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

fmt.Printf("[Plugin] %s \n", line)
}

Check warning on line 140 in pkg/common/plugin/exec.go

View check run for this annotation

Codecov / codecov/patch

pkg/common/plugin/exec.go#L138-L140 

Added lines #L138 - L140 were not covered by tests
}

// TODO stdout reader
return stdout.Bytes(), nil
return resultsBuffer.Bytes(), nil
}

func (e *DefaultExecutor) pluginErr(err error, stdout, stderr []byte) error {
Expand Down
8 changes: 8 additions & 0 deletions plugins/verifier/sample/sample.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@ package main
import (
"encoding/json"
"fmt"
"os"

"github.com/deislabs/ratify/pkg/common"
"github.com/deislabs/ratify/pkg/ocispecs"
Expand All @@ -37,7 +38,14 @@ type PluginInputConfig struct {
}

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

fmt.Fprintf(os.Stderr, "debug: plugin %s %s \n", "sample", "1.0.0")
Copy link
Collaborator

@akashsinghal akashsinghal Jan 18, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Collaborator

@akashsinghal akashsinghal Jan 19, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)


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) {
Expand Down
Loading