Log messages being printed to stderr

[leebenson]

What happened in your environment?

The default logger provided by NewLogger() is printing all messages to stderr:

ratify/pkg/common/plugin/logger/logger.go

Lines 33 to 34 in e9152c9

	infoLogger: log.New(os.Stderr, "INFO: ", 0),
	debugLogger: log.New(os.Stderr, "DEBUG: ", 0),

What did you expect to happen?

I'd expect that at least info and debug level logs would be printed to stdout.

What version of Kubernetes are you running?

No response

What version of Ratify are you running?

No response

Anything else you would like to add?

This is causing at least one customer issue at Datadog. An Agent reading from a Kubernetes pod's console output is interpreting info/debug logs as errors due to the stderr stream.

Are you willing to submit PRs to contribute to this bug fix?

• Yes, I am willing to implement it.

[akashsinghal]

@duffney do you think you could provide some insights here?

[binbin-li]

Discussed in the community meeting, @duffney will post more context in the issue. @leebenson wonder if you will help fix this bug?

[leebenson]

I'm happy to help fix. AFAICT, it's just a case of switching os.Stderr for os.Stdout.

My take would be:

• Info, debug, warn logs go to stdout.
• Error logs go to stderr.

I realise there are other opinions on this. ipfs/go-log#60 has some related discussion with opinions on both sides. My position would be closer to this comment; Node, Docker, Nginx and other tooling follows this convention.

Whatever you decide to do here, let me know and I'm happy to adjust as warranted.

[duffney]

@leebenson what your proposing makes total sense to me. The only thing to keep in mind is that the plugins return a configuration to Ratify via stdout as json. Meaning other messages written to stdout need to be parsed. However, that functionality does exist and I can't see any reason not to switch the logger to use stderr for info, debug, and warn logs. We'll just have to make sure the parsePluginOutput func I wrote is good enough. :)

Here's some link for more context on the parser and how the messages are passed from the plugin:

• https://github.com/ratify-project/ratify/blob/dev/pkg/common/plugin/exec.go#L103
• https://github.com/ratify-project/ratify/blob/dev/pkg/common/plugin/exec.go#L143

I also greatly appreciate your wiliness to contribute, if you need any assistance please feel free to reach out. You can also find me in the CNCF slack if DMs are quicker.

[leebenson]

Thanks @duffney. Does it seem accurate that it's just a case of swapping these lines for os.Stdout, or it this likely to touch more?

The reason I ask: I'm certainly happy to contribute, but my familiarity with Ratify is surface-level and I wouldn't want that to hinder progress. If suddenly sending logs to stdout is likely to impact plugins or existing customers, it may be better tackled by someone who is able to test for those scenarios.

OTOH, if this is literally the 3 line change I'm hoping it is, then I'm happy to whip up a PR!

[duffney]

I believe that's is accurate. My only additional suggestion would be to add a test that has two messages written to stdout. One that's json and another message to valid that the parser handles it properly. If it turns out I was wrong and everything blows up feel free to paste a Homer disappear meme and we can take a closer look. :) And thank you again for filing the issue. It's really good to know that other tools have expectations for where these messages are written to.

Link to exec tests: https://github.com/ratify-project/ratify/blob/dev/pkg/common/plugin/exec_test.go