Information messages should be written to stdout

[kichristensen]

What does this change

The current behaviour is that span.Info messages are written to stderr instead of stdout. This is going against what is describe the contributor document.
With this change logs written with the log level Info will be written to stdout.

What issue does it fix

Closes #2889

Notes for the reviewer

There were existing tests that verified that logs with Info level was written to stderr under some circumstances, these have been changed in this PR. But I have a hard time determining it breaks any real use cases.

Checklist

• Did you write tests?
• Did you write documentation?
• Did you change porter.yaml or a storage document record? Update the corresponding schema file.
• If this is your first pull request, please add your name to the bottom of our Contributors list. Thank you for making Porter better! 🙇‍♀️

Reviewer Checklist

• Comment with /azp run test-porter-release if a magefile or build script was modified
• Comment with /azp run porter-integration if it's a non-trivial PR

[schristoff]

It looks like to Porter info == debug, and so we're going to have to rework what is considered debug and what is "general" output. I wonder if there's some documentation on standards around this we can dig up.

[kichristensen]

Yes it looks like that. I'm not sure what the best solution here would be. I haven't been able to find any real documentation on standards, only pointers in different places:
This Stack Overflow post says more or less what is written in CONTRIBUTOR.md, which makes sense to me, although I never thought about like that before.
The default production configuration in zap will send all log messages to stderr.
Based on CONTRIBUTOR.md and the few links I can find, I think problem surfaces because some parts of the code logs directly using fmt.Fprintln as described in CONTRIBUTOR.md, and other parts, like the place described in #2889, uses logs through spans. Because logs through spans have to be handled more generally, I don't think we can assume anything, as it depends on if the command has any "real" output, like JSON, it all becomes very context specific.
If a command produces some JSON log messages should never go to stdout, but only stderr.
In a command like porter credentials apply there only output is the log message which is why it logically would make sense for the log message to be written to stdout.
Unfortunately this also means that classifying log messages to a specific level becomes hard. I would argue that in the case of porter credentials apply the message it not tied to a specific log level, it is the output of the command.

Before I started to write this comment, I didn't really know where I stood in this question. But after formulating all this, I think I know 😄

I think there should be a difference between log messages and command output. Command outputs should always be written to stdout. Log messages are a bit harder, because based on the name, most people think about stderr as meant for errors. Then it boils down to the purpose of the log messages, or in this case the log messages sent through spans. In my head command output should never written through spans, only through fmt.Fprintln. See the difference between how it is done in for parameters vs credentials (in think the correct way is done in parameters):

porter/pkg/porter/parameters.go

Lines 151 to 160 in aa7959f

	fmt.Fprintf(p.Out, "Generating new parameter set %s from bundle %s\n", genOpts.Name, bundleRef.Definition.Name)
	numExternalParams := 0
	for name := range bundleRef.Definition.Parameters {
	if !bundleRef.Definition.IsInternalParameter(name) {
	numExternalParams += 1
	}
	}
	fmt.Fprintf(p.Out, "==> %d parameter(s) declared for bundle %s\n", numExternalParams, bundleRef.Definition.Name)

porter/pkg/porter/credentials.go

Lines 150 to 151 in aa7959f

	span.Infof("Generating new credential %s from bundle %s\n", genOpts.Name, bundleRef.Definition.Name)
	span.Infof("==> %d credentials required for bundle %s\n", len(genOpts.Credentials), bundleRef.Definition.Name)

If the way it is implemented in parameters is considered correct and we would accomendate the issue in #2889, that the default log level should be changed from into to either warn or error, to avoid informational "tracing" messages to the printed to stdout, and that the credentials command uses fmt.Fprintln to write the command output correctly to stdout. This would also apply to other places where span.Info is used to write command output. span.Info is generally not used at lot of places in Porter, making it not as big a task as you would think.
Doing these things I think would align with CONTRIBUTOR.md and at the same time address thee issue described in #2889. But then the question becomes "Is this a breaking change?" to some extend you can argue "Yes". There might be users that expect certain output in stderr or in the OpenTelemetry logs, on the other hand you could argue that it was a bug that command output was written to stderr in the first place.

Sorry for this long comment, thinking about it got me started, please let me know what you think?

[schristoff]

I remember having discussions about log level and where to output before, this has been a weird topic.
I appreciate you digging up some knowledge on this as well.
So, as far as the easiest question: "Is this a breaking change" - if we do change something I would agree with yes.
I would also agree with you on that users expect command output that would be considered "info" level (i.e. "This has succeeded") to go to stdout.

I think this can be broken into two parts, a "for now" fix, and a "long term bigger PR" fix (this way you didn't take something that seemed like a couple line change, and it grows to a couple hundred lines) - which is to swap over cmd output that is span.Infof into a fmt.Println (I don't love this long term, but again, band aid) - but to do this we must decide on what logging will look like long term (if we rip out spans, we should replace them with ctx, and then what are the changes needed to do that and run our logger throughout all the cmds)

I would also love to chat about this in the community call this Thursday at 9AM MST - if you're able to make it I'd love your input there. :) Since this seems to be a user facing change I want to make sure there's nothing I'm not forgetting.

[kichristensen]

@schristoff Sorry for the late response.
I would to join a Community Call to talk about this. Unfortunately I didn't see this message or had time Thursday the 7th. But I can the next time, I guess the next Community Call is cancelled because of KubeCon in Paris? Also I'm going KubeCon, so it doesn't fit very well anyway. But the I join the one after.