Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
jba opened this issue Mar 27, 2023 · 29 comments
Closed

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

jba opened this issue Mar 27, 2023 · 29 comments

Comments

@jba
Copy link
Contributor

jba commented Mar 27, 2023

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
Copy link

AndrewHarrisSPU commented Mar 27, 2023

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
Copy link

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
Copy link
Contributor

rsc commented Mar 28, 2023

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
Copy link
Contributor

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

@AndrewHarrisSPU
Copy link

AndrewHarrisSPU commented Mar 28, 2023

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
Copy link
Contributor

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
Copy link
Contributor

rsc commented Mar 29, 2023

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
Copy link

StevenACoffman commented Mar 29, 2023

@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
Copy link
Contributor

@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
Copy link
Contributor

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
Copy link
Contributor

rsc commented Mar 31, 2023

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
Copy link
Contributor

rsc commented Mar 31, 2023

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

@ChrisHines
Copy link
Contributor

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
Copy link
Contributor Author

jba commented Apr 4, 2023

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
Copy link
Contributor

rsc commented Apr 5, 2023

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
Copy link
Contributor

ChrisHines commented Apr 5, 2023

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
Copy link
Contributor Author

jba commented Apr 8, 2023

@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
Copy link
Contributor Author

jba commented Apr 8, 2023

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.

@jba jba changed the title proposal: log/slog: ReplaceAttr gets PC instead of file:line proposal: log/slog: ReplaceAttr gets Source instead of file:line Apr 8, 2023
@jba jba changed the title proposal: log/slog: ReplaceAttr gets Source instead of file:line proposal: log/slog: ReplaceAttr gets Source struct instead of file:line Apr 8, 2023
@AndrewHarrisSPU
Copy link

@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
Copy link
Contributor Author

jba commented Apr 9, 2023

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
Copy link
Contributor

rsc commented Apr 12, 2023

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

@ChrisHines
Copy link
Contributor

@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
Copy link
Contributor Author

jba commented Apr 13, 2023

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
Copy link
Contributor

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
Copy link
Contributor

rsc commented Apr 19, 2023

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

@rsc rsc changed the title proposal: log/slog: ReplaceAttr gets Source struct instead of file:line log/slog: ReplaceAttr gets Source struct instead of file:line Apr 19, 2023
@rsc rsc modified the milestones: Proposal, Backlog Apr 19, 2023
@gopherbot
Copy link

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

@ChrisHines
Copy link
Contributor

ChrisHines commented Apr 19, 2023

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
Copy link
Contributor Author

jba commented Apr 19, 2023

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
Copy link
Contributor

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

@dmitshur dmitshur modified the milestones: Backlog, Go1.21 Jun 4, 2023
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Add a struct called Source that holds the function, file and line
of a location in the program's source code.

When HandleOptions.AddSource is true, the ReplaceAttr function will
get an Attr whose key is SourceKey and whose value is a *Source.

We use *Source instead of Source to save an allocation. The pointer
and the value each cause one allocation up front: the pointer when it
is created, and the value when it is assigned to the `any` field of a
slog.Value (handle.go:283). If a ReplaceAttr function wanted to modify
a Source value, it would have to create a new slog.Value to return,
causing a second allocation, but the function can modify a *Source in
place.

TextHandler displays a Source as "file:line".

JSONHandler displays a Source as a group of its non-zero fields.

This replaces the previous design, where source location was always a
string with the format "file:line". The new design gives users more
control over how to output and consume source locations.

Fixes golang#59280.

Change-Id: I84475abd5ed83fc354b50e34325c7b246cf327c7
Reviewed-on: https://go-review.googlesource.com/c/go/+/486376
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
eric pushed a commit to fancybits/go that referenced this issue Sep 7, 2023
Add a struct called Source that holds the function, file and line
of a location in the program's source code.

When HandleOptions.AddSource is true, the ReplaceAttr function will
get an Attr whose key is SourceKey and whose value is a *Source.

We use *Source instead of Source to save an allocation. The pointer
and the value each cause one allocation up front: the pointer when it
is created, and the value when it is assigned to the `any` field of a
slog.Value (handle.go:283). If a ReplaceAttr function wanted to modify
a Source value, it would have to create a new slog.Value to return,
causing a second allocation, but the function can modify a *Source in
place.

TextHandler displays a Source as "file:line".

JSONHandler displays a Source as a group of its non-zero fields.

This replaces the previous design, where source location was always a
string with the format "file:line". The new design gives users more
control over how to output and consume source locations.

Fixes golang#59280.

Change-Id: I84475abd5ed83fc354b50e34325c7b246cf327c7
Reviewed-on: https://go-review.googlesource.com/c/go/+/486376
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Jonathan Amsterdam <jba@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

9 participants