Hacker News Board Hacker News, browsed like a classic message board
Live data from Hacker News

Structured logging with slog

go.dev

Post reply on HN
Print view View original

151–160 of 174 posts

Re: Structured logging with slog

#151

Post by scottlamb »

tstack wrote: post #150
scottlamb wrote: post #148

Earlier quoted context omitted.

The idea of structured logs is that every place in the code where you define a log message, you can throw in extra attributes (key/value) pairs. As far as I can tell, the lnav feature you describing allows you to define a JSON log format with predefined fields. But if some log message uses an attribute you haven't anticipated in the format definition, there's no way to see it in the pretty-printed output or filter on…

> But if some log message uses an attribute you haven't anticipated in the format definition, there's no way to see it in the pretty-printed output Properties in the log message that are not in the "line-format" are displayed below the message as key-value pairs. As an example, the bunyan[1] log format[2] has a few standard properties that are used in the "line-format" to form the main message. Then, as shown in this…

Thanks for this. When I switched my project to structured logging, I deleted its lnav log format file and was sad about it. I'll add one back now!

Re: Structured logging with slog

#152

Post by tstack »

scottlamb wrote: post #151
tstack wrote: post #150

Earlier quoted context omitted.

> But if some log message uses an attribute you haven't anticipated in the format definition, there's no way to see it in the pretty-printed output Properties in the log message that are not in the "line-format" are displayed below the message as key-value pairs. As an example, the bunyan[1] log format[2] has a few standard properties that are used in the "line-format" to form the main message. Then, as shown in this…

Thanks for this. When I switched my project to structured logging, I deleted its lnav log format file and was sad about it. I'll add one back now!

> I also don't see something else I might want: a way to have a different "view" for certain log messages; maybe to switch between filtering/viewing particular ones, maybe to just have line-format be conditional based on the detected format.

Have a look at the following comment on an issue that might be similar to what you're thinking of:

https://github.com/tstack/lnav/issues/1065#issuecomment-1602...

> I guess I can sort of do this based on `module-field`? but I might want it lighter-weight/finer-grained than that.

Unfortunately, the "module-field" does not work for JSON logs at the moment. It's something I should really fix.

Ultimately, lnav has existed for almost two decades now and I use it every day. So, it's always seeing improvements. If you're having a problem with it, file an issue on github. I don't always get around quickly to fixing other folks feature requests / issues, but it tends to happen eventually.

Thanks.

Re: Structured logging with slog

#153

Post by lsaferite »

duskwuff wrote: post #47
insanitybit wrote: post #9

Structured logging is a very sane default. Even if you end up with `{"msg": "blah blah blah"}` at least you have room to grow in the future.

And if your current logging is along the lines of log.Printf("failed to frob %s: %s", thing, error) then moving from that to: slog.Error("failed to frob", "thing", thing, "error", error) isn't terribly difficult, and will make log analysis dramatically easier.

Given your example of

    log.Printf("failed to frob %s: %s", thing, error)
Wouldn't you just want to use

    slog.Error("failed to frob", thing, error)
That keeps the _value_ of `thing` as the key and the _value_ of `error` as the value. That would keep more in line with your first example.

Re: Structured logging with slog

#154

Post by jjice »

morelisp wrote: post #115
jjice wrote: post #70

Earlier quoted context omitted.

PHP did so with PSR-3 as well https://www.php-fig.org/psr/psr-3/ .

A PSR is not de facto, nor is this structured.

No it's not de facto but what can be defacto? It's pretty well followed by the community and I think that's about all you can get.

Re: Structured logging with slog

#155

Post by morelisp »

jjice wrote: post #154
morelisp wrote: post #115

Earlier quoted context omitted.

A PSR is not de facto, nor is this structured.

No it's not de facto but what can be defacto? It's pretty well followed by the community and I think that's about all you can get.

The core question of this subthread was what, if anything, the effect of only having a de facto logging solution was on a language community. The community easily coalescing around a de jure solution (and for a different problem with a significantly smaller API surface) is not really relevant to that.

Re: Structured logging with slog

#156

Post by duskwuff »

lsaferite wrote: post #153
duskwuff wrote: post #47

Earlier quoted context omitted.

And if your current logging is along the lines of log.Printf("failed to frob %s: %s", thing, error) then moving from that to: slog.Error("failed to frob", "thing", thing, "error", error) isn't terribly difficult, and will make log analysis dramatically easier.

Given your example of log.Printf("failed to frob %s: %s", thing, error) Wouldn't you just want to use slog.Error("failed to frob", thing, error) That keeps the _value_ of `thing` as the key and the _value_ of `error` as the value. That would keep more in line with your first example.

Probably not. ELK-style log analysis tools benefit from having messages follow a consistent schema. Using a variable as a key makes indexing much more difficult, and can make it impossible to detect patterns where (for example) a single error appears sporadically across many different values of "thing".

