Hanami Logging | Alchemists

Hanami Logging

Hanami logging is one of the worst aspects of working with a Hanami application. This was hinted at when discussing Hanami Containers earlier so we’re going to learn why Hanami’s default logger is a problem and how you can fix so you can have sensible logging that works for you rather than against you.

Table of Contents

Configuration
Default
Custom
Conclusion

Configuration

As of Hanami 3.x.x you can configure the formatter used for your logger across the entire application via the following configuration:

# config/app.rb
class App < Hanami::App
  # Formatters
  config.logger.formatter = :json

  # Streams
  config.logger.stream = root.join "log", "other.log"

  # Levels
  environment(:production) { config.logger.level = :warn }

  # Filters
  config.logger.filters.append "token"
end

⚠️ All of the above is ignored when using a custom logger. The workaround is to configure all of this via your logger provider.

The only configuration options that do work is the ability to set your own custom logger or configure the database logging level:

# config/app.rb
class App < Hanami::App
  # Custom Logger
  config.logger = Cogger.new

  # Database
  config.db.log_level = :info
end

When it comes to setting your own logger, you’re better off using your own log provider (more on this below).

Default

When you build a Hanami application, you’ll end up with Dry Logger as the default logger. This allows you to stay focused on implementing the specifics of your application but you’ll quickly outgrow what the default logger can provide for you when you need to ensure all of your logs are consistently formatted. Specifically, you’ll run into the following problems:

Dry Logger — along with many Dry gems — isn’t actively maintained.
The Dry Logger documentation has, for the longest time, been extremely sparse and hard to understand the entire feature set. That said, this has been improved as of Version 1.2.0.
Hanami does not make replacing Dry Logger with a better logger — like Cogger which will be discussed in a moment — because you need to monkey patch the Object API.

In other words, swapping out the the default logger with a custom logger is not trivial but, fear not, we’re going dive into all this so you can understand the problem and the corresponding solution.

Custom

Now that you understand the premise of the default logger and why it’s a problem, we can discuss the solution which means supplying your own custom logger. We’ll use Cogger to replace Dry Logger. Cogger was inspired by and born out of frustration of dealing with Dry Logger so is a great logger to add to your Hanami application for solving this problem. That said, if you want to use a different logger entirely, you should be able to take everything you learn here and apply it to using your custom logger with only a few tweaks.

Quick Start

If you’d like to skip learning how to add a custom logger and immediately setup Hanami with Cogger as your primary logger then use Hanamismith to build your Hanami project because everything discussed below is fully automated when using Hanamismith.

Provider Implementation

You’ll need to create a custom application provider that allows your logger to be the main application logger. Using Cogger, here’s what that looks like:

# app/providers/logger.rb

# auto_register: false

module Demo
  module Providers
    # The logger provider.
    class Logger < Hanami::Provider::Source
      RESOLVER = proc { Object.const_get "Cogger" }

      def initialize(environment: Hanami.env, resolver: RESOLVER, **)
        @environment = environment
        @resolver = resolver
        @id = Hanami.app.namespace.to_s.downcase.to_sym
        super(**)
      end

      def prepare = require "cogger"

      def start
        add_aliases
        add_filters
        register :logger, build_instance
      end

      private

      attr_reader :environment, :resolver, :id

      def add_aliases
        cogger.add_formatter(
          :rack,
          Cogger::Formatters::Emoji,
          "%<emoji:dynamic>s <dynamic>[%<id>s] [%<level>s] [%<at>s] %<verb>s " \
          "%<status>s %<elapsed>s %<ip>s %<path>s %<length>s </dynamic>"
        )

        cogger.add_formatter :sql,
                             Cogger::Formatters::Emoji,
                             "%<emoji:dynamic>s <dynamic>[%<id>s] [%<level>s] [%<at>s] %<db>s " \
                             "%<elapsed>s%<elapsed_unit>s %<query>s</dynamic>"
      end

      def add_filters
        cogger.add_filters :csrf, :HTTP_ID, :mac_address, :password, :password_confirmation
      end

      def build_instance
        io = "log/#{environment}.log"

        case environment
          when :test
            cogger.new(id:, io: StringIO.new, formatter: :json, level: :debug).add_stream io:
          when :development then cogger.new(id:).add_stream(io:, formatter: :json)
          else cogger.new id:, formatter: :json
        end
      end

      def cogger
        @cogger ||= resolver.call
      end
    end
  end
end

The above ensures Cogger is properly prepared, started, and testable. The only oddity is the RESOLVER which ensures Cogger is lazy loaded for preparation and testing purposes because, due to the nature of provider lifecycles, you must wait for the provider to be properly prepared. Otherwise, you’d end up with a NameError.

💡 For a deeper diver, see the Inheritance section of Hanami Containers and the Cogger documentation for configuration details.

Finally, and assuming you are using RSpec for your test suite, it’s highly recommended you add this logger to your to your application dependencies shared context so you always have quick access to your application logger for testing purposes. Example:

