Let's talk Tagged Logging vs Structured Logging in Ruby or Rails

What is Tagged Logging?

Should you be using it? What libraries support it? Is it the same as structured logging?

Let's start with an example. Here's ActiveSupport::TaggedLogging in action.

class Permissions
  def get(user)
    logger.tagged("Auth API") do
      uri = URI("https://auth.example.com/permissions/?user=#{user}")

      logger.info { "Fetching #{uri}" }
      permissions = Permissions.parse(Net::HTTP.get(uri))
      logger.info { "Got permissions #{permissions.to_s}" }
    end
  end
end

# Log Output
#[Auth API] Fetching https://auth.example.com/permissions/?user=bob
#[Auth API] Got permissions admin, writer, reader

An example from Justin Weiss shows us how we might do this for users:

logger.tagged(current_user_id ? "user-#{current_user_id}" : "user-anonymous") do
  logger.debug "Finding people..."
  @people = Person.all
  logger.debug "Found #{@people.length} people!"
end

# Log Output
#[user-123] Finding people...
#[user-123]   Person Load (0.3ms)  SELECT "people".* FROM "people"
#[user-123] Found 0 people!

What's Good About Tagged Logging

Good Readability / Grep-ability

It's nice that the log lines for multiple parts of a request have the same tag. That's going to be helpful with ctrl-f locally or grep in production.

It's DRY (Don't Repeat Yourself)

We put the user.id in one place, and it is now in all the log output. We could even put that in an around_action and have it in all logging for our request.

What's Not as Good

Poor Machine Readability

logger.tagged "user-#{user.id}" do
  logger.tagged team.name do
    logger.info "hello"
  end
end

# The plain text version of the log reads nicely
#INFO [user-1] [The Best Team] hello

# But the JSON Log isn't ideal
#{severity: INFO, message: "hello", tags: ["user-123", "The Best Team"]}

Almost every log aggregator will support JSON logging and user-123 won't be as easy to search as {user: 123}. With the structured format you're going to be able to display and search the column user for 123. Additionally, the team name is just floating there without a key. This post Structured logging in Rails lays out the problem well. Does your logging aggregator want:

[2018-05-13T17:51:08.772542] [INFO] [127.0.0.1] [2892] Customer registration error - SSN already exists.

Or

{
  "timestamp": "2018-05-13T17:51:08.772542",
  "source": "127.0.0.1",
  "msg": "SSN already exists.",
  "level": "INFO",
  "user_id": 2892,
  "error_type": "customer_registration"
}

The answer is almost assuredly the latter.

The gem json_tagged_logger gets in the fight here. It takes the same tagging behavior and puts them in a tags key.

Rails.logger.tagged("TAG") do
    Rails.logger.tagged("NESTED").info("nested tagged log message")
end

# Log Output
{
    "level": "INFO",
    "request_id": "914f6104-538d-4ddc-beef-37bfe06ca1c7",
    "host": "127.0.0.1",
    "my_param": "param value",
    "user_id": "99",
    "my_custom_header": "some header value",
    "tags": [
        "TAG",
        "NESTED"
    ],
    "msg": "nested tagged log message"
}

If you really like tagging, this is a good move.

🤔 But are these things you're tagging really "tags" or should they be new keypairs? In a practical example, the code is more likely something like this:

Rails.logger.tagged("BillingJob") do
  Rails.logger.tagged("User #{user.id}").info("nested tagged log message")
end

and wouldn't that be better JSON as:

{
  "class": "BillingJob",
  "user": 1234
}

vs

{ "tags": ["BillingJob", "User 1234"] }

If you're nodding along, at this point, you're probably wondering whether maybe we should just write:

logger.info "nested message", user: 1234, class: "BillingJob"

If so, congratulations, you've just invented structured logging!

What's Structured Logging?

As you can see, structured logging is pretty straightforward. It lets us do something like this:

log.info "hello", user: "1", team: "The best team"

# Text Log
# INFO hello user=1, team=The Best Team
# JSON Log
# {severity: INFO, message: "hello", user: 1, team: "The Best Team"}

Hey now, that really is better.

So, what libraries do this? Quite a few, actually. Here's what they look like:

logcraft

logger = Logcraft.logger 'Application'

logger.info 'Log message'
# => {"timestamp":"2022-...","level":"INFO","logger":"Application","pid":80422,"message":"Log message"}

logger.info message: 'User logged in', user_id: 42
# => {"timestamp":"2022-...","level":"INFO","logger":"Application","pid":80422,"message":"User logged in","user_id":42}

