Hacker News new | past | comments | ask | show | jobs | submit login
Structured logging with slog (go.dev)
275 points by spacey on Aug 22, 2023 | hide | past | favorite | 168 comments



Admittedly I'm not a huge fan of having:

  slog.Info("hello, world", "user", os.Getenv("USER"))
It's a little magical that "user" is a key. So what if you have multiple key-value pairs? Arguably it most likely going to be obvious which is the keys, but having every other value be a key and the rest values seems a little clumsy.

I really like Pythons approach where you can have user="value" it makes things a bit more clear.


I think Uber chose a better approach for their Go logging library called Zap [1]

    logger.Info("failed to fetch URL",
      // Structured context as strongly typed Field values.
      zap.String("url", url),
      zap.Int("attempt", 3),
      zap.Duration("backoff", time.Second),
    )
They also have zap.Error(err) which generates the "error" key as a convention.

[1] https://github.com/uber-go/zap


You can reproduce that example with slog verbatim by changing zap to slog.

For example: https://pkg.go.dev/golang.org/x/exp/slog#example-Group


As mentioned in the article, Zap's SugaredLogger has roughly the same thing https://pkg.go.dev/go.uber.org/zap

    sugar.Infow("failed to fetch URL",
      "url", "http://example.com",
      "attempt", 3,
      "backoff", time.Second,
    )
Really slog presents mostly the same two APIs as Zap, with a single entrypoint.


`[level]w` supports both key/value pairs and individual `zap.Type(key, value)` values combined fwiw, so for that part the API is essentially the same too


Slog allows doing that by creating Attr structs directly.


> It's a little magical that "user" is a key. So what if you have multiple key-value pairs?

You... add them afterwards? It's really just a plist (https://www.gnu.org/software/emacs/manual/html_node/elisp/Pr...), that's hardly novel. The method takes any number of parameters and pairs them up as key, value.

Or if you really hate yourself, you use LogAttrs with explicitly constructed Attr objects.

> I really like Pythons approach where you can have user="value" it makes things a bit more clear.

The trouble is, Go doesn't have keyword parameters so that doesn't work.


It sure has maps though... logrus famously uses `logrus.Fields{"key": "value"}`


And logrus is one of the slowest loggers by far, in part because of its heavy map usage.


It's also the reflect on the value part which slows down things. It could be improved but it's hard to do that without breaking interface. It's so widely used that a major bump wouldn't that useful.


I'd expect it to be mostly called on map literals, at least a compile time constant set of keys. That should be amenable to a targeted compiler optimisation.


It’s not without precedence, for example: https://pkg.go.dev/strings#NewReplacer

I don’t mind it. You can use LogAttrs if you want to be explicit.

Although I do wonder if there’s anything tricky with the type system that is preventing something like this from being supported: https://go.dev/play/p/_YV7sYdnZ5V


I think go loggers have tried to move away from passing log entries as maps for performance reasons.


That seems like a problem that should be solved. Logging structured data is a very basic expectation.


This is structured logging. Stubbornly insisting that "structured logging" === "map" is dumb and ignores a large fraction of use cases where performance matters.


Are there languages that solve the “performance“ problem with maps? In fact, isn’t Go one of them?


In this use case using maps doesn't solve any problem, requires at least one allocation, and requires hashing each key. This is not even an interesting discussion.


I can see the case for flat logging, aka. key value logging, as an optimization for very, very performance critical code that needs to emit string logs. That however, isn’t mainstream in my experience. The far, far more common case is logging in code with complex data-driven behaviors where the data is structured (more than one level, not flat) and where forensic debugging via logs is a critical activity. If that’s not your world, you should only be interested in it if you’re interested in the community at large. If you’re not, that’s cool.


I think you seem to be arguing that the end result should be a "map"-like structure, whereas the other commenter is arguing about the interface to the logging library not being based on maps. These are not the same and taking maps in the interface is likely to incur allocations, yes. Having to specify your key-value pairs without maps is the only downside to not taking fully constructed maps in the interface.


Adding the application/component code to do ”good logging” is tedious. Friction in the interface decreases the probability it will be done well, and consistently. I think the interface matters, and while it’s a second order problem it does impact system quality in the long run.

Just my opinions here. I don’t question the value of slog as it sits, just could have been better for the community at large is all.


Avoiding the map allocation & construction cost is way harder than avoiding the use of a map, like zap and slog.LogAttrs do.


Is ordering of the keys guaranteed to be the same as in the literal?


Order should be preserved up to the Handler. Some Handlers e.g. JSONHandler produce output with key order explicitly undefined.


That’s a good point. I think it would be random without some sorting shenanigans.


You don’t need LogAttrs to pass in Attr entries, it should work fine with normal functions

The reason it doesn’t use maps is that maps are significantly slower, TFA has an entire section on performances.

However if you prefer that interface and don’t mind the performance hit, nothing precludes writing your own Logger (it’s just a façade over the Handler interface) and taking maps.