# spec/support/shared_contexts/application_dependencies.rb

RSpec.shared_context "with application dependencies" do
  let(:app) { Hanami.app }
  let(:logger) { app[:logger] }
end

Here’s what log output looks like in the development environment console (minus the green color):

🟢 [demo] Provisioning device 123..."

Provider Registration

With our provider implementation in hand, we only need to register the provider so Hanami uses our custom logger provider as follows:

# config/providers/logger.rb

require_relative "../../app/providers/logger"

Hanami.app.register_provider :logger, source: Demo::Providers::Logger

If you’re thinking: "Wait, you said Hanami provides a default logger provider?". You’re correct, Hanami does, but checks if a custom provider (as shown above) has been defined first. If so, then Hanami skips loading it’s default logger provider.

Oddly, this is the only default provider that Hanami grants this exception to as the inflector, rack logger, and DB logger providers do not support this behavior. This means we’ll have to work a little harder to work around this problem so we’ll tackle those issues next.

3.x.x

With Hanami 3.x.x, things have become slightly better where you can replace the default logger with your own logger. Unfortunately, you still need to monkey patch the application to make things work (more on this in a moment). Worse, this version introduces nested tags which, sadly, is an antipattern that stems from Rails that can yield in the following code:

logger.tagged :deeply do
  logger.tagged :nested do
    logger.tagged :blocks do
      logger.fatal "This is gross."
    end
  end
end

The following details how to replace the default logger with your own logger.

Structured Logging Patch

Hanami automatically wraps any custom logger you configure via a universal logger which adds overhead and contorts your logger to adhere to what Hanami considers structured logging (even if your logger is a structured logger). The problem, especially with Rack and SQL logging, is that you need to swap formatters based on tag information. Definitely not ideal so the following converts the incoming message and payload into the correct data structure. You may still need to adjust your own logger depending on your needs.

# config/initializers/universal_logger_patch.rb

# auto_register: false

# Patches Hanami's universal logger to work with Cogger.
module UniversalLoggerPatch
  DEFAULTS = {
    verb: nil,
    status: nil,
    elapsed: nil,
    elapsed_unit: nil,
    ip: nil,
    path: nil,
    length: nil,
    db: nil,
    query: nil
  }.freeze

  def _log_structured method, message, payload
    tags = _current_tags
    block_content = yield if block_given?

    logger.formatter = case tags
                         in [:rack] then tags.delete :rack
                         in [:sql] then tags.delete :sql
                         else Hanami.env == :development ? :emoji : :json
                       end

    unless block_content.is_a? Hash
      message = block_content
      block_content = {}
    end

    combined = {**DEFAULTS, **payload, **block_content}

    logger.public_send method, message, tags:, **combined
  end
end

Hanami::UniversalLogger.prepend UniversalLoggerPatch

The DEFAULTS constant handles situations in which keys are missing as Hanami will, sometimes, drop keys needed for Rack or SQL formatting. The keys are filtered out by your log formatter when not used (this is also why they are splatted first so they can be overwritten).

Hanami uses special :rack and :sql tags which you need to pattern match on in order to use the right formatter for your logger. Otherwise, you need to revert to your default formatter based on environment. Definitely annoying and no irony is lost on how the "universal" logger isn’t so universal.

Hanami also has a bad habit of prefixing internal methods with underscores when proper public, protected, and private scope would be better while cleaning up the Object API further. This is why you see several underscored methods for structured logging and tagging.

Application Configuration

With our universal logger patch in hand, we only need to require it at the top of our application configuration as follows:

# config/app.rb

require_relative "initializers/universal_logger_patch"

That’s it. You’ll now be using a single logger instance for all messaging within your application. Even better you can inject this custom logger within any application object with minimal effort.

2.x.x

Custom logging within Hanami 2.x.x is more involved but the following will walk you through how to make this work.

Rack Adapter

In addition to having a custom logger provider, you’ll need to build an adapter for logging HTTP requests which also allows you to replace Hanami’s default Rack logger. This is important especially when you want to use the same logger for all logging. Here’s what this looks like for Cogger:

# app/aspects/logging/rack_adapter.rb

module Demo
  module Aspects
    module Logging
      # Adapts Cogger Rack middleware for provider registration.
      module RackAdapter
        module_function

        def with logger
          @logger ||= logger
          self
        end

        def new application
          @application = Cogger::Rack::Logger.new application, {logger: @logger}
        end

        def call(environment) = @application.call environment
      end
    end
  end
end

RSpec Specification

# spec/app/aspects/logging/rack_adapter_spec.rb

require "hanami_helper"

