log/slog: ReplaceAttr gets Source struct instead of file:line

[jba]

If HandlerOptions.AddSource is set to true, the built-in handlers behave as if the attribute with key SourceKey and string value "file:line" were present. When a ReplaceAttr function is also provided, it is passed that exact attribute, just as with the other built-in attributes.

But this is a missed opportunity to make it easy for users to customize the output of the source location. ("Easy" here meaning a couple of lines of code, compared to writing an entire new Handler.)

Instead, I propose that When AddSource is true, ReplaceAttr is passed an Attr with SourceKey and the Record's PC field. It could then do whatever it wished, like including the function name in the returned Attr. If it returned the Attr unchanged, the handler would proceed with the default "file:line" output.

Downsides:

• Without this change, only Handler writers were exposed to the PC field of the Record. Working with pcs is an advanced topic, and perhaps the everyday users of slog should not be asked to deal with it.

• This is a special case for ReplaceAttr. In particular, this is the only time the built-in handlers would make a decision based on its return value (except for eliding empty Attrs).

See also #56345.

[AndrewHarrisSPU]

Working with pcs is an advanced topic, and perhaps the everyday users of slog should not be asked to deal with it.

This feels like the right insight to me - if interested, users can provide some function func(___the record's PC field___) Attr(*) to wrangle different path formatting, a function symbol, or even arbitrary things like runtime.Debug module info, rather than re-implement most of a Handler. Also, it's not an everyday thing.

At the cost of changingHandlerOptions, the AddSource field itself could be a function, or another field like AddSourceFunc could be added. Then, where the built-in handlers currently branch on a boolean AddSource configuration here once per record, instead branch on the presence of an AddSource-related function.

slog.HandlerOptions{
	AddSource: true,
	AddSourceFunc: ..., // defaults to file:line behavior
}

This is a special case for ReplaceAttr

I think this is probably not a huge deal, but changing HandlerOptions I think might be less special case overall (?).

(*: A func(Record) Attr, or I guess even func(context.Context, Record) Attr, exposes more information than func(Attr) Attr - I think the ceiling on clever things here is high)

[ianthehat]

Instead how about if the SourceKey was paired with a structured value not a string (probably the runtime.Frame?). Then ReplaceAttr could either fix up the fields, or swap it for a fixed string value etc. This involves no declared API change.
For things that need any more power than that, they can always write a middleware that modifies the record on the way through.

[rsc]

I agree with @ianthehat - exposing a PC is going to be error prone, but it would be possible to expose instead a

type Source struct {
    Func string
    File string
    Line int
}

func (s *Source) String() string { return fmt.Sprintf("%s:%d", s.File, s.Line) }
func (s *Source) MarshalText() []byte { return []byte(s.String()) }

and make that the attribute value. The name Source matches SourceKey.

[ChrisHines]

We already have runtime.Frame. Why not use that as @ianthehat suggested?

[AndrewHarrisSPU]

We already have runtime.Frame. Why not use that as @ianthehat suggested?

The added methods of a slog.Source make it work as a Value more straightforwardly. I think this is a good fit for someone writing a ReplaceAttr function more on the spot, and a bit more coordinated overall.

[ChrisHines]

Ever since I read about how PGO uses line offsets within functions to help improve stability of its data across refactorings I've been wondering if caller information in logs might be better reported the same way.

To be honest, despite maintaining github.com/go-stack/stack and contributing caller implementations to a couple of logging packages, I haven't been using that feature in logs for the last several years. The reasons are:

• Logs usually contain enough information to trace them back to their origin in the source code without file and line info
• The file and line info is pretty useless to non-developers looking at the logs
• Version skew can make the file and line number info unreliable

Logging a function name and line offset could be both less prone to version skew and possibly more informative (assuming function names have more value than file names).

Can we arrange it so that someone could choose to implement something like that? Here's a proof-of-concept: https://go.dev/play/p/7YfnTGA6jRP

type Source struct {
	runtime.Frame
}

func (s *Source) String() string {
	if s.Func == nil {
		return fmt.Sprintf("%s:%d", s.File, s.Line)
	}

	_, firstLine := s.Func.FileLine(s.Func.Entry())
	return fmt.Sprintf("%s:%d", s.Function, s.Line-firstLine)
}

func (s *Source) MarshalText() []byte { return []byte(s.String()) }

[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

[StevenACoffman]

@ChrisHines I have sometimes included the runtime vcs.revision in error logs so that the stacktrace can be consistently resolved.

func getVCSRevision() string {
	bi, ok := debug.ReadBuildInfo()
	if !ok {
		panic("couldn't read build info")
	}
	for _, d := range bi.Settings {
		if d.Key == "vcs.revision" {
			return d.Value
		}
	}
	return ""
}

With the frame.File and frame.Line (or Source.File and Source.Line) this allows the construction of a GitHub (or equivalent) permalink https://github.com/99designs/gqlgen/blob/9a644c5415585cb3be6c4f5cb51610b8e23d1b89/handler/handler.go#L36

[ChrisHines]

@StevenACoffman that's another good idea. My point, more simply stated, is don't limit the information artificially. Give us all the data from the runtime.Frame and let us use it how we want. I don't see any reason to narrow it down to just this:

type Source struct {
    Func string
    File string
    Line int
}

[earthboundkid]

I can imagine if I were writing an error logging service like Sentry or Honeycomb, that I would like to make it so that when you call logger.Error it would take a stack trace and ship that off to be recorded for inspection by developers later.

[rsc]

If we define our own type, we have control over how it marshals. Using runtime.Frame does not give us that control. I'm also not entirely sure that runtime.Frame is really the right API in the runtime, and I'm not sure we should be using it in new APIs.

[rsc]

Note also that we can add to Source over time. @ChrisHines, what information would you want to add beyond Func, File, Line?

[ChrisHines]

Note also that we can add to Source over time. @ChrisHines, what information would you want to add beyond Func, File, Line?

Unknown. I would possibly want anything the runtime can provide.

If the runtime provides more, I might want it. As I've said a few times in the discussion, don't artificially hide information, let it all pass through so we can use it however we want. If I can read the runtime package docs and see the information is available and also see that slog is filtering the information without good reason that will be frustrating. So I really think the burden is on slog to explain why it needs to limit the data. Only providing one stack frame seems like a reasonable limitation for efficiency reasons, but I don't see any reason to hide information about that one frame.

Going way back to when runtime.Frame was added I recall that the initial suggestion was for a function that returned a big tuple of things and I suggested to make it a struct type so it could be expanded later in a compatible way if we wanted. I was happy that choice was made then. I don't understand why it's not the right API here. As I showed above (#59280 (comment)) we can have a defined type in slog that wraps runtime.Frame to add methods for formatting and still gives access to all the data for third parties to use how they want.

[jba]

I would vote for using the a separate Source struct, which can be added to over time. I would rename the field from Func to Function for consistency with runtime.Frame.

[rsc]

If the runtime ever moved to some newer, more efficient API, then we'd be stuck. The Frame exposes things like runtime.Func, which I'd really rather not appear in the slog API. If new important things appear in runtime.Frame, we can make them appear in slog.Source as well.

[ChrisHines]

If the runtime ever moved to some newer, more efficient API, then we'd be stuck. The Frame exposes things like runtime.Func, which I'd really rather not appear in the slog API. If new important things appear in runtime.Frame, we can make them appear in slog.Source as well.

I understand the concern. Note also, however, that I made use of runtime.Frame.Func in my proof-of-concept in #59280 (comment).

It would be nice if we could have some source location ur-value that we believe Go will support for the foreseeable future. If that is not a PC uintptr and it is not runtime.Frame then does that mean we don't have one?

If we don't have one then it seems we must decouple collecting source location data from the slog core implementation and Handler API so that it is easy to write slog extensions that collect source location data in different ways. That would allow us to integrate more efficient APIs for source location with slog as they arise. Specifically I think that means removing the PC field from slog.Record and possibly having some type of hook in slog.Logger that is optionally called to collect source location data to include in the record somehow.

[jba]

@ChrisHines, the current issue is limited to what the built-in handlers pass to ReplaceAttr. I think Record.PC can act as a "source location ur-value" for custom handlers.

[jba]

edit: modified TextHandler to return to source=file:line

Here is my proposal:

Add Source:

type Source struct {
    // Function is the package path-qualified function name containing the                                                                                    
    // source line. If non-empty, this string uniquely identifies a single                                                                                    
    // function in the program. This may be the empty string if not known.                                                                                    
    Function string
    // File and Line are the file name and line number (1-based) of the source                                                                                
    // line. These may be the empty string and zero, respectively, if not known.                                                                              
    File string
    Line int
}

There are no exported methods on Source.

The default handler continues to output source locations as "file:line".

If HandlerOptions.AddSource is true, TextHandler renders a Source with the old file:line syntax and JSONHandler renders it as a group with key SourceKey and a list of the non-zero fields. So TextHandler's output would look like

source=f.go:4

and JSONHandler's output would look like

"source":{"function":"my/package.F",file":"f.go","line":4}

If AddSource is true and ReplaceAttr is non-nil, ReplaceAttr will be passed an Attr with key SourceKey and a value of type *Source. It can modify that value's fields in-place or replace it completely. As an example of the former, here is part of the ReplaceAttr function from the wrapping example:

 if a.Key == slog.SourceKey {
    source := a.Value.Any().(*slog.Source)
    source.File = filepath.Base(source.File)
}

LIkely questions:

• Why change the JSON output format from the familiar "file:line"?
  One obvious reason is that we now have the function name. But more importantly, this is structured logging, and we have a structure. It feels like the right thing to do. Concretely, it makes it easier for downstream processors to handle source location information: they don't have to parse to recover the components.

• Why pass *Source to ReplaceAttr instead of Source? Isn't that an unnecessary allocation?
  The assignment to any would cause an allocation anyway. And if someone wanted to modify a Source as in the example above, they would have to create a new Value to return, causing a second allocation.

[AndrewHarrisSPU]

@jba

Here is my proposal

I think "gets Source" is an improvement on "gets PC", and covers a lot of use cases. The use of Source is a bit nuanced - no methods (not even Source.LogValue) is interesting, but I'm buying that the allocation behavior is worth it.

[jba]

no methods (not even Source.LogValue)

I forgot to mention that Source.LogValue doesn't work: values are resolved before being passed to ReplaceAttr, so it wouldn't see a *Source. Instead the built-in handlers have special-case code for the source location, as they did before.

[rsc]

Based on the discussion above, this proposal seems like a likely accept.
— rsc for the proposal review group

[ChrisHines]

@ChrisHines, the current issue is limited to what the built-in handlers pass to ReplaceAttr. I think Record.PC can act as a "source location ur-value" for custom handlers.

OK. Then I am confused why we Record.PC is OK for that part of the slog API but must be made opaque for ReplaceAttr. Can someone explain the rationale for that?

[jba]

The slog API has two distinct parts.

The majority of users will only use Logger. They will know about creating handlers, perhaps with HandlerOptions, but they don't need to think about the Handler or Record types. This part of the API emphasizes simplicity and ease of use. These users should not have to know what a pc is or how to use it with runtime.Callers.

The relatively few handler writers will need to deal with Handler and Record. This part of the API emphasizes flexibility and power. Exposing pcs to these users makes sense.

To answer the obvious question, yes, we did think about having two packages. But we decided the extra ceremony wasn't worth it.

[ChrisHines]

The majority of users will only use Logger. They will know about creating handlers, perhaps with HandlerOptions, but they don't need to think about the Handler or Record types.

I agree with the general premise of multiple classes of slog users. However, it seems to me that once someone delves into writing ReplaceAttr functions they quickly need to understand something about the Handler and Record part of the API.

It seems to me that the ReplaceAttr code is co-located with the construction of the chosen Handler and separate from most of the calls to logger.Info type functions. If the user can't do what they want with a ReplaceAttr function and the only alternative is to write a middleware Handler then it seems like the choice to make the PC opaque forces them to learn more of the slog API rather than less.

[rsc]

No change in consensus, so accepted. 🎉
This issue now tracks the work of implementing the proposal.
— rsc for the proposal review group

[gopherbot]

Change https://go.dev/cl/486376 mentions this issue: log/slog: add Source type for source location

[ChrisHines]

I am disappointed that this was accepted without any reply to my last comment. Maybe it wasn't fully clear in that post, but I would hope from the discussion context it was clear that I was advocating for giving access to the PC value in the ReplaceAttr function somehow, maybe as part of the new Source struct. :(

[jba]

Sorry about that, Chris. I did take your point, but ultimately we thought it was better to keep the split as we have it, with pcs and handlers together on the advanced side.

[ChrisHines]

OK. I wish I was more persuaded, but so be it, I guess. Thanks for the quick reply.