If you had read more than the introduction you’d have found a paragraph about this in the middle and multiple at the end.


You use attrs [1] instead. I personally find this much more readable, and prefer this.

  slog.Info("hello, world", slog.String("user", os.Getenv("USER")))
[1]: https://pkg.go.dev/log/slog#hdr-Attrs_and_Values


Rust's slog ( https://docs.rs/slog/ ) does:

  use slog::info;
  ...
  info!("hello, world"; "user" => std::env::var("USER"));


It can do that because Rust’s macros can have their own mini language at the top level, and can transform that into whatever data structure they want under the cover.

For better or for worse, Go doesn’t have that.


Also funny story: in Perl “,” can be spelled “=>” specifically for this sort of use cases, when you write

    my %hash = (
        Foo => “bar”,
        Baz => “qux”,
    );
the behaviour is no different than

    my %hash = (
        Foo, “bar”,
        Baz, “qux”,
    );
it’s just that a literal plist in a hash context is interpreted as a hash.

Hence “=>” being called “fat comma” in perl.

Which means you can writer

    my %h = (a => b => c => d);
or

    my %h = (a, b => c, d);
they all mean the same thing.


That all sounds questionable.


Yup! Love the Rust slog crate. Initially thought OP was gonna be about Rust slog, before I saw the domain mention Go.


Yeah, I agree. Passing in an optional `map[string]string` or something would be better, but then you get into having to either pass in `nil` every time you don't have the extra data or needing an entirely different function for with vs without the map


> Passing in an optional `map[string]string` or something would be better

It would definitely not be better from the point of view of

> We wanted slog to be fast.


A better interface/API is really what I meant. The performance characteristics are probably worth the tradeoff.


Passing in a map would require an extra allocation for the map memory for each log line. I think the performance would probably not be great?


it depends. I believe map literals are stack allocated if they aren't shared across goroutines or globals.


While the hmap struct can be stack allocated if it does not escape, I’m pretty sure the buckets still need to be heap-allocated. I do not believe hmap has a “flat structure” variant which could live entirely on the stack, though I could be wrong.


It's most definitely not. Logging is crucial for monitoring services, and making logging statements many times slower will either sink your service or push developers to avoid logging and making the service impossible to debug.

Most log metadata will be attached by libraries and middleware, so service/application devs won't even see most of it.


I think you interpreted my comment the wrong way, I think the performance tradeoffs are worth the mediocre API design. My bad for making it ambiguous


this is not uncommon. this is what I've been dealing with earlier today in Postgres:

  json_build_object ( VARIADIC "any" ) → json

  jsonb_build_object ( VARIADIC "any" ) → jsonb

  Builds a JSON object out of a variadic argument list.
  By convention, the argument list consists of alternating keys and values.
  Key arguments are coerced to text; value arguments are converted as per to_json or to_jsonb.

      json_build_object('foo', 1, 2, row(3,'bar')) → {"foo" : 1, "2" : {"f1":3,"f2":"bar"}}


I'm really used to writing them on new lines.

  json_build_object(
    'foo', 1,
    2, row(3, 'bar')
  )


Plist or named arguments doesn't really make too big of a difference, to my eyes. I do recommend Mapped Diagnostic Context style approaches, if you can do it. Passing all arguments that you think may be useful to logs gets unwieldy quickly. Looks particularly absurd when folks start adding parameters to functions for the sole purpose of letting you log them.


I'm really happy there's a name for this idea. I've been looking for something like this.


Personally I only intend to ever use LogAttrs/AddAttrs/GroupValue, for this reason. I really don't want to count evens and odds.


Indeed. Logging a map-like object seems like a pretty basic expectation. Separate keys and values as parameters seem very C-like.


Today I'm pulling this out of a context object, can I still do that?


The same pattern can be seen in Java using Map.of(...)


Structured logging is such an easy to gain, massive improvement to observability. Assuming you can pay for the log processor to make sense of it all :)

I’ve been working on a side project to bring something like the DataDog log explorer to the local development environment. The prototype I made has already been extremely helpful in debugging issues in a very complex async ball of Rails code. Does something like that sound useful to other folks? Does it already exist and I just can’t find it?


> Does something like that sound useful to other folks?

Very much so!

One piece I'd like to have is a good output format from my program. Right now I have stuff outputting logs in JSON format to stderr/local file (then picked up by the Opentelemetry OTLP collector, Datadog agent, AWS CloudWatch, whatever) and the traces/spans actually sent from my process to the collector over the network. It baffles me why the traces/spans are done in that way rather than placed in a local file (and for compressibility, ideally the same file as the logs). The local file method would make it easier to have simple local-focused tools, would lower the requirements for outputting these records (no need to have async+http client set up, just the writer thread), and would better handle the collector being in a bad mood at the moment.