I don't really dig having to say message: but it's not the end of the world. Logcraft has around 5k downloads on rubygems as of today.

ougai

Here's an excerpt from the ougai docs:

logger.info('Information!')
#{"name":"main","hostname":"mint","pid":14607,"level":30,"time":"2016-10-16T22:26:48.835+09:00","v":0,"msg":"Information!"}

logger.info({
  msg: 'Request', method: 'GET', path: '/login',
  format: 'html', controller: 'LoginController',
  action: 'new', status: 200
})
#{"name":"main","hostname":"mint","pid":9044,"level":30,"time":"2016-10-28T17:58:53.668+09:00","v":0,"msg":"Request","method":"GET","path":"/login","format":"html","controller":"LoginController","action":"new","status":200}

Again with the msg: but it's not the end of the world. Ougai has around 8.4M downloads on rubygems as of today.

semantic_logger

logger.debug('log this', foo: 'foo', bar: 'bar')
# Text
#DEBUG 2023-09-06 10:31:18 -0400: {foo: foo,bar: bar} log this
# JSON
{"named_tags":{"foo":"foo","bar":"bar"},"name":"Post","message":"log this"}

Semantic Logger has about 12M downloads, and there is also a rails_semantic_logger gem with Rails-specific integrations.

What About Lograge?

Lograge is sort of a structured logger. It does output structured logs for your Rails requests, but it doesn't give you a way to structure your own logs. It's 101M downloads and a proven tool, but I'm not including it here because we're talking about structured logging and tagged logging in general.

So, is Tagged Logger worse than Structured Logging?

Well, yes. Mostly. Honestly I didn't have an opinion before I really dug in and researched this, but in my view structured logging can give us the same benefits as tagged logging, but in a cleaner, more machine-readable way that fits better with modern log aggregators.

🤔 However there is one thing I found valuable with tagged logging and that is nested contexts. It’s a convenient way to propagate context instead of adding it to each log entry. Does using structured logging mean we have to give that up?

No! Fortunately, we can do this in SemanticLogger as well. It looks like this:

logger.tagged {user: 1} do
  logger.info "nested"
end

# Log Output
# nested user=1

Could it be better?

My last gripe would be that I'm repeating this context. Isn't this the same context I'm using for my feature flags library, datadog, and sentry?

Sentry

Sentry.configure_scope do |scope|
  scope.set_context(
    'user',
    {
      name: 'Bob Beemer',
      id: 1234,
    }
  )
end

Datadog

Datadog.configure do |c|
  c.tags = { 'user_name' => 'Bob Beemer',
             'user_id' => '1234' }
end

LaunchDarkly

context = LaunchDarkly::LDContext.create({
    key: "user-key-123abc",
    kind: "user",
    name: "Bob Beemer",
    id: 1234
})

Prefab

$prefab.with_context({
      user: {
        key: current_user.tracking_id,
        id: current_user.id,
        name: current_user.name,
      }
    }, &block)

Why do I need to repeat this again for logging? Can't I just do it once?

The Ideal

I ended up writing this post because we're working on a dynamic log library, and I wanted to make sure we had all our bases covered with respect to structured logging and tagged logging.

Semantic logger is pretty darn good, but if we're going to really DRY things up I could reuse the context I use for feature flags. Here's what that might look like.

My proposed ideal code

# application_controller.rb
class ApplicationController < ActionController::Base

  around_action do |_, block|
    # Put our context together in one place for the whole request
    $prefab.with_context({
      user: {
        key: current_user.tracking_id,
        id: current_user.id,
        name: current_user.name,
      }
    }, &block)
  end
end

# application.rb
module MyApplication
  class Application < Rails::Application
    # tell the logger to add the values of these contexts to log messages
    logger.add_context_keys "user.id", "user.name"

    # or add extra logging context in a block
    logger.with_context {runtime: {value: 42}} do
      logger.info "hello"

       # Feature flag value evaluation uses existing context for user.id and runtime.value
       $prefab.get("my-feature-flag")
    end
  end
end

# Log Output
# INFO hello user.id=1234, user.name=Bob Beemer, runtime_value=42

This is the approach we're planning on, but I'd love to hear your thoughts.

Summary

1. Tagged logging is nice.
   1. Tagged logging makes decent-looking console output.
   2. Tagged logging requires adding things manually.
   3. Tagged logging is a bit like structured logging, but in a way that log aggregators can't use.
2. Structured logging is better.
3. But ideally structured logging can also add structure in a block.
4. Semantic Logger is a great library that does this, and it's the same approach we're taking at Prefab.