Skip to main content

Change log levels without restarting.

Get exactly the logging you need, only when you need it, with Prefab dynamic logging.

Learn More

Before You Lograge

· 16 min read
Jeff Dwyer

Lograge is one of the all-time great Rails gems and is one of those 3-4 gems like devise, timecop or rails_admin that I typically install on every new Rails project.

So, lograge is great, but are better alternatives in 2024? I think so. We'll examine two options: an excellent free choice called Rails Semantic Logger and one I've built for the Prefab platform.

What Problem Do These Gems Solve?​

First, let's take a quick look at what problem we're trying to solve. Here's the logging you get from Rails & Lograge out of the box at info level.

Started GET "/posts" for 127.0.0.1 at 2023-09-06 10:08:20 -0400
Processing by PostsController#index as HTML
  Rendered posts/index.html.erb within layouts/application (Duration: 0.8ms | Allocations: 813)
  Rendered layout layouts/application.html.erb (Duration: 19.3ms | Allocations: 34468)
Completed 200 OK in 30ms (Views: 21.1ms | ActiveRecord: 0.5ms | Allocations: 45960)

There are a number of annoyances with the Rails logging defaults:

  1. 5 lines of logging for a single request.
  2. "Completed 200 OK" doesn't tell us which request it was that completed.
  3. No timestamps on the log lines after the first one.

In contrast, lograge is clear, concise & grep-able.

(You can, of course, output in JSON as well; I'm not showing that because it's not as pleasant to look at.)

So this is the problem that lograge has been solving all these years, and it's a great fix.

More Than Just a Single Line​

But, a single-line request summary is not the only interesting aspect of logging. What about debug logging? What about tagged and struct logging? Can any of these libraries help us fix our problems faster?

To exercise the other aspects of logging, here's the sample code we will run. It logs at all four levels and uses tagged and structlog to show how to add context to your logs.

class PostsController < ApplicationController
  def index
    @posts = Post.all
    if can_use_struct_log?
      logger.debug "🍏🍏🍏detailed information", posts: @posts.size #struct logging
      logger.info "🍋🍋🍋informational logging", posts: @posts.size
    else
      logger.debug "🍏🍏🍏detailed information #{@posts.size}" # old-school
      logger.info "🍋🍋🍋informational logging #{@posts.size}"
    end
    @posts.first.process_post
  end
end

class Post < ApplicationRecord
  def process_post
    logger.tagged "process post" do
      logger.tagged "post-#{id}" do #nested tagged logging
        logger.debug "🍏🍏🍏details of the post"
        logger.info "🍋🍋🍋 info about the post"
      end
    end
  end
end

Comparing At INFO Level​

Let's compare the output at the info level for each of the gems. It is a bit funky to see it on the web and not a wide terminal, but we'll do our best. Each of the gems does provide a way to provide a custom formatter to tweak things like date, time, etc, but this is what you get out of the box. Also, you'll probably want to use JSON output in production. All the gems support that; see the JSON output comparison in the appendix, but it's pretty straightforward.

Started GET "/posts" for 127.0.0.1 at 2023-09-06 10:08:20 -0400
Processing by PostsController#index as HTML
🍋🍋🍋informational logging 1
[process post] [post-2] 🍋🍋🍋 info about the post
  Rendered posts/index.html.erb within layouts/application (Duration: 0.8ms | Allocations: 813)
  Rendered layout layouts/application.html.erb (Duration: 19.3ms | Allocations: 34468)
Completed 200 OK in 30ms (Views: 21.1ms | ActiveRecord: 0.5ms | Allocations: 45960)

We see that Rails, by default, has no support for structured logging, though it does support tagged logging. We're outputting logging 1 instead of logging posts=1 and in JSON we won't have a nice {"posts": 1} to index.

It's also not clear what class or file informational logging 1 is coming from. This is annoying because it makes us need to type more detail into the error message just to help us locate / grep.

We do see helpful logging about what templates were rendered and how long they took.

Comparing At DEBUG Level​

For completeness, let's compare the output at the debug level for each of the gems.

Started GET "/posts" for 127.0.0.1 at 2023-09-06 10:01:55 -0400
Processing by PostsController#index as HTML
  Post Count (0.0ms)  SELECT COUNT(*) FROM "posts"
  ↳ app/controllers/posts_controller.rb:8:in `index'
🍏🍏🍏detailed information 1
  CACHE Post Count (0.0ms)  SELECT COUNT(*) FROM "posts"
  ↳ app/controllers/posts_controller.rb:9:in `index'