That's the most important piece, but if getting that done requires inventing a new format (it seems to?!?), there are some other details I'd like to it to do well. You should be able to see all the stuff associated with each log entry's matching span, which means that spans and attributes should be recorded on open, not just on close. (Attributes can also be updated mid-span; the Rust tracing library allows this.) (OpenTelemetry notably only supports complete spans). It could be more efficient by interning the keys. some care about how rotation is handled, timestamps are handled, etc.


I hadn't even considered collecting traces/spans in this way yet, and have taken the approach of "stuff outputting logs in JSON format to stderr/local file". I usually end up writing a (temporary, structured) log message with the relevant span tags, but wouldn't it be much better to run the actual trace/span code and be able to verify it locally without the ad-hoc log message?

The prototype I built is a web application that creates websocket connections, and if those connections receive messages that are JSON, log lines are added. Columns are built dynamically as log messages arrive, and then you can pick which columns to render in the table. If you're curious here's the code, including a screenshot: https://github.com/corytheboyd-smartsheet/json-log-explorer

With websockets, it's very easy to use websocketd (http://websocketd.com), which will watch input files for new lines, and write them verbatim as websocket messages to listeners (the web app).

To make the idea real, would want to figure out how to not require the user to run websocketd out of band, but watching good ol' files is dead simple, and very easy to add to most code (add a new log sink, use existing log file, etc.)


The Grafana stack, including Loki for logs, can be started easily in a docker-compose project in your local environment. Not that Grafanas log viewer is the best in class but it’s at least something. For terminal fans there is a logcli.

If you are concerned with cost of the log processor, Loki again has your back by being very easy and lightweight to deploy. Giving you same tools in dev as in prod.


Have you checked lnav?


I’ve seen it mentioned before, but I haven’t given it a demo yet. To be honest I wasn’t sure if TUI was the right UI for something like this, as it can’t pull off all of the things a GUI can. It’s not that I have a TUI allergy either (I can’t live without lazygit).


There are certainly limits on what can be displayed and done interactively due to the low resolution. Especially, when it comes to charting data. Some visualizations are available within lnav, mostly bar charts and the like. What type of things are you trying to do that you think are not possible within a TUI?


lnav is neat but doesn't really do structured logging AFAICT, just predetermined fields for the format.


lnav has support for JSON-lines, logfmt, as well as the Bro and W3C Extended Log File formats that are XSV and self-describing. The contents are also accessible through SQLite tables. Is there some gap here that you're thinking of?


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 it in the UI and no ability to see it in the SQLite virtual table. That's why I say lnav doesn't appear to support structured logs.

edit: oh, I missed `"hide-extra": false`! That significantly improves things! Still, I don't see a way to access it from the SQLite virtual table. 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. (I guess I can sort of do this based on `module-field`? but I might want it lighter-weight/finer-grained than that.)


> 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 test[3] for this log[4], the remaining properties (even ones not mentioned in the format file) are shown underneath.

> or filter on it in the UI

Since they are part of the message as mentioned above, they can be filtered on.

> and no ability to see it in the SQLite virtual table.

The "log_raw_text" column in the table can be used to access the original log message from the file. So, you can use the JSON functions in SQLite to retrieve the value:

    ;SELECT log_raw_text ->> '$.repository' from bunyan
[1] - https://github.com/trentm/node-bunyan

[2] - https://github.com/tstack/lnav/blob/master/src/formats/bunya...

[3] - https://github.com/tstack/lnav/blob/master/test/expected/tes...

[4] - https://github.com/tstack/lnav/blob/master/test/logfile_buny...


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.


Yeah it's essential to have a viewer that deals natively with structured logs.

I'm iterating on a log pretty printer that accepts structured logs in a pipe and does things like color coding, adding terminal-recognized vscode:// hyperlinks for call stacks, smart wrapping based on the terminal width, and special formatting for panics and stuff.

NCurses is probably coming in a couple months.

Does anything like this already exist?


I'm so happy this is a stdlib feature. This is good enough for me to not need to bring in external loggers (e.g. zerolog) which is nice, and I strongly think that structured logging should be the default logging format.

Logs are data.


The rationale:

> With many structured logging packages to choose from, large programs will often end up including more than one through their dependencies. The main program might have to configure each of these logging packages so that the log output is consistent: it all goes to the same place, in the same format. By including structured logging in the standard library, we can provide a common framework that all the other structured logging packages can share.

This is IMO the right way of doing it. Provide an interface with simple defaults, usable out of the box. Those who need more can use a library that builds towards the interface.

So when evaluating any library, you can ask "How well does this integrate with interfaces in the standard library?". Discovering that some functionality is just a "Fooer" that pieces well together with existing stuff is calming. Not only do you already know how to "Foo", you also get a hidden stability benefit: There's an implied API surface contract here.

This is in stark contrast to the "builds on top of" approach, where you end up with competing, idiosyncratic interfaces. This is often necessary, but there is always an implied risk in terms of maintenance and compatibility.


