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

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

[rafaelfranca]

It is mostly for backward compatibility. Existing applications have a lot of calls to the logger passing strings. We indeed could just change the backend and formatter to transform those strings in well structured data, but this doesn't allow us to for example just ignore all the existing calls and only care about new ones.

But, I want to point out that it is been a while that Rails supports structure logging. Rails itself, most of the time, only generate structured events (ActiveSupport::Instrumentation), that are later converted to strings (ActiveSupport::LogSubscriber). One could just build a different instrumentation subscriber that just get the hashes Rails already generate and send them to where they like.

But, application developers interact with Rails.logger every time they want to log, we need to solution that would teach application developers to stop putting strings to loggers, and adding a new method to make this distinction seems like a good path.

But, we aren't married to any API just yet.

Those same ActiveSupport::Instrumentation events can be used for OpenTelemetry, or any other format that people want to use, so it isn't like Rails doesn't provide the tooling for it.

[palkan]

application developers interact with Rails.logger every time they want to log, we need to solution that would teach application developers to stop putting strings to loggers, and adding a new method to make this distinction seems like a good path.

Maybe, not a new method, but a new logger: Rails.slogger? Yeah, naming is mhe but I refer here to how Go introduced slog package compatible (at least, in terms of API function names) with the older log package. In their case, in simple situations it's enough to change the import statement, no need to change every invocation.

And, of course, we can add a framework option config.use_structured_logger = true making Rails.logger work as Rails.slogger (and that would be a part of config.load_defaults 8.0).

And how it's assumed to specify the level in case of logger.struct(**) API? I guess, via the level keyword (though I don't think it's a good idea due to the lack of consistency). Compare:

Rails.logger.struct level: :debug, message: "putz debugga", context: "api"
# vs.
Rails.slogger.debug "putz debugga", context: "api"

(Note that in the example above I also assume using the first positional argument as the message field value — maybe there is no need in changing the interface at all?)

[modosc]

And, of course, we can add a framework option config.use_structured_logger = true making Rails.logger work as Rails.slogger (and that would be a part of config.load_defaults 8.0).

passing attributes to Rails.logger.info "message", extra: 'attributes'

i think this approach is the simplest because combined with the above config option you can coerce this to do the right thing eg:

# unstructured, similar to console.log in js 
> Rails.logger.info "message", extra: 'attributes'
message {:extra=>"attributes"}

# structured 
> Rails.logger.info "message", extra: 'attributes'
{"message":"message","extra":"attributes","status":"info"}

also, i've implemented various solutions for this at multiple employers, and in my experience folks want unstructured logging in development (because humans are parsing it) but structured logging in production environments (because machines are parsing it). having this be a simple config switch that doesn't require rewriting all existing logging calls seems like a big win.

[jonyeezs]

Also to suggest to look into Message Template: https://messagetemplates.org/

[nhorton]

One suggestion I would really like here is something like the following:

items.each do |item|
  with_context(current_item: item.name) do
    logger.info('I did a thing')
    Rails.error.report(BadThingException.new)
  end
end

and have that result in current_item being part of the structured payload of the logging message and be part of the error report in the next line. Obviously that is a simple example - the reason this matters in general is for when the error or log message is happening 10 steps down the call stack.

[KJTsanaktsidis]

One suggestion I would really like here is something like the following:

+1 to this, especially since there’s an analogue to this with text tags in the block form or Rails.logger.tagged

[nhorton]

I have been diving on some issues around this, and think the situation may be worse than I thought (happy if others can correct me that I am wrong).

It looks like much of Rails itself is both logging and using the error reporting interface (Rails.error) for issues that happen. This means that anywhere that someone is using Rails.error.report (or even worse - Rails.error.handle that is handling errors in a block) they need to do an extra log capture at the same time, or they get a confusing jumble of some exceptions (the ones from Rails itself) going to the logs and others (the ones they added themselves) not doing so.

Staring at this more as a user right now (because we are having issues around it) I am coming around a little more to the comments earlier that Telemetry might be a better solution for all this.

If Rails.error functionality were available under something more like telemetry and one could do the following types of actions and Rails itself just moved away from traditional logging, it would likely be way simpler. The Broadcast logger already really looks a lot like the error reporting system anyways - showing the close analogy.

1. telemetry.error - same as Rails.error.report, but also putting out a structured log messaged. It could also make the exception optional and have support for message text instead.
2. telemetry.info / telemetry.debug / telemetry.warn - Same as above, but with a different severity level. Logging would happen in all cases modulo the log level, and other subscribers could register at the level they wanted to (Sentry, Honeybadger, etc). Note that this is a gap right now - we have to use Sentry.capture_message when we don't have an actual exception.
3. All the above could be done with block-form too, and could result in starting and finished log messages, along with breadcrumbs in error reporting tools

The other really big point I would make here is that this also would leave a ton of flexibility in literal loggers. i.e. we could have a default dev logger that does something like AwesomePrint's output for showing the kwargs and message in a nice way, then have JSON and other log formatters, and all they would need to do is be subscribers to the telemetry events with different outputs. My deeper point there being that currently, loggers often times play with the logging interface itself because they are being called directly via Rails.logger lookups, but if it was through the telemetry system, it would be a far-simpler implementation.

[nhorton]

@byroot - do you have any opinions on this topic? Since you wrote the error reporter (IIRC) and since I know Shopify has some robust logging? My team spends an excessive amount of time on issues around error tracking and logging, so I am really invested in this roadmap item. :)

[byroot]

I got lots of opinions on lots of things, unfortunately structured logging isn't one of them. And honestly, if I was asked to define what structured logging is, I don't think I could.

[nhorton]

I hear you there. I honestly think this comes down to a couple items:

1. Get all the logger methods inside rails to accept kwargs (BroadcastLogger not doing so is a big issue because it means no logger-agnostic code can pass key/value pairs)
2. Reconcile the ErrorReporter with logger.error since it is still very standard practice to monkeypatch logger.error to capture exceptions since not everything gets reported
3. Get ActiveSupport::LogSubscriber and its subclasses to use the above
4. Reconcile the block tagging mechanism used for tagged logging with the above.

Those are, I think, the must-wins to have this work. The stuff that I think is amorphous is what the default log formatters should do, but that feels like it matters very little since that would actually be pluggable.

[soulcutter]

Get all the logger methods inside rails to accept kwargs (BroadcastLogger not doing so is a big issue because it means no logger-agnostic code can pass key/value pairs)

I think this addressed BroadcastLogger #52868