If "thing" were a variable with a small cardinality (like a class name or an enumeration), that might change matters. But I'd still be reluctant to do that; having the two values available in separate fields, rather than as a single key/value pair, is a lot more flexible.

Re: Structured logging with slog

#157

Post by lsaferite »

duskwuff wrote: post #156
lsaferite wrote: post #153

Earlier quoted context omitted.

Given your example of log.Printf("failed to frob %s: %s", thing, error) Wouldn't you just want to use slog.Error("failed to frob", thing, error) That keeps the _value_ of `thing` as the key and the _value_ of `error` as the value. That would keep more in line with your first example.

Probably not. ELK-style log analysis tools benefit from having messages follow a consistent schema. Using a variable as a key makes indexing much more difficult, and can make it impossible to detect patterns where (for example) a single error appears sporadically across many different values of "thing". If "thing" were a variable with a small cardinality (like a class name or an enumeration), that might change matter…

Oh, sorry if I was unclear, I wouldn't do that. I was just suggesting that it was closer to the original log message design. :) I'm a massive structured logging fan and have used it for quite a long time. In go I've used zerolog mostly, but I bring structured logs to whatever language I'm working with.

Re: Structured logging with slog

#158

Post by physicles »

kiitos wrote: post #139
physicles wrote: post #131

Earlier quoted context omitted.

Indeed, our code base is littered with fmt.Errorf("...: %w", err), but that only works if enough places in the code add context. Currently only about 15% of return sites do this. And I disagree that the cost of carrying around the callstack is something to worry about. Errors are akin to exceptions in C++/Java: no happy path should rely on errors for control flow (except io.EOF, but that won't generate a call stack).…

Every error should be annotated at the call site. fmt.Errorf("...: %w", err) isn't litter, it should be a basic expectation of any code which passes code review. > Errors are akin to exceptions in C++/Java: no happy path should rely on errors for control flow (except io.EOF, but that won't generate a call stack). They should be rare enough that any cost below about 1ms and 10k is negligible. This may be true in C++ o…

I think there's less daylight between us than it seems.

> Errors are normal, not exceptional.

The _handling_ of errors is normal. Code that doesn't consider errors is not production code.

And granted, in Go, control flow is driven by errors more often than in C++ or Java. Sentinel error values are common. See for example all usage of error.Is, checking for io.EOF, packages that define ErrSituationA and ErrSituationB, etc.

But my argument was about errors that can't be dealt with locally, where the origination and ultimate handling are very far apart. A given flow will encounter these errors relatively rarely compared to the happy path (and if it's not rare, you probably need to fix or change something). Having an intuition about this is important for predicting your code's performance. For example:

- The SQL call failed because the network connection dropped; client gets 500 or 502, or retry.

- A call to an external service failed because the network was bad; it gets retried.

- The SQL call succeeded, but the record the client asked for wasn't found, so the client gets a 404.

- Writing to a temporary file failed because the disk is full, so some batch job fails with an error.

Apart from potential concerns about DoS, worrying too much about the performance of error handling in these relatively rare cases is absolutely premature optimization.

DoS isn't even a concern. I just benchmarked capturing a call stack in Go, and it's on the order of a few microseconds. Unless you're in performance critical code (and you're benchmarking, right?), it's fine.

Re: Structured logging with slog

#159

Post by physicles »

morelisp wrote: post #134
physicles wrote: post #131

Earlier quoted context omitted.

Indeed, our code base is littered with fmt.Errorf("...: %w", err), but that only works if enough places in the code add context. Currently only about 15% of return sites do this. And I disagree that the cost of carrying around the callstack is something to worry about. Errors are akin to exceptions in C++/Java: no happy path should rely on errors for control flow (except io.EOF, but that won't generate a call stack).…

Are you suggesting it's OK if ParseInt failures take 1ms? Or should ParseInt use a different "kind of error" that's not commensurate with the regular error kind? Do you think most errors look more like ParseInt, or more like sql.Open where 1ms might be acceptable? (Do you think a call stack from the insides of sql.Open would be useful? My experience, mostly not...) So the stacks should probably only be for "complex e…

See my response to a sibling. I wasn't clear; I was implicitly differentiating between these:

1. errors that can be handled locally (such as parsing; in other languages, these situations are often signaled with return values instead of exceptions)

2. errors that can't be handled locally (such as network errors; other languages use exceptions for these)

My argument was that worrying too much about error handling performance in #2 is premature optimization. 1ms is extreme, but the actual figure of capturing a call stack in Go -- several microseconds, by my benchmark -- puts it squarely in the "don't worry about it unless your code is performance-critical" category.

Re: Structured logging with slog

#160

Post by User23 »

yencabulator wrote: post #98
User23 wrote: post #91

Just log to sqlite. It’s literally better than all the alternatives, but for some reason nobody does.

That'd be a slog.Handler, not a reason to avoid the new standard API.

That’s missing the point. SQL itself, specifically the sqlite dialect, is the new standard API I’m advocating. I’m claiming that any traditional log library interface is going to be worse.
Post reply on HN