Something like this would be a welcome addition to Ruby/Rails where you have to pull in dependencies that patch the multiple independent loggers in the stack, some of which break messages onto multiple lines, not to mention the common case of inconsistent tagged and structural logging in your application code.

It’s a lot of effort when all you want is to log everything to STDOUT, in JSON, but you have to choose one of half a dozen logging libraries that all behave extremely differently.


Rust seems to do find with a de-facto logging library, and the Java ecosystem seems to have converged on a common API, but with a lot of effort I think.


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.


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.


Now all we need is the 1,000,000 other components in the multiple ecosystems to log in the same format and I won't have a perpetual headache.

Good job Go though for being opinionated but rational.


There are some attempts with Elastic Common Schema [1] or OpenTelemetry [2].

[1] https://www.elastic.co/guide/en/ecs-logging/overview/current... [2] https://opentelemetry.io/docs/specs/otel/logs/data-model/


With this another most requested feature is covered by Go. This leaves error handling, enum type which are often asked by users but are not actively being worked on for now.


The lack of Error Handling in Go is a feature, not a bug. See here: https://go.dev/doc/faq#exceptions. I think I'd be disappointed if Try/Catch ever made their way into the language.


Error handling != exceptions.

Step one would bee sum types, so only valid value space can be represented (return value or error, but not both or neither).


Good point, a poor assumption on my part


What would be the big gain from this, over the existing approach using multiple return values?


Great, so Go has support for native stacktraces so bubbled errors don't get shadowed?

Just because Go made opinionated design decisions around their error handling a decade ago when developing the language doesn't mean that there's not practical room for improvement as the language is widely in production and shortcomings in its error handling have been found.

The number of hacks I've seen over the years to try and solve the "wait, where did this error originate" problem in Go are legion, with little standardization.

And no, using Errorf with '%w' to wrap error messages along the stack isn't exactly an elegant solution.

Even if they want to keep the core error behavior as it is for compatibility, providing a core library way of wrapping with stacktraces would be a very useful next step, particularly given the most popular package doing that previously is now unmaintained.


> providing a core library way of wrapping with stacktraces would be a very useful next step

What eventually became the standard library error wrapping proposal evolved from the work done on the Upspin project. It did include stacktraces, and believed like you that it would be useful to have them. But analysis of the data showed that nobody ever really used them in practice and, for that reason, was removed from the final proposal.

> particularly given the most popular package doing that previously is now unmaintained.

Lacking wide appeal doesn't mean there isn't a niche need, of course. However, with the standard library accepting a standard for error wrapping, which this package you speak of has been updated to be compatible with, what further maintenance would be needed, exactly? It would be more concerning if it wasn't considered finished by now. It seems the solution for niche needs is right there.


In the last few months I've realized what I desperately need: a way to wrap an error with a call stack at the point where it enters our code base. This would probably save me on average 20-30 minutes a week.

I see this all the time:

   main.go:141 error: could not transmogrify the thing: a144cd21c48
And then I literally grep the code base to find the error message. That works ~50% of the time, but the other 50%, I see this:

   main.go:141 error: not found
And then I have to spend 5-10 minutes spelunking to try to find where that error might have originated from.

But this would be amazing:

   main.go:141 error: not found callstack=...


This is such an infuriating problem. I'm convinced I'm using Go wrong, because I simply can't understand how this doesn't make it a toy language. Why the $expletive am I wasting 20-30 and more minutes per week of my life looking for the source of an error!?

Have you seen https://github.com/tomarrell/wrapcheck? It's a linter than does a fairly good job of warning when an error originates from an external package but hasn't been wrapped in your codebase to make it unique or stacktraced. It comes with https://github.com/golangci/golangci-lint and can even be made part of your in-editor LSP diagnostics.

But still, it's not perfect. And so I remain convinced that I'm misunderstanding something fundamental about the language because not being able to consistently find the source of an error is such an egregious failing for a programming language.


I find it interesting how, as soon as the word error shows up, people seemingly forget how to program.

Ignore the word error for a moment. Think about how you program in the general case, for a hypothetical type T. What is it that you do to to your T values to ensure that you don't have the same problem?

Now do that same thing when T is of the type error. There is nothing special about errors.


Its flaws or merits aside, when you have no other useful context to add to the error, that's precisely what Errorf is for.

  func bar() error {
    err := baz.Transmogrify()
    return fmt.Errorf("transmogrify: %w", err)
  }

  func foo() error {
    err := bar()
    return fmt.Errorf("bar: %w", err)
  }

  func main() {
    err := foo()
    fmt.Printf("foo: %v", err)
    // foo: bar: transmogrify: not found
  }
There's your callstack, without the cost of carrying around the actual callstack.


