proposal: os/exec: add GODEBUG flag to print a line to STDERR for each command started

[mknyszek]

This came out of a conversation with @aclements about trying to understand what commands cmd/dist runs, but I've found such a thing to be useful for x/benchmarks/sweet as well (and had to implement my own wrapper to get this functionality).

These use-cases suggest this might be a more generally useful flag for debugging CLI tools that frequently start commands, especially when the logic for how those commands are constructed is somewhat complex.

The alternative is to use something like strace or whatever your platform provides, but this typically introduces additional overheads and it's a bit more indirect (i.e. syscall.Exec and os/exec.Command typically have different intents).

[mvdan]

For what it's worth, I would also have found this useful a few times. For example, when debugging why a Go tool isn't working the way I expect it too, or when it's surprisingly slow, it's very useful to be able to tell what go list invocations it is making.

Would there also be lines printed out when commands finish, with stats like elapsed time or cpu user/system time? I would find those useful too, at times.

[robpike]

What precedent does this set? How do we choose which elements of the library need special annoations? A GODEBUG element for every file we open? Every chdir that executes? Every regular expression we parse?

This proposal suggests the wrong solution, or at least the wrong location, to fix something that may actually deserve attention. Since pretty much everyone uses something like Cobra for CLIs these days, isn't that a better place to manage logging?

[mknyszek]

What precedent does this set? How do we choose which elements of the library need special annoations? A GODEBUG element for every file we open? Every chdir that executes? Every regular expression we parse?

These all provide value, which is why strace exists (excluding the regular expression example). The difference is that spawning subprocesses, perhaps unfortunately, involves a lot of moving parts. Evidence of this lies in the size of the API surface for exec.Cmd (which doesn't include the additional logic required to accommodate the idiosyncrasies of CLIs of popular tools). As a result, I tend to write the same code in CLI tools I've written: a logging wrapper around exec.Cmd.

But almost every time, the only reason I actually wanted this logging was so that I could debug my program. (Perhaps this experience doesn't resonate with others.)

As you say, one possible solution for this is to simply provide a logging wrapper. A third-party library could do it, too.

My suggestion of GODEBUG came from the fact that it parallels other STDERR-logging traces like GODEBUG=inittrace=1. The main benefit of GODEBUG is that it works without having to change any source code. I admit this benefit is marginal, but so is the cost of a GODEBUG flag compared to additional API in the standard library. (Note: perhaps that's no longer true given the discussion at #55090 as the purpose of GODEBUG is solidified. Also, third-party solutions are lowest cost, but also with, from my perspective, the smallest benefit to the Go ecosystem.)

(The other benefit over relying external tooling such as strace that it doesn't exist on all the platforms Go supports. These system call tracing tools also tend to not be particularly user-friendly in my experience.)

Another alternative, which I didn't previously consider, is to make (*exec.Cmd).String more verbose in order to make println(cmd.String()) more useful as a debugging tool. It's already documented as intended only for debugging, and currently it only prints the command and its arguments, which tends to be insufficient for the situations I've encountered. In general I also find myself wanting to know the environment (perhaps a diff from os.Environ?), how STDOUT and STDERR are hooked up, and the subprocess's working directory.

[prattmic]

I more-or-less agree with @robpike. This sounds useful, but also somewhat arbitrary in a big space of other similar potentially useful traces.

Here's another thought: runtime/trace already includes (blocking) system calls. What if those syscall events became more descriptive (including arguments, etc)? And os.NewProcess could use a special syscall event that captures the things that happen after fork (chdir, execve arguments, etc).

runtime/trace is very heavyweight from capturing this right now, but imagine if it were lighter weight, allowed filtering to only these events you care about, and could potentially integrate better with logging?

[mknyszek]

runtime/trace is very heavyweight from capturing this right now, but imagine if it were lighter weight, allowed filtering to only these events you care about, and could potentially integrate better with logging?

Right, that would be ideal. (Well, that and also something to print it for you without having to launch the trace viewer.) It might also make sense to support inittrace, gctrace, etc. in there as well and potentially remove them. (These runtime-level STDERR traces would benefit from the ability to start tracing at runtime init.)

I stand by spawning subprocesses being unfortunately hard, and the nice thing about GODEBUG being that (in theory, unless I've very fundamentally misunderstood something) we can take it away once we have something better. Simultaneously, I don't feel too strongly about this; it was an idea for a small and easy thing that felt like it could be a small step toward making the debugging experience for CLI tool owners better.

[rittneje]

What about something analogous to httptrace?

package exec

type Trace struct {
    OnCommandStarted func(context.Context, *CommandStartedEvent)
}

type CommandStartedEvent struct {
    Command *Cmd
}

func WithTrace(ctx context.Context, trace *Trace) context.Context {
    // ...
}

Then exec.Cmd.Start will pull the Trace from the context (if any) and call the callback (if any).

The go command can just go by some env var or flag or whatever to include a trace config in the context. And this gives other clients full control over what specifically is logged, how it is formatted, etc.

[mknyszek]

I think we want to expose this trace programmatically, not just for ingestion by humans, the better solution is to try and expose all tracing information programmatically. Then, as @prattmic suggests, we can just track this in regular runtime/trace traces. It's more work but far more valuable and far less arbitrary.

My argument for GODEBUG basically comes down to: it's easy, it's cheap, and I think this specific case of subprocesses brings enough benefit that it outweighs the fact that yeah, it is somewhat arbitrary. A whole API is I think too high a cost.

[rsc]

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

[rsc]

It sounds like there are serious objections to library code printing to stderr based on GODEBUG. We did that for the runtime and GC, but we probably shouldn't keep doing it.

Finding a way to get this information into runtime/trace sounds like a reasonable plan. Do we know what that would look like? Should this wait for a redesign of runtime/trace?

[mknyszek]

I think exposing this in runtime/trace today looks like emitting a new trace event for emitting additional syscall details in general. This is probably not that hard (emit an event at a syscall sink, such as syscall.Syscall6 or something, containing all the arguments; interpret the result later), but given the current usability limitations of runtime/trace it's probably not all that useful today. (I can't see where in the event spec we already emit these details, so I don't think we do. I could be missing something though.)

As a result, this might want to wait on a redesign of runtime/trace in that case. It wouldn't be that much effort to implement but it's not clear if that effort is worth it.