runtime: use standard prefix for GODEBUG logs

[tibetsam]

What version of Go are you using (go version)?

$ go version
go version go1.13.1 linux/amd64

Does this issue reproduce with the latest release?

yes.

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
not relevant

What did you do?

I've just enabled the gctrace and found all the debug logs are sent to stderr by print function.
src/runtime/mgc.go:
if debug.gctrace > 0 {
printlock()
print("gc ", memstats.numgc,
" @", string(itoaDiv(sbuf[:], uint64(work.tSweepTerm-runtimeInitTime)/1e6, 3)), "s ",
util, "%: ")

// write to goroutine-local buffer if diverting output,
// or else standard error.
func gwrite(b []byte) {
if len(b) == 0 {
return
}
recordForPanic(b)
gp := getg()
// Don't use the writebuf if gp.m is dying. We want anything
// written through gwrite to appear in the terminal rather
// than be written to in some buffer, if we're in a panicking state.
// Note that we can't just clear writebuf in the gp.m.dying case
// because a panic isn't allowed to have any write barriers.
if gp == nil || gp.writebuf == nil || gp.m.dying > 0 {
writeErr(b)
return
}

n := copy(gp.writebuf[len(gp.writebuf):cap(gp.writebuf)], b)
gp.writebuf = gp.writebuf[:len(gp.writebuf)+n]

}

What did you expect to see?

i'm happy to see the debug logs puts to stdout with some debug flag like:
debug.out=1

What did you see instead?

all debug logs were treated as error by log server.

[tibetsam]

i saw the comments in #994 but hmmm, i don't think it applies to debug log

[ianlancetaylor]

Why not just redirect standard error to standard output if that is what you want to do?

I don't see a compelling reason to add another knob here.

[tibetsam]

@ianlancetaylor i can't simply mix "real" error logs and normal logs to stdout. i just want debug log puts to stdout.

[ianlancetaylor]

Let's assume that knobs are expensive and undesirable, that they require documentation and ongoing testing, and that we won't add a knob merely because it is convenient. Let's assume that people do not routinely set GODEBUG and that anybody who does set it, other than when working with experienced Go developers to resolve a bug, is an expert on what they are doing.

Under those assumptions, what is the compelling use case for adding another knob?

Thanks.

[tibetsam]

I completely agree with you about what you said in the 1st half part. it might cost lot.

But please be aware of one thing is doesn't matter how experienced engineer is, whenever she/he needs to troubleshoot and enables the debug, all the debug logs will go to stderr and those are not actually errors, but all those debug logs will be appeared as error in log server. And the person who is doing maintenance job might not be familiar with those debug logs and will treat them as real error(bcz there isn't a keyword in a log shows it's debug log, so you can't filter is automatically). And this will also cost lot to open ticket for support, arrange people to look into ticket. And of course all these things will happen to not only one user/customer.

In my view add a knob can keep it's backward compatibility, even it might cost lot(in this case, may be not that lot), but will benefit many others.

[networkimprov]

@ianlancetaylor how about a GODEBUG option to log runtime output to a file, since apps commonly use both stdout & stderr? That would allow "gctrace=1,log=/dev/stdout".

On first look, I'd agree that logging runtime stats to stderr is surprising.

EDIT: a use case is an app which, in debug mode, produces a LOT of stderr output, complicating the process of providing a trace log to the Go team, for example.

[ianlancetaylor]

When I complain about adding a knob, I don't think the solution is to add another, more complicated, knob. Even the current approach is already more complicated than one might think; see https://golang.org/src/runtime/write_err_android.go.

I think that for the very small number of people who need to be concerned with this, this is something that can be address by wrapping tools around a Go program, it's not something that needs to change in the Go runtime.

The way to change this calculation is to demonstrate that this is a problem for a large number of people, and not an unusual special case.

[ALTree]

It would probably help if the runtime printed a standard prefix before each log line (to make it easy to filter logs with eg grep).

Then it doesn't matter if runtime logs and your logs both go on stderr, you can do something like

grep -v "GODEBUG" logs > filtered_logs

and then filtered_logs will have just your application's stderr.

Right now this is much harder to do: you can catch the scavenger logs with "scvg" but the gc lines look like this:

gc 2 @0.057s 0%: 0.011+0.51+0.005 ms clock, 0.047+0.25/0.32/0.44+0.023 ms cpu, 4->4->0 MB, 5 MB goal, 4 P

and grepping over gc \d is probably not very reliable (too short, the string could appear in the application's logs).

[ianlancetaylor]

I would be fine with a standard prefix.

CC @aclements

[networkimprov]

Perhaps a configurable prefix? "logprefix=..."

[ALTree]

Perhaps a configurable prefix? "logprefix=..."

How to get your Go proposal to be immediately rejected in 1 easy step:

1. suggest adding a new, only marginally useful, knob or flag to the runtime

[aclements]

I agree with Ian and would be fine with a standard prefix. It doesn't seem like making it configurable is worthwhile.

In general, stdout is for the primary output of a program: in-band data that you could, say, pipe to another program. stderr is for out-of-band data, such as logs. The presence of data on stderr shouldn't indicate failure; a non-zero exit status indicates failure. (Though I realize that reality is complicated.) However, there are also good reasons for trying to make some sense of what's on stderr, and a standard prefix for runtime messages would go a long way to helping with that.

We already try to prefix runtime crash messages with "runtime: ". Maybe we should just do that for the gc and scvg logs?

[networkimprov]

If any scripts grep/awk runtime log output, the new prefix could break them. An option to set the prefix would let us turn it off, or better yet, turn it on.

FWIW, in server apps, I use stdout for normal status (can be discarded or switched off) and stderr for unexpected status (not nec an error, but must be logged). There's no output I'd expect to pipe to another program.

[tibetsam]

I'm fine with prefix solution. Thanks to you all for the discussion.

[networkimprov]

GORACE supports:

log_path (default stderr): The race detector writes its report to a file named log_path.pid. The special names stdout and stderr cause reports to be written to standard output and standard error, respectively.

[fweimer]

Issue #42888 seems related and appears more favorably received, too.