Nitpicking here, but I prefer a different convention.

  func bar() error {
    err := baz.Transmogrify()
    return fmt.Errorf("bar: %w", err)
  }

  func foo() error {
    err := bar()
    return fmt.Errorf("foo: %w", err)
  }

  func main() {
    err := foo()
    fmt.Printf(err)
    // foo: bar: transmogrify: not found
  }
Also, I tend to skip quite a lot of layers. The (only?) advantage of manual wrapping over stack traces is that a human can leave just 3 wrappings which are deemed sufficient for another human, while stack trace would contain 100 lines of crap.


    func bar() error {
        err := baz.Transmogrify()
        return fmt.Errorf("bar: %w", err)
    }
This is broken. If baz.Transmogrify() returns a nil error, bar will return a non-nil error.

Also, annotations like this, which repeat the name of the function, are backwards. The caller knows the function they called, they can include that information if they choose. Annotations should only include information which callers don't have access to, in this case that would be "transmogrify".

The correct version of this code would be something like the following.

    func main() {
        fmt.Printf("err=%v\n", foo())
    }
    
    func foo() error {
        if err := bar(); err != nil {
            return fmt.Errorf("bar: %w", err)
        }
        return nil
    }
    
    func bar() error {
        if err := baz.Transmogrify(); err != nil {
            return fmt.Errorf("transmogrify: %w", err)
        }
        return nil
    }


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). They should be rare enough that any cost below about 1ms and 10k is negligible.


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++ or Java, but in Go, it is absolutely not the case.

Errors are essential to, and actually the primary driver of, control flow!

Any method or function which is not guaranteed to succeed by the language specification should, generally, return an error. Code which calls such a method or function must always receive and evaluate the returned error.

Happy paths always involve the evaluation and processing of errors received from called methods/functions! Errors are normal, not exceptional.

(Understanding errors as normal rather than exceptional is one of the major things that distinguish junior vs. senior engineers.)


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.


> 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.

When code encounters an error, it can either deal with that error programmatically, or return that error to its caller. I don't think you can make any generalized assertions about whether one or the other of these cases is more common, and I'm confident that you can't assert that one or the other of these cases is better or worse than the other, or that one of them represents a problem worth fixing.

Errors potentially occur at every fallible expression. Where an error is handled is orthogonal, and generally unknowable, to the given bit of code that receives that error.

I agree with you that "the performance of error handling" should never be a first-order concern when writing code.

I don't agree with you that capturing a call stack is fast enough to ignore. Calling runtime.Callers (https://pkg.go.dev/runtime#Callers) takes time proportional to the size of the pc []uintptr slice, and can easily get to O(ms) or beyond. It's fine if a given bit of code opts in to this cost, but it's not something that you should do by default; the threshold for performance critical code is O(ns), not O(us).


> worrying too much about the performance of error handling in these relatively rare cases is absolutely premature optimization.

It's not something to worry about, but it's also a premature optimization to include when there is no need. The Go team considered adding stack traces as described before 1.13, postulating that it would be useful, but measurement determined that they were rarely used in the real world.

If your measurements (you are measuring, right?) that pertain to your specific situation tells a different story, they aren't something to be afraid of, but would be silly to make the default for everyone. The standard tools don't need to serve every single use case ever imagined.

The reality is, unless you forget how to program every time you see the word error (which seems to be a thing), in the real world you are never going to just `return err` up, up, up the stack anyway. Even ignoring traceability concerns, that is going to introduce horrible coupling. You wouldn't do that for any arbitrary type T, so why would you for type error? There is nothing special about errors.


> Any method or function which is not guaranteed to succeed by the language specification should, generally, return an error.

Most Go programmers are too scared to panic and abort when invariants are violated. I think most codebases contain at least 2x as much error handling as is really necessary.


Nope.

Panic isn't an ersatz error reporting mechanism, it's a tool of absolute last resort. Any function or method that can fail should return an error, and should signal failure via that error. Callers that invoke any fallible function or method should always receive, inspect, and respond to the returned error.


Who said panic should report errors? I specifically said abort…


Panic doesn't reliably abort the program.

And, in any case, arbitrary code doesn't have the right to abort the program in the first place! Only func main is allowed to terminate the process. Errors in any other context should always be reported to the caller via normal control flow, i.e. return.


This is exactly the broken view I mean.


If you allow arbitrary code to terminate the process, then the control flow of the program is effectively non-deterministic, and impossible to model, or even really understand. Software written in this way is fundamentally unreliable.


Reasoning about control flow is much easier when you have so much less control flow because you just let it crash.


What an insane way to think about programming.

A service should never crash in response to a runtime error, or any kind of business logic conditional! Crashes are not normal, they signal critical problems and/or programmer errors. A service that crashes in production is a priority-0 bug that needs to be addressed and fixed immediately.

More specifically, if you can't trust that calling a function will always return execution to the call site, then there is no way to build a practical and deterministic model of control flow, and it becomes impossible to manage resource lifecycles.