RSpec.describe Demo::Aspects::Logging::RackAdapter do
  subject(:adapter) { described_class }

  include_context "with application dependencies"

  let(:application) { proc { [200, {"Content-Type" => "text/plain"}, "test"] } }

  describe ".with" do
    it "answers itself" do
      expect(adapter.with(nil)).to eq(adapter)
    end
  end

  describe ".new" do
    it "answers Cogger middleware" do
      expect(adapter.with(logger).new(application)).to be_a(Cogger::Rack::Logger)
    end
  end

  describe ".call" do
    let(:middleware) { adapter.with(logger).new application }

    it "answers application" do
      expect(middleware.call({})).to eq([200, {"Content-Type" => "text/plain"}, "test"])
    end

    it "logs request" do
      middleware.call({})
      expect(logger.reread).to match(/level.+INFO.+status.+200/)
    end
  end
end

Where you place this adapter is up to you but the aspects namespace can be useful for specialized objects. You might have also noticed this implementation mimics a generic Rack application by using a module instead of a class. This is done to reduce creating new objects that need to be garbage collected. Instead, this module wraps the Cogger Rack Logger within a Rack-like interface that is also compatible for registration as a Hanami provider because Hanami providers expect to be sent the .new message after being registered which is why the .with method is used to aid with initialization.

If this doesn’t click yet, hang tight, as this’ll make more sense when we look at the monkey patches below.

Rack Patch

Now that we have our adapter in hand, we can patch the Hanami’s Rack Logger. Unfortunately, we have to use a monkey patch to pull this off:

# config/initializers/rack_logger_patch.rb

# auto_register: false

require "dry/system"

# Patches Hanami's default providers.
module RackLoggerPatch
  def prepare_app_providers
    require "hanami/providers/inflector"

    logger = Class.new Hanami::Provider::Source do
      def start
        slice.start :logger
        register :monitor, Demo::Aspects::Logging::RackAdapter.with(slice[:logger])
      end
    end

    register_provider :inflector, source: Hanami::Providers::Inflector
    register_provider :rack, source: logger, namespace: true
    register_provider :db_logging, source: Hanami::Providers::DBLogging
  end
end

Hanami::App::ClassMethods.prepend RackLoggerPatch

Yes, monkey patches are the worst, but a necessary evil in this case since Hanami has no support in this respect. As you can see, the above patches Hanami’s prepare_app_providers method which can be found here. A couple notes worth pointing out:

The conditional logic for auto-detecting our custom application logger is completely deleted in this patch since Hanami will load our Cogger logger like any other provider. Same goes for all of the other conditional logic (feel free to tweak as necessary, though).
The main change is registering our Rack adapter in lieu of Hanami’s default monitor provider. This ensures our adapter delegates to Cogger for logging all HTTP requests.

Here’s what log output looks like in the development environment console (minus the green color):

🟢 [demo] [verb=GET] [ip=::1] [path=/screens] [params=] [length=] [status=200] [duration=114] [unit=ms]

SQL Patch

Sadly, we have to apply another monkey patch to ensure all SQL activity also uses our custom logger. Here’s the monkey patch:

# config/initializers/sql_logger_patch.rb

require "dry-monitor"
require "dry/monitor/sql/logger"

# Patches Hanami's default SQL logger.
module SQLLoggerPatch
  def log_query time:, name:, query:
    Hanami.app[:logger].info { {message: query, tags: [{db: name, duration: time}]} }
  end
end

Dry::Monitor::SQL::Logger.prepend SQLLoggerPatch

Dry Monitor, also no longer maintained, is used for logging all database activity. As with Rack logging, we need to ensure our custom logger is used instead. In this case, we override the log_query method in order to use our logger. This method takes three keywords where query becomes our log message while name and time are added as tags.

Here’s what log output looks like in the development environment console (minus the green color):

🟢 [demo] [db=postgres] [duration=1] SELECT "screen"."id", "screen"."label", "screen"."created_at", "screen"."updated_at" FROM "screen" WHERE ("name" = 'plugin-a8739f') ORDER BY "screen"."label"

Application Configuration

With our Rack and SQL logger patches in hand, we only need to require them at the top of our application configuration as follows:

# config/app.rb

require_relative "initializers/rack_logger_patch"
require_relative "initializers/sql_logger_patch"

That’s it, thankfully. At this point, you’ll be using a single logger instance for all messaging within your application. Even better you can inject this custom logger within any application object with minimal effort.

Conclusion

You’ve learned that Dry Logger is Hanami’s default logger and how you can replace it with your own logger, like Cogger, to provide your own custom implementation by doing the following:

Implementing and registering a custom provider.
Patching database logging.
Patching your application configuration so all of this is wired up properly.

Is this ideal? Definitely not and — because monkey patches are applied — you must be diligent with Hanami upgrades since implementation updates could break your patches. This is always the downside of monkey patching.

On the upside, you now understand how logging is currently wired up within Hanami so you can adjust accordingly especially if you want all of your logging to have multiple streams that are consistently formatted. Even better, Cogger is actively maintained with the goal to keep improving so Hanami logging gets better including logging for any application, in general.