Dynamic Ruby Log Levels With Semantic Logger & Prefab

info

tl;dr As of 1.6.0 prefab-cloud-ruby's dynamic logging now works by being an injectable filter for semantic_logger rather than a full logging library, ie SemanticLogger.add_appender(filter: Prefab.log_filter). This is awesome.

After we released our dynamic logging library for Ruby, I stepped back and tried to do an overview of the pros and cons of the major logging libraries in the Ruby ecosystem in Before You Lograge.

One redditor commented:

Kudos to the author for not putting their company's product at #1 when it is clearly a very solid #2. I had forgotten how good semantic logger is.

It's nice to feel people appreciated me being fair. But also... kinda stinks to be #2.

The fact of the matter was that they were right. Semantic Logger is awesome. It's been around for 12 years, it's had 62 contributors. It's a solid piece of code that can deal with whatever weirdness Rails throws at it and has had time to build custom appenders for everything from: Sentry to syslog, DataDog to Splunk.

At Prefab we really don't want to be in the business of building logging libraries. We want you to be able to turn on debug logging for a single customer in an instant, with our dynamic logging, but we don't really want to have an opinion on your aggregator, your formatting or how logging integrates with Rails.

In other languages, like Java or Python the standard logging libraries have a clear place to inject a custom filter and this was perfect for us. In Ruby however, the standard logging libraries didn't have any concept of a pluggable filter, so in our initial version we ended up rolling our own.

This worked quite well, but we were always going to be behind SemanticLogger when it came to a question of:

Supporting lots of different logging sinks/aggregators

# ElasticSearch example
SemanticLogger.add_appender(
  appender:    :elasticsearch,
  url:         "http://localhost:9200",
  index:       "my-index",
  data_stream: true
)
# LogStash example
log_stash = LogStashLogger.new(type: :tcp, host: "localhost", port: 5229)
SemanticLogger.add_appender(logger: log_stash)

Structured Logging

logger.debug("Calling stripe", item: "si_124", customer: "cust_456")
#2024-04-01 D MyController -- Calling stripe -- { :item => "si_123", :customeer => "cust_456" }

Duration Metrics

logger.measure_info("Called sleep", metric: "supplier/add_user") do
  sleep 3
end
#2024-04-01 I (3.005s) MyController -- Called sleep

Tagged Logging

SemanticLogger.tagged(user: "Jack", zip_code: 12345) do
  # All log entries in this block will include the above named tags
  logger.debug("Hello World")
end
# 2024-04-01 D {user: Jack, zip_code: 12345} MyController -- Hello World

Standardizing the very odd output of Rails logging internals

See rails_semantic_logger for details, but we get really nice structured breakdowns of Rails' internal logging.

2024-04-01 16:09:38.404316 W [99437:puma srv tp 001] {path: application_controller.prefab_controller} (3.005s) PrefabController -- Called supplier
2024-04-01 16:09:38.404822 W [99437:puma srv tp 001] {path: application_controller.prefab_controller} PrefabController -- Calling Supplier -- { :request => "update", :user => "Jack" }
2024-04-01 16:09:38.405205 W [99437:puma srv tp 001] {user: Jack, zip_code: 12345, path: application_controller.prefab_controller} PrefabController -- Hello World
2024-04-01 16:09:38.409065 D [99437:puma srv tp 001] {path: action_view} ActionView -- Rendering -- { :template => "prefab/index.html.haml" }
2024-04-01 16:09:38.416935 D [99437:puma srv tp 001] {path: action_view} (7.391ms) ActionView -- Rendered -- { :template => "prefab/index.html.haml", :within => "layouts/application", :allocations => 13541 }
2024-04-01 16:09:38.515765 D [99437:puma srv tp 001] {path: action_view} (1.488ms) ActionView -- Rendered -- { :partial => "layouts/_amplitude.html.haml", :allocations => 2874 }
2024-04-01 16:09:38.519110 D [99437:puma srv tp 001] {path: active_record} (1.332ms) ActiveRecord -- Brand Load -- { :sql => "SELECT \"brands\".* FROM \"brands\" ORDER BY slug", :allocations => 8, :cached => nil }
2024-04-01 16:09:38.530351 D [99437:puma srv tp 001] {path: action_view} (1.356ms) ActionView -- Rendered -- { :partial => "layouts/_footer.html.haml", :allocations => 3857 }
2024-04-01 16:09:38.530932 I [99437:puma srv tp 001] {path: application_controller.prefab_controller} (3.153s) PrefabController -- Completed #index -- { :controller => "PrefabController", :action => "index", :format => "HTML", :method => "GET", :path => "/prefab", :status => 200, :view_runtime => 118.27, :db_runtime => 5.8, :allocations => 171461, :status_message => "OK" }
2024-04-01 16:09:38.596435 D [99438:puma srv tp 002] {path: active_record} (0.668ms) ActiveRecord -- { :sql => "SELECT \"schema_migrations\".\"version\" FROM \"schema_migrations\" ORDER BY \"schema_migrations\".\"version\" ASC", :allocations => 7, :cached => nil }

If You Can't Beat Them, Join Them!

All of this is to say that as of 1.6.0 we're very happy that prefab-cloud-ruby works by leveraging semantic_logger and implementing dynamic log levels where they were meant to be, as a filter.

To get dynamic logging level for all of your code, you just need to:

# config/initializers/logging.rb
SemanticLogger.sync!                                  # Use synchronsous processing for targeting logging with current context
SemanticLogger.default_level = :trace                 # Prefab will take over the filtering
SemanticLogger.add_appender(
  io: $stdout,                                        # Use whatever appender you like
  filter: Prefab.log_filter,                          # Insert our Prefab filter
)

PR (#173) was a delightful +304/-1046, which reflects all of the work that we no longer had to do by being able to just rely on our new logging friend.