Add structured logging next to developer logging

[dhh]

When you want to aggregate the data from your Rails application into a data analysis platform, it's a real pain trying to parse the developer-focused log lines that Rails spits out by default. In addition to these log lines, which are great in development and for manual inspection, we should add structured json logging on a per-request basis that can easily be digested by analytics.

Both Shopify and 37signals have been using in-house structured logging for a long time, so extracting something from those battle-tested scenarios is the path we intend to go.

cc @Jeremy @rafaelfranca

[KJTsanaktsidis]

Huge +1 to having something out-of-the-box for this; we've managed to grow several different implementations of structured logging at Zendesk and I would very much like there to be a clear gold standard here to switch to!

One thing I would like to see addressed in a built-in structured logging solution is what to do about multiple independent processes writing to stdout.

It's very common, in my experience, for apps in container environments to be expected to write their logs to stdout, where it gets collected by the container engine and then forwarded to a centralised logging solution. It's also very common to run Rails apps in a multiprocess app server like Unicorn or Puma's cluster mode, so there might be several independent Rails processes running in the one container. The problem is, by default, all of those processes will share the single stdout stream, leading to issues where structured log messages might be interleaved and thus their structure broken.

I've been sketching out a way to solve this for us at Zendesk (https://github.com/zendesk/multiproc_log_device). Essentially, it runs a parent process above Unicorn which exposes a unix socket, and reopens stdout in each process to connect to that socket. Then, the parent process can merge the logs together in a structure aware way.

I would be very interested in hearing how other Rails users have dealt with this issue, and very very interested in trying to hammer out a way this problem can be addressed in a built-in Rails structured logging solution.

[sandstrom]

we should add structured json logging on a per-request basis

Good initiative!

Maybe logfmt (https://brandur.org/logfmt) could be supported as an output alternative to JSON?

Assuming it's all strings and only one level deep (that's how JSON log lines are usually structured), logfmt is 1:1 with JSON log lines, so it's only a matter of output.

---

Also, maybe this is an area where an RFC light might be useful.

Just write down a rough plan on the interface and output structure, and ask a few large Rails users (Shopify, Zendesk, Github, etc) to provide feedback.

[stympy]

Assuming it's all strings and only one level deep (that's how JSON log lines are usually structured), logfmt is 1:1 with JSON log lines, so it's only a matter of output.

It is not uncommon for JSON log lines to have multiple nested levels when using observability tools, so if logfmt is supported, I suggest making JSON the primary focus and gracefully degrading to logfmt.

Semantic Logger has a nice approach of allowing the user to choose among a list of formatters for each appender that receives the logs. In fact, if you take a look at their documentation for appenders (a concept that I think would be fantastic to have as part of this work), you'll find an example payload that shows a nested payload structure. :grin:

[KJTsanaktsidis]

Is there any indication what the rough shape of the structured logging interfaces/APIs might look like? Or, what's the best way to provide input on this?

We’ve cooked up a bunch of home-grown interfaces for this in Zendesk:

• making Rails.logger.tagged(attr: 'value') { ... } accept a hash of structured attributes
• passing attributes to Rails.logger.info "message", extra: 'attributes'
• entirely separate methods like Rails.logger.append_attributes({attribute_for: 'remaining lifetime of this request'})

(I think the semantic logger gem mentioned above supports the first two methods, but we're not actually using that implementation).

I’m presently trying to consolidate all of these various interfaces in our code. I’d ideally want to “just do what rails does”, but of course rails doesn’t do anything related to structured logging… yet. If I had a rough idea what direction Rails is planning to go in, it would greatly help me out with deciding which interfaces to keep and which to refactor 🙏

[rafaelfranca]

API would be something like this:

logger.struct my_message: "Something happened"

But this isn't set and I'm not planning to work in the first half of the year.

[dmathieu]

While structured logging in rails would be great, have you considered introducing tracing instead? That would allow finer grained information, and exporting the data into stdout/a file in a structured logging kind of way is always feasible.

OpenTelemetry is quickly becoming an industry standard, and while there are already a good coverage of instrumentation for the rails components in otel, having the project go that way would be pretty awesome imho.

[solnic]

API would be something like this:

logger.struct my_message: "Something happened"

What's the reasoning for having a special method for structured logging? Typically, logging libraries provide different backends/formatters and you always use the same interface regardless of what you're logging. There are well established patterns out there so I'd recommend just sticking to them (see already mentioned SemanticLogger or dry-logger that took some inspiration from it).

I'd also say that un-structured logging should only be enabled in development and test envs by default and structured logging should be enabled in test and prod envs by default. Why in test? Because structured logging is important in prod and you wanna have it executed in tests too to make sure that things do work and don't crash. In a perfect world you'd also have a nice way of testing structured logs like a test logger that captures logs and makes it easy to make assertions about the logs.

Furthermore, just like @dmathieu mentioned, OpenTelemetry is becoming a standard and Rails absolutely misses out right now, but I'd say it's a separate topic (even though it's related to logging).