proposal: runtime/pprof: add WriteGoroutineLabels function for logging

[ansiwen]

Problem Statement

Given that goroutines are anonymous and there is no accessible goroutine id makes it very difficult to add goroutine context to debug/tracing output without having a context parameter in all functions and a context field in all objects, which is often unfeasible. That lead to many attempts to workaround this limitation and reoccurring debates about it. So, although beyond doubt there is a reasonable demand for context logging, it has deliberately been ignored in order to not undermine the anonymity of goroutines, which is regarded as more important.

Proposal

As a kind of compromise, that allows to log goroutine context, without making it too easy to abuse it for "goroutine local storage", I want to propose the following API:

package pprof

// WriteGoroutineLabels writes the current goroutine's labels to w. If a write
// to w returns an error, that error is returned, nil otherwise. The format of
// the output is not specified, and should only be used for logging/tracing
// purposes.
func WriteGoroutineLabels(w io.Writer) error { ... }

This would easily and efficiently allow to set labels with the SetGoroutineLabels() and Do() functions, and still log them in code paths, where the context is not available, and give important information for log forensics. This is especially useful for 3rd party libraries, that don't support contexts, but do support setting a global log sink for debug output. For example:

import (
  "context"
  "log"
  "runtime/pprof"

  "github.com/ansiwen/foobar"
)

func init() {
  foobar.SetDebugOutput(func(msg string) {
    var lbls strings.Builder
    _ = pprof.WriteGoroutineLabels(&lbls)
    log.Printf(`[DBG]<foobar> msg="%s" context="%s"`, msg, lbls.String())
  })
}

func fireFoobarRequest(id string, data []byte) {
  go func() {
    lbl := pprof.Labels("requestID", id)
    pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), lbl))
    foobar.doRequest(data)
  }()
}

Edit: added usage example.

[ianlancetaylor]

It seems like you are suggesting that there are packages out there that don't and won't take a context.Context, and that don't and won't take a logger that could annotate logs however it likes, but that will change their code to call pprof.WriteGoroutineLabels. Do you have any examples of packages like that?

[ansiwen]

@ianlancetaylor Thanks for your answer. No, sorry, I think I didn't make that clear enough. I'm talking about libraries, that don't support context.Context but do support setting a logger for debug output. Let me demonstrate it with some example code:

import (
  "context"
  "log"
  "runtime/pprof"

  "github.com/ansiwen/foobar"
)

func init() {
  foobar.SetDebugOutput(func(msg string) {
    var lbls strings.Builder
    _ = pprof.WriteGoroutineLabels(&lbls)
    log.Printf(`[DBG]<foobar> msg="%s" context="%s"`, msg, lbls.String())
  })
}

func fireFoobarRequest(id string, data []byte) {
  go func() {
    lbl := pprof.Labels("requestID", id)
    pprof.SetGoroutineLabels(pprof.WithLabels(context.Background(), lbl))
    foobar.doRequest(data)
  }()
}

(I just sketched that down, probably full of mistakes.) So it basically applies to all libraries that

1. allow to set a logger or similar as a (global) debug sink
2. doesn't take a context (or at least, doesn't make it available in the debug log callback) and
3. that is potentially used concurrently.

Without this "tunneling" of context, it inevitably gets lost, and you can't relate the debug output to the request anymore.

I hope that makes it more clear.

Edit: fixed inconsistency in example

[ansiwen]

And regarding an example library: While I believe there are loads of libraries that fit into that category, we are about to add debug logging to our ceph Go bindings and realised, that without breaking our API the users can't relate the concurrent calls into the library with the debug output.

[ianlancetaylor]

It seems to me that if you can pass in a logger, then you can create a logger type that attaches any information you like to the log. It can do the equivalent of pprof.WriteGoroutineLabels, only it doesn't need to call that function because it knows the relevant labels.

[ansiwen]

@ianlancetaylor How can it do that? Of course it could store any information, but a global logger instance, that is called from concurrent goroutines, could never know, which is the "right" information to add. The result of pprof.WriteGoroutineLabels is depending on the goroutine in which it is called, because every goroutine has its own set of labels.

[ansiwen]

Alternatively maybe this is also sufficient:

func GoroutineLabelsString() string { ... }

I was following the WriteTo scheme, but maybe in this case that's over-engineered, because the output is shorter.

[ianlancetaylor]

Sorry, I meant that you pass in the logger appropriate to the goroutine. I didn't mean to imply that there was a single global logger.

[ansiwen]

I see. But libraries don't usually support passing in a logger per request, at least I've never seen that. Either you can pass in a global logger, or they use the standard logger, which output you can redirect. If the library offers a logger per request that is an equivalent of a context.