Consider a network protocol that expects an explicit disconnect/teardown procedure. If your process creates a connection with this sort of protocol, you need to at least try to tear the connection down before terminating the process outright. You can't just yolo kill the client and expect the server to deal with it. And this is just one example among infinitely many possible examples: basically every API that understands a concept of a resource has similar expectations: filesystems, consensus protocols, etc. etc.


I'll pray for you.

(Consensus protocols are your most bizarre example because they're one of the definitional things that needs to keep working no matter how hard or fast a non-quorum of members dies.)


Likewise.


Erlang/OTP expects its processes might crash in response to invalid user input. There, crashing is basically normal and relatively common. In contrast, supervisors like systemd and Docker expect their processes to be generally resilient to bad user input, and to crash only in response to much more critical issues. There, crashing is basically abnormal and uncommon. And assumptions are baked into the entire execution stack of each orchestrator.

Crashing is an error handling strategy only if you know a priori that your code will be running in an execution environment that treats crashes as normal. Such environments are exceptions, not the rule.


> that only works if enough places in the code add context.

It would be a bit odd to not add context, wouldn't it? Same goes for any value. This is not exclusive to errors. If you consider a function which returns T, the T value could equally be hard to trace back if you find you need to determine its call site and someone blindly returned it up the stack. There is nothing special about errors.

While ideally you are returning more context than Errorf allows, indeed, it is a good last resort. If your codebase is littered with blind returns, the good news is that it shouldn't be too hard to create a static analyzer which finds blind returns of the error type and injects the Errorf pattern.


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 errors", and only for frames that happen in code you (hand waving) "care about". Maybe your programs just have far too complex internal error handling?


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.


An error is an error. The immediate caller is always responsible for detecting and handling errors in whatever way is appropriate for their calling context.


Not exactly -- you should only fmt.Errorf wrap errors which are non-nil.

See my sibling comment: https://news.ycombinator.com/item?id=37234455


Agreed. In fact I wrote a (very) small library to help deal with it.

https://github.com/kitd/chock


>And no, using Errorf with '%w' to wrap error messages along the stack isn't exactly an elegant solution.

I don't think anyone has ever claimed otherwise. But I do think its a pretty good solution. Whats elegance worth, anyways?


Yeah I have to agree that the Go-style error handling does actually lead to better code. At least when I write it. It makes me think through how I am going to handle error states rather than chucking it in try/except in Python and hoping nothing breaks lol.


Rust-style error handling works better though - similar to Go, but with the addition of enums such that the precise types of errors which may be encountered can be easily documented in the type system.


Agreed, I’d love if they would take inspiration from Rust and bring that to Go.


Yes - if Go had sum types (and they were idiomatically used in the standard library), it would take it from a pretty good platform to a first class one.

The library ecosystem is already excellent, and the tooling is good, lack of sum types is the single wart that makes me regret it every time I pick Go up for a project.


Try/catch/finally is in the language, its just called panic/defer/recover, where panic works like throw, every function works like try, defer works like a combination of a nonselective catch that rethrows by default and finally, and recover disables the rethrows-by-default behavior, while also being the only way to interrogate the panic to see if you should do that.


I am not demanding either of these things. Just making general comment based on observing folks.


An iterator type is being actively worked on now. After that presumably the missing data types in the standard library will be filled out (set, deque, a usable heap, whatever other algorithms). After that, who knows. Maybe native bigints?

I don’t really see the enum thing happened. Is lack of enums a real problem? Theoretically, it would be convenient, but I can’t say that I see bugs caused by its lack.


Having "type MyType int" and defining a bunch of constants isn't a great replacement for enums. Yeah, it "works," but it still lets the developer forget to check for a possible variant, or you could have an underlying int that doesn't correspond to a valid variant.

The addition of enums would move all these runtime checks to compile time.


As a workaround, a list in a DB combined with a foreign key constraint. Ugly, yes.


Enums with associated values are a very basic data modeling primitive. Writing code without them is like doing arithmetic with only the multiplication sign, not the plus sign.


It's nice to have this in the standard library, but it doesn't solve any existing pain points around structured log metadata and contexts. We use zap [0] and store a zap logger on the request context which allows different parts of the request pipeline to log with things like tenantId, traceId, and correlationId automatically appended. But getting a logger off the context is annoying, leads to inconsistent logging practices, and creates a logger dependency throughout most of our Go code.

[0] https://github.com/uber-go/zap


log/slog package essentially delegates writing log messages to some "handler" interface. The key method is:

    Handle(context.Context, Record) error
This method has access to the context, which means you can get the logging handler to extract values from the context. Instead of storing the logger on the context, you can extract the traceId, etc values from the context and log those.

It's a little bit involved to write a whole logger from scratch, but you can 'wrap' the existing logger handlers and include values from the context relatively easily.

There are examples in this project (which aims to help solve your usecase): https://github.com/zknill/slogmw


Here's an example of extracting context values in a custom slog handler:

https://github.com/indexsupply/x/blob/main/wslog/slog_test.g...


This is addressed in the article.

> As the call to LogAttrs shows, you can pass a context.Context to some log functions so a handler can extract context information like trace IDs.

I’m not a fan of slog’s syntax, but the convenience of having it in the stdlib trumps that, for me.


I must admit: I'm not a huge fan of structured logging, beyond simple use cases like tagging messages by the thread that produced them. If you want something machine-readable, use a dedicated metrics system, analytics database, or document store. If you want something human-readable, structured logging will only make things worse.


I feel what is missing here is message templates [1] - the logging API should permit the key-value pairs to be substituted into a template which results in a human-readable message, while preserving the KV data separately. Take a hash of the template and add it as a KV pair so that messages of the same type can be easily filtered.

[1] https://messagetemplates.org


Loggers are just façade objects on Handlers, which is an interface.

It’s really designed to be a minimum necessary package to allow interop (via handlers) and a baseline of standalone usability (via loggers). The stdlib only provides a text and a json handler, not even a no-op handler which I think is sorely neededor a multi handler which I think would make a lot of sense.

But nothing precludes you publishing a messagetemplates handler, or whatever else you may want.


Structured logging is not meant for humans to read. It's meant for machines to read and represent in a human readable format. Additionally, these logs can _later_ be streamed into a metrics system, analytics database, or a document store. Sort of in a plug & play fashion.


The new structured logging library is a great addition, its nice to have structured logging in the standard lib.

It's easy to get started with log/slog and one of the built in handlers, but as soon as you want to change something the library design pushes you towards implementing an entire handler.

For example, if I want the built in JSON format, but with a different formatting of the Time field, that's not easy to do. It's not obvious how to change the built in handler.

I wrote slogmw[1] to solve this problem. It's a set of middleware and examples that make it easy to make small changes to the built in handlers without having to write a whole new handler from scratch.

[1] https://github.com/zknill/slogmw


> but as soon as you want to change something the library design pushes you towards implementing an entire handler.

Yes, it annoyed me to no end. But OTOH I think it may be wise of them to see what the ecosystem finds and provide more convenience later. After all, it's std we're talking about, and this takes time to get right.

I'm personally missing:

- A goddamn default no-op/nil logger, that can be declared before initialized in e.g. structs.

- Customization to TextHandler for changing format easily, and omit keys (AIUI ReplaceAttr cannot omit stuff like `time="..."` on each line), which is critical since CLI screen real estate is incredibly sparse.

- (Controversial) but I would like opinionated logger initialization guidance for package authors, so that you get consistency across the ecosystem. Doesn't have to be exactly one way, but say.. two ways? E.g. a package-global and a struct-initialized version? Right now, people are even confusingly wondering if they should accept slog.Handler or *slog.Logger.


Nice middleware package.

I have to admit, the `log.InfoContext(ctx,...` style of redundancy that permeates the standard lib at this point is really gross, especially given that the most common use case for go is going to have contexts everywhere.


The -Context suffix is only needed when something existed before Context was created. New stuff should be just `foo.Bar(ctx, ...)`


Isn't slog, like, completely new as of this release?


Yes. Then it having separate -Context variants means they really wanted to provide both, and not just the context one.


Go’s decision to not support function overloading leads to a tonne of really ugly APIs. Obviously every decision in language design is a tradeoff, but IMO they made the wrong call here.


I'm not sure how I feel about this. What are the actual consequences of these apis being "ugly"? Like, why does that matter?


To me, at least, it is like listening to a person who constantly says "uh..." while talking. Occasionally, sure fine. But it's so pervasive in commonly used APIs that it becomes annoying.

Let's be clear: this is just a peeve of mine.


I wish there was a better approach for the problem of avoiding function calls when the log level at runtime is higher than the call site.

So,

    slog.Info("failed to frob", "thing", GetThing(1))
Still calls GetThing(1) when the log level is greater than Info. The only solution right now for this is to test the log level before making the logging call. It would be amazing if language designers could make the arguments late bound instead or used aspect-oriented programming approaches to protect each logging call site.


There is. See slog.LogValuer

https://pkg.go.dev/golang.org/x/exp/slog#LogValuer


There are other languages of course where the logging avoids this, even in libraries written by the same company that writes Go. In C++, the Abseil logging library (f.k.a. glog) will not evaluate a condition for a disabled log level.

  LOG(INFO) << WowExpensiveFunction();
This is safe when the log level is set to WARN or higher. For the same reasons, LOG_EVERY_N and LOG_FIRST_N in the same library are pretty cheap.


https://pkg.go.dev/log/slog#hdr-Performance_considerations


I guess it's nice to have a standard, but I wish the Golang developers stopped introducing stuff like "args ...any" all over the place in the standard library.

It's not the level of type-safety that I expect from a strongly typed language.


Benthos just adopted it: https://github.com/benthosdev/benthos/commit/ee0000450413ad3...


I might have misunderstood, but shouldn't the adapter be operating on a `slog.Handler`?


slog’s top-level functions use the default logger, so using that made the most sense for now. There are some custom labels being injected (see the `WithFields()` method) but that's about it.


Oof. We just converted all of our logging to zap[0] to get structured JSON logging for downstream parsing. Wonder how the perf stacks up.

[0]: https://github.com/uber-go/zap


It looks like they've included slog in their performance benchmarks, which show zap as considerably more performant (though I don't really understand the benchmark).


That test puts a lot of stuff through `slog.Any`, while the zap version uses more strongly-typed variants, so I'm not sure it's a fair comparison.

What it comes down to is that zap special cases things like slice-of-int, slice-of-string, slice-of-timestamp, slog doesn't, and the benchmark includes all those special cases. I question whether your typical log statement includes slices. A more fair benchmark would be just scalar types, and zap & slog optimizations there look pretty similar.

https://github.com/uber-go/zap/blob/fd37f1f613a87773fc30f719...

https://github.com/uber-go/zap/blob/fd37f1f613a87773fc30f719...


http://bench.zerolog.io/ Is a useful set of benchmarks


I'm really glad they've introduced this, I just wish it also had the traditional formatting methods, eg Infof, Debugf, Errorf, etc, for backwards compatibility.

I've got a few packages that accept a basic logger interface, eg:

  type debugLogger interface {
      Debugf(format string, args ...any)
  }

  type MyThing struct {
    logger debugLogger
  }

  func New(logger debugLogger) *MyThing {
    return &MyThing{logger}
  }
I'd love to switch to slog but I'll have to v2 these packages now.


I would defend slog's decision there. Infof/Debugf/Errorf are like fine especially when I'm making a little CLI tool for myself, but my main consumption of logs at work is other peoples' logs via a cloud log aggregator, and so when you give other devs who are not me Sprintf they start to do things like "[%s] default/%v - %v" or so, which makes sense to them but doesn't give me great strings to search for when I'm trying to figure out "what were all of the situations in which this strange thing happened".

It's like when you're trying to internationalize, you want to emit as constant of a string as reasonably practical, so that it can be straightforwardly matched and substituted into a different language. Except in this case that different language is regexes being used to change the thing into a SQL statement to fix the mess (or whatever).

So much easier to say "stop trying to Sprintf your logs, just add the values as key-value pairs at the end of the function call."


I'm slowly retraining myself to write structured logs instead of Infof, etc. The extra effort really is negligible. There's a nice benefit too: my log printer takes structured logs and adds color coding, which isn't possible with Infof.


Slog is an amazing name


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.


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.


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.


Looking for advice: logging for servers/services tends to be different than logging for CLI-based applications. How do folks differentiate them or use slog for them in a generic way? Or does it make sense to have separate logging packages for CLI vs services? CLI tends to be more verbose and procedural vs servers/service based logging which is more errors only unless debug.


Assuming you are logging from some package that's shared over a CLI app and some webservice app; log/slog expects you to setup the slog logger with a specific handler. This handler controls _how_ events are written out, the format of them etc.

If you want to use slog, I can imagine setting up the logger with a handler specific for the CLI output in the CLI tool, and a json or text structured handler in the webservice app.

The quesiton is, do you actually want structured logging in the CLI app? Yes you probably want to print something out, but is it _structured_ in the sense that slog expects? Or is it just some output.

If it's not really structured, then you probably want some other interface/library that better represents the logging you want to do. Slog will push you towards structured key-value pairs, and you might find yourself fighting against this in the CLI app.


It seems like I could write an output handler for the CLI app that is more terminal-appropriate. I'd like to abstract logging for functions shared by both (especially debug logs). Today I have combined the functions of logging and tracing/sampling into one package/function call as they are equivalent in my eyes.


Log everything as Json!

We need to start making Json viewer were we look into log files without tooling the default.

It's so much easier to use Json automatically and ship them to systems out of the box.

Linux logging should do that too. Not just container in k8s


This supports quoting values. There isn't much JSON would add except overhead and making it a bit simpler to read and write them. I really don't think it's worth the overhead.


Q: what do people use for structured logging in Java?


Any Java logger has structured logging.

The prevailing solution is SLF4J, which is a facade that can be implemented by any number of backends, e.g. Logback.

There is logging in the stdlib (java.util.logging), but it's the less common choice, for whatever reason.


Logback has structured logging. I think log4j has it as well


Walking past an eatery with outdoor seating, I overheard one diner say the phrase "process raw logs" and I thought, "wow, I guess that is one of those tricky problems that basically everyone ends up dealing with".

And then I heard "... with a chainsaw. It's a chainsaw mill" and realized I may have misunderstood the context.


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.




Consider applying for YC's Spring batch! Applications are open till Feb 11.

Guidelines | FAQ | Lists | API | Security | Legal | Apply to YC | Contact

Search: