slog: Support structured logging #17

ellemouton · 2024-09-10T17:56:02Z

This PR does a few things:

turns this package into a go module
Expands the existing Logger interface with new structured logging messages (DebugS, InfoS etc)
let's the existing default implementation implement these new methods (in an unstructured way)
add a new log/slog implementation of the Logger that uses proper structured logging.

Details

This new implementation is flexible enough to allow callers to pass in their own slog.Handlers (which underneath could be a json formatter, a logfmt formatter or any anything else like a charm Handler

Usage

The idea is that the msg passed to an S method should be a constant. The attr... params are then used for key-value pairs.

log.InfoS(ctx, "User performed a request",
			"user_id", id,
			"request_uri: ", uri)

Each new method also takes a context.Context. The WithCtx helper can be used to attach any key-value pairs to a
context and then when the logger is called, the pairs will be extracted from the context and added as attributes in the log.

For example:

ctx := WithCtx(context.Background(), "user_id", id)

// This log will include both the `user_id` and `request_uri` attributes.
log.InfoS(ctx, "User performed a request", "request_uri", uri)

guggero

Very nice! LGTM, just a couple of nits and/or suggestions.
Really excited to get this in so we can have structured logs in lnd.

go.mod

slog.go

ellemouton

Thanks @guggero 📁

go.mod

slog.go

ellemouton · 2024-09-16T10:04:09Z

Note to reviewers: Im going to look into writing a Default Handler that can be passed to the NewSLog() constructor that will result in the output looking identical to the existing sublogger output. If this is done, then we can actually just completely remove the subLog impl in this PR

ellemouton · 2024-09-17T17:51:10Z

Note: I have updated the PR to include a default Handler that can be used with the new NewSlogger method :)

ellemouton · 2024-09-18T11:00:51Z

I have also added a test now

slog.go

guggero

Great stuff! Super cool that we can get all of those features with zero additional dependencies 💯

guggero · 2024-09-19T09:08:06Z

log.go

+//
+// This is part of the Logger interface implementation.
+func (l *subLog) TraceS(_ context.Context, msg string, attrs ...any) {
+	l.Tracef(msg, attrs...)


Do we need to process the attrs first? Or is the assumption that msg would never contain formatting directives? Then perhaps we should call into l.Trace() instead.
Example of what I mean:

bar := "bar" subLog.TraceS(ctx, "incorrectly used directive: %v", "foo", bar)

What I think would be printed:

incorrectly used directive: foo%!(EXTRA string=bar)

What the user would expect to be printed:

incorrectly used directive: foo=bar

cool yeah agreed

ah - the thing is thought that for this implementation, under the hood there is not actually structured logging going on. So the output we get will not look like "key=value" etc. So I used the *f methods just so that we are passing the msg and attr to some underlying impl. the non f methods only take ...attr so the message would not be used.

So this was just to somewhat complete this implementation. In reality if callers want structured logging, they should use the new slog implementation. In the LL fork PR, I completely remove this impl anyways. So I think instead of trying to get this to work as if it is using slog underneath, let's just add a warning to the impl saying it works like the *f methods.

Taking a step back: i think we arent gonna get this into this repo anyways and so we will carry on with the forked version which removes this impl anyways

EDIT given latest updates to the convo: perhaps I should just look into a best effort way of converting the given attributes to k=v pairs and writing those to the writer

handler.go

guggero · 2024-09-19T09:11:36Z

handler.go

+		d.appendAttr(buf, attr)
+	}
+
+	// Append slog attributes


nit: missing full stop.

handler_test.go

yyforyongyu

Pending Oli's comments, otherwise LGTM🙏

ellemouton · 2024-09-23T04:37:52Z

Ok yall: thanks so much for review here! I think we are gonna go with the forking path here as I dont think the maintainer(s) of the repo is/are active.

So let's move discussion & final review there: lightninglabs#1

EDIT: nevermind... if we fork this then we'd also need to fork every other btcsuite PR that we use that imports the logger....
Ideally we need merge here.

Roasbeef · 2024-09-23T06:46:35Z

cc @davecgh

davecgh · 2024-09-23T14:04:02Z

@Roasbeef What's up? I guess maybe perms? I really no longer have anything to do with maintaining btc things.

A couple of things I noticed on a quick review though is:

Making this a module that requires Go 1.21 will force every single consumer, even those that do not want to use the new logging semantics, to be hoisted forward and themselves require Go 1.21. We no longer use this code, so it wouldn't affect us, but if we did, this change would 100% be a showstopper as a result of that.
Allowing and encouraging ANSI codes (styled output) is just asking for log injection attacks. That is something I personally would never allow in anything even remotely related to cryptocurrency code.

davecgh · 2024-09-23T14:27:10Z

Aside from the two aforementioned things, and some nits like missing copyright headers, the changes otherwise look fine.

As I said though, I no longer maintain anything btc, so I'll defer to @Roasbeef to make merge decisions.

ellemouton · 2024-09-24T02:31:46Z

Making this a module that requires Go 1.21

The reason that go1.21 was chosen is cause log/slog is only available in that version onwards.

Allowing and encouraging ANSI codes (styled output) is just asking for log injection attacks

it is off by default - but if we are worried about this, i can update the PR to just allow the user to pass in various Style(string)string call-backs instead of specifying anything specific here. Then the risk is totally left up to the caller.

so I'll defer to @Roasbeef to make merge decisions.

Ok cool

davecgh · 2024-09-24T03:00:37Z

The reason that go1.21 was chosen is cause log/slog is only available in that version onwards.

Aye, I understand the reasoning. The code was changed over to define Level as a slog.Level (and some technically incompatible changes to the constant values, but since everything really should be using the constants, that doesn't matter so much) and it also now embeds a new instance of a log/slog.

Regardless of the rationale though, the effect is that anything that uses it will necessarily be hoisted forward thereby forcing everything that uses those things to also be hoisted forwards all the way down the dependency stack.

For example, take github.com/btcsuite/btcd/wire. It currently only requires Go 1.17 and it's imported by nearly 3000 modules, a huge number of which themselves only require Go 1.17. This would force every single one of those, and anything that uses them to now require Go 1.21. For many projects, that would prevent them from being able to update to the latest versions of the code.

Even something relatively simple like github.com/btcsuite/btcd/btcutil/psbt currently only requires Go 1.17 and is imported by ~100 modules, many of which themselves also only require Go 1.17.

Without looking super closely, I imagine it would be possible to make this compatible with Go 1.17 by implementing the relevant slog interface and not defining anything explicitly in terms of the slog types. That way, it'll still work fine with older Go versions and still be able to interop with the log/slog package in Go 1.21+.

ellemouton · 2024-09-30T09:58:04Z

the effect is that anything that uses it will necessarily be hoisted forward thereby forcing everything that uses those things to also be hoisted forwards all the way down the dependency stack.

But this is only the case if they want to update to the latest version right? And they would only want to update to the latest version if they want the new features which in this case is slog stuff which would anyways require them to run go 1.21.

The only other reason they'd want to update their btclog dep is if there is some bug found in the old code & they want to update to include just that fix - but for that, we can just maintain a branch that only includes the old implementation & backfills the fix. That way they can point to that branch.

It just seems like we should be able to move logging forward and take advantage of new features that go provides us in terms of logging so that those users that want to take advantage of newer features can do so

I imagine it would be possible to make this compatible with Go 1.17 by implementing the relevant slog interface and not defining anything explicitly in terms of the slog types. That way, it'll still work fine with older Go versions and still be able to interop with the log/slog package in Go 1.21+.

Meaning just update the interface but have the implementation be defined elsewhere (ie not in this repo)? This would work except for the tricky situation with the slog.Levels since I think slog requires the use of its Level numbers... so that makes things tricky I think... I'll double check this to make sure though

Roasbeef · 2024-10-02T22:22:23Z

I think we might be able to get away with using the old version of the package: https://pkg.go.dev/golang.org/x/exp/slog. It doesn't look to use as many recent language features.

ellemouton · 2024-10-15T12:01:01Z

Ok, I've updated this to create a v2 module instead so that there is no blast radius. I've also removed any direct styling functionality from this and instead have added functional options that will allow a caller of the new module to add its own styling if it wishes

ellemouton · 2024-10-15T18:34:47Z

@yyforyongyu & @guggero - just tagging you guys for a re-review here if possible given the new structure.

The biggest "controversial" thing here (and difference from the previous version of this PR) is probably the re-use of the Level type from the v1 module.

guggero

Just a couple of nits, otherwise LGTM 💯

v2/interface.go

v2/buffer.go

v2/handler.go

v2/interface.go

yyforyongyu · 2024-10-16T16:38:32Z

v2/attrs.go

+
+// mergeAttrs returns the attributes from the context merged with the provided attributes.
+func mergeAttrs(ctx context.Context, attrs []any) []any {
+	resp, _ := ctx.Value(attrsKey{}).([]any) // We know the type.


if that's the case maybe we can just panic here if !ok

we dont want it to panic cause if nothing has been set yet (ie, there is nothing to append to), then ok will actually be false

v2/buffer.go

v2/handler.go

yyforyongyu · 2024-10-16T16:55:45Z

v2/log.go

+// attributes with btclog.LevelTrace to the log.
+//
+// This is part of the Logger interface implementation.
+func (l *sLogger) TraceS(ctx context.Context, msg string, attrs ...any) {


Wanna point out this does create some overhead as we now need to be concerned about context leak? Is Background context auto GCed?

I think passing a context around in go is generally considered a good pattern. If we are doing lots of context.Background() calls, then it means we should update the parent function to take a context. ie, if we are creating lots of context.Backgrounds() then they really should actually be context.TODO().

Passing in the context here is really nice cause we can add request scoped attributes that we want to include in logs to the context and then dont need to remember to log them

ellemouton · 2024-10-17T08:16:51Z

Thanks for the review yall - added LICENSE to v2 & copied the golang license context to the appropriate file

Roasbeef

LGTM 🪛

ziggie1984 · 2024-10-21T09:41:34Z

v2/handler_test.go

+				log.Critical("Critical")
+			},
+			expectedLog: `[TRC]: Trace
+[DBG]: Debug


hmm formatting seems weird here.

no real other way to define this such that things match on a char by char level. It's just a test too :)

ziggie1984 · 2024-10-21T09:56:42Z

v2/LICENSE

@@ -0,0 +1,16 @@
+ISC License


maybe you can describe a short how-to create a v2 library of a specific module in case we need it in the future.

ziggie1984 · 2024-10-22T11:50:58Z

v2/handler.go

+// appendValue writes the given slog.Value to the buffer.
+func appendValue(buf *buffer, v slog.Value) {
+	defer func() {
+		// Recovery in case of nil pointer dereferences.


can a slog.Value be nil here ?

This was referenced Sep 10, 2024

log: structured logging lightningnetwork/lnd#9083

Merged

add Lnotimestamp flag #16

Closed

ellemouton force-pushed the slog branch from 8f637ad to cbf662f Compare September 11, 2024 09:40

guggero approved these changes Sep 16, 2024

View reviewed changes

go.mod Outdated Show resolved Hide resolved

slog.go Outdated Show resolved Hide resolved

slog.go Outdated Show resolved Hide resolved

ellemouton force-pushed the slog branch 2 times, most recently from 514790a to d81e157 Compare September 16, 2024 09:20

ellemouton commented Sep 16, 2024

View reviewed changes

go.mod Outdated Show resolved Hide resolved

slog.go Outdated Show resolved Hide resolved

slog.go Outdated Show resolved Hide resolved

ellemouton force-pushed the slog branch from d81e157 to 1ef3989 Compare September 17, 2024 17:49

ellemouton mentioned this pull request Sep 17, 2024

slog: structured logging lightninglabs/btclog#1

Closed

ellemouton force-pushed the slog branch 3 times, most recently from c3830ec to 9a10e4f Compare September 18, 2024 11:00

yyforyongyu reviewed Sep 18, 2024

View reviewed changes

slog.go Outdated Show resolved Hide resolved

guggero reviewed Sep 19, 2024

View reviewed changes

yyforyongyu approved these changes Sep 19, 2024

View reviewed changes

ellemouton closed this Sep 23, 2024

ellemouton reopened this Sep 23, 2024

ellemouton force-pushed the slog branch 2 times, most recently from c138569 to f2bad85 Compare October 14, 2024 16:07

ellemouton force-pushed the slog branch from f2bad85 to b5e8a30 Compare October 15, 2024 11:59

guggero approved these changes Oct 16, 2024

View reviewed changes

v2/interface.go Outdated Show resolved Hide resolved

v2/interface.go Outdated Show resolved Hide resolved

v2/buffer.go Show resolved Hide resolved

v2/handler.go Outdated Show resolved Hide resolved

yyforyongyu reviewed Oct 16, 2024

View reviewed changes

ellemouton added 3 commits October 17, 2024 10:03

v2: create a v2 module

76d6eda

v2: extend Logger with structured logging calls

66304ed

v2: implement default handler and logger using slog

e9988e6

ellemouton force-pushed the slog branch from b5e8a30 to e9988e6 Compare October 17, 2024 08:10

guggero approved these changes Oct 17, 2024

View reviewed changes

Roasbeef approved these changes Oct 17, 2024

View reviewed changes

Roasbeef merged commit 3428138 into btcsuite:master Oct 17, 2024

ellemouton deleted the slog branch October 17, 2024 18:35

ziggie1984 reviewed Oct 21, 2024

View reviewed changes

ziggie1984 reviewed Oct 22, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

slog: Support structured logging #17

slog: Support structured logging #17

ellemouton commented Sep 10, 2024

guggero left a comment

ellemouton left a comment

ellemouton commented Sep 16, 2024

ellemouton commented Sep 17, 2024

ellemouton commented Sep 18, 2024

guggero left a comment

guggero Sep 19, 2024

ellemouton Sep 23, 2024

ellemouton Sep 23, 2024

ellemouton Sep 30, 2024

guggero Sep 19, 2024

yyforyongyu left a comment

ellemouton commented Sep 23, 2024 •

edited

Loading

Roasbeef commented Sep 23, 2024

davecgh commented Sep 23, 2024 •

edited

Loading

davecgh commented Sep 23, 2024

ellemouton commented Sep 24, 2024 •

edited

Loading

davecgh commented Sep 24, 2024 •

edited

Loading

ellemouton commented Sep 30, 2024 •

edited

Loading

Roasbeef commented Oct 2, 2024

ellemouton commented Oct 15, 2024

ellemouton commented Oct 15, 2024

guggero left a comment

yyforyongyu Oct 16, 2024

ellemouton Oct 17, 2024

yyforyongyu Oct 16, 2024

ellemouton Oct 17, 2024

ellemouton commented Oct 17, 2024

Roasbeef left a comment

ziggie1984 Oct 21, 2024

ellemouton Oct 21, 2024

ziggie1984 Oct 21, 2024

ziggie1984 Oct 22, 2024

slog: Support structured logging #17

slog: Support structured logging #17

Conversation

ellemouton commented Sep 10, 2024

Details

Usage

guggero left a comment

Choose a reason for hiding this comment

ellemouton left a comment

Choose a reason for hiding this comment

ellemouton commented Sep 16, 2024

ellemouton commented Sep 17, 2024

ellemouton commented Sep 18, 2024

guggero left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yyforyongyu left a comment

Choose a reason for hiding this comment

ellemouton commented Sep 23, 2024 • edited Loading

Roasbeef commented Sep 23, 2024

davecgh commented Sep 23, 2024 • edited Loading

davecgh commented Sep 23, 2024

ellemouton commented Sep 24, 2024 • edited Loading

davecgh commented Sep 24, 2024 • edited Loading

ellemouton commented Sep 30, 2024 • edited Loading

Roasbeef commented Oct 2, 2024

ellemouton commented Oct 15, 2024

ellemouton commented Oct 15, 2024

guggero left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ellemouton commented Oct 17, 2024

Roasbeef left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ellemouton commented Sep 23, 2024 •

edited

Loading

davecgh commented Sep 23, 2024 •

edited

Loading

ellemouton commented Sep 24, 2024 •

edited

Loading

davecgh commented Sep 24, 2024 •

edited

Loading

ellemouton commented Sep 30, 2024 •

edited

Loading