🍋🍋🍋informational logging 1
  CACHE Post Count (0.0ms)  SELECT COUNT(*) FROM "posts"
  ↳ app/controllers/posts_controller.rb:10:in `index'
  CACHE Post Count (0.0ms)  SELECT COUNT(*) FROM "posts"
  ↳ app/controllers/posts_controller.rb:11:in `index'
  Post Exists? (0.1ms)  SELECT 1 AS one FROM "posts" LIMIT ?  [["LIMIT", 1]]
  ↳ app/controllers/posts_controller.rb:12:in `index'
  Post Load (0.0ms)  SELECT "posts".* FROM "posts" ORDER BY "posts"."id" ASC LIMIT ?  [["LIMIT", 1]]
  ↳ app/controllers/posts_controller.rb:13:in `index'
[process post] [post-2] 🍏🍏🍏details of the post
[process post] [post-2] 🍋🍋🍋 info about the post
  Rendering layout layouts/application.html.erb
  Rendering posts/index.html.erb within layouts/application
  Post Load (0.1ms)  SELECT "posts".* FROM "posts"
  ↳ app/views/posts/index.html.erb:4
  Rendered posts/index.html.erb within layouts/application (Duration: 0.6ms | Allocations: 736)
  Rendered layout layouts/application.html.erb (Duration: 7.9ms | Allocations: 14135)
Completed 200 OK in 15ms (Views: 8.4ms | ActiveRecord: 0.6ms | Allocations: 20962)

Rails debug for local dev gets pretty chatty with a lot more detail. In addition to the templates and layouts we got at the debug level, we can now see the executed SQL.

We also now get class and line number output for some of the logging, though not all of it. Our custom logging does not include any information about where it came from.

It's also a lot of output, and it's not particularly easy to grep for the important bits. As your app grows, this logging can start to get a bit overwhelming.

It may go without saying, but turning this on in production would be a very bad idea.

JSON Formatting​

The JSON formatting of each of these libraries is pretty much what you would expect, but for completeness:

{
  "method":"GET",
  "path":"/posts",
  "format":"html",
  "controller":"PostsController",
  "action":"index",
  "status":200,
  "allocations":45961,
  "duration":37.91,
  "view":29.63,
  "db":0.42
}

Summary​

The state of Rails logging gems in 2024 is good, and you've got great options. If you've been defaulting to just standard Rails logging or lograge for years, it may be time to take a look at what else is out there. Being able to quickly trace each log line back to its source is valuable, and structured logging feels much better than string interpolation and can be very powerful in conjunction with your log aggregation tool.

Rails Default Logger​

Good:

  • Rails gives us a lot of great information out of the box.

Bad:

  • 5 lines of logging for a single request is too much in deployed environments.
  • "Completed 200 OK" doesn't tell us what request completed.
  • No timestamps on the log lines after the first one.
  • Difficult to fine-tune debug logging. Very "all-or-nothing".

Lograge​

Lograge has been the default choice for years. If you don't use much logging and just want the basic request log, it's a good choice.

For more information, check out the GitHub for lograge

Good

  • Better 1-line Req Log
  • Supports tagged logging

Bad

  • No support for struct log
  • Unclear display of level by default formatter
  • Difficult to fine-tune debug logging
  • Doesn’t format your other logs, like Rails.logger.info "foo"
  • No file names/origin of logging

rails_semantic_logger​

Rails Semantic Logger is an impressive piece of software that has been around for a long time. It's got a lot of features and is very configurable. It has everything you could want in a logger, save the ability to update it dynamically.

For more information, check out the docs for rails_semantic_logger

Good:

  • Adds Class Name
  • Optionally add file and line number
  • Better 1-line Req Log
  • Very configurable
  • Structlog & Tagged Logging
  • logger.measure_trace("Low level trace information such as data sent over a socket") do ... end is cool
  • logger.error("Oops external call failed", exception) is cool

Bad:

  • Can't change log levels on the fly

prefab-cloud-ruby​

Prefab is a SaaS that provides dynamic configuration and uses that to support Feature Flag and Dynamic Log Levels. Prefab provides the same log cleanup and core features as SemanticRails, with the additional benefit of being able to quickly debug production by temporarily enabling debug logging for a specific user or job.

For more information, check out: Dynamic Log Levels

Good

  • Consistent display of class and method
  • Change log level instantly
  • Turn debugging logging on for just a single user or team
  • Better 1-line Req Log
  • Structlog & Tagged Logging

Bad

  • Not as comprehensive as rails_semantic_logger
  • Fewer integrations than rails_semantic_logger or lograge
  • Part of a paid product

Thanks for checking this out. If you have any questions, please reach out.

Like what you read? Change log levels on the fly with Prefab. Start now for free.
Learn More