dry-logger crashes fatally

wuarmin · June 12, 2024, 1:43pm

Hey ,

I keep seeing this fatal error in my logs and can’t figure out what the problem is:

[my_app] [FATAL] [2024-06-12 15:20:20 +0200] Logging crashed
  (0.000555s) SELECT "order_states"."id", "order_states"."name" FROM "order_states" WHERE ("order_states"."id" IN ('ERR')) ORDER BY "order_states"."id" {}
  key<verb> not found (KeyError)

I’m using rom-rb for persistence, analog to decafsucks/config/providers/persistence.rb at main · decafsucks/decafsucks · GitHub.

Here’s the full backtrace:

key<verb> not found (KeyError)
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/formatters/template.rb:73:in `%'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/formatters/template.rb:73:in `%'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/formatters/string.rb:77:in `format'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/formatters/structured.rb:55:in `call'
  /usr/local/lib/ruby/3.2.0/logger.rb:743:in `format_message'
  /usr/local/lib/ruby/3.2.0/logger.rb:666:in `add'
  /usr/local/lib/ruby/3.2.0/logger.rb:695:in `info'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:228:in `block in log'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:293:in `each'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:293:in `block in each_backend'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:292:in `synchronize'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:292:in `each_backend'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:227:in `log'
  /usr/local/bundle/gems/dry-logger-1.0.4/lib/dry/logger/dispatcher.rb:132:in `info'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/logging.rb:88:in `public_send'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/logging.rb:88:in `block in log_each'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/logging.rb:88:in `each'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/logging.rb:88:in `log_each'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/logging.rb:82:in `log_duration'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/logging.rb:48:in `log_connection_yield'
  /usr/local/bundle/gems/rom-sql-3.6.3/lib/rom/plugins/relation/sql/instrumentation.rb:73:in `block (2 levels) in define_log_connection_yield'
  /usr/local/bundle/gems/dry-monitor-1.0.1/lib/dry/monitor/clock.rb:15:in `measure'
  /usr/local/bundle/gems/dry-monitor-1.0.1/lib/dry/monitor/notifications.rb:29:in `instrument'
  /usr/local/bundle/gems/rom-sql-3.6.3/lib/rom/plugins/relation/sql/instrumentation.rb:72:in `block in define_log_connection_yield'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:171:in `execute_query'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:159:in `block in execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:136:in `check_disconnect_errors'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:159:in `execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:532:in `_execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:348:in `block (2 levels) in execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:555:in `check_database_errors'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:348:in `block in execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/database/connecting.rb:293:in `synchronize'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:348:in `execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/dataset/actions.rb:1189:in `execute'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/adapters/postgres.rb:651:in `fetch_rows'
  /usr/local/bundle/gems/sequel-5.81.0/lib/sequel/dataset/actions.rb:164:in `each'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation.rb:223:in `each'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation.rb:361:in `each'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation.rb:361:in `to_a'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation.rb:361:in `to_a'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation/loaded.rb:36:in `initialize'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation.rb:352:in `new'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation.rb:352:in `call'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation/combined.rb:66:in `call'
  /usr/local/bundle/gems/rom-core-5.3.2/lib/rom/relation/materializable.rb:15:in `to_a'
  /home/user/app/slices/vouchers/repositories/positions_repo.rb:30:in `all_filtered'
  /home/user/app/slices/vouchers/graphql/types/query_type.rb:94:in `inactive_order_positions'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:683:in `public_send'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:683:in `block (2 levels) in resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:828:in `block in with_extensions'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:864:in `block (2 levels) in run_extensions_before_resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:867:in `run_extensions_before_resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:864:in `block in run_extensions_before_resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field_extension.rb:134:in `resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:851:in `run_extensions_before_resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:823:in `with_extensions'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:654:in `block in resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:766:in `minimal_after_lazy'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/query.rb:372:in `after_lazy'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/field.rb:652:in `resolve'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:374:in `block (2 levels) in evaluate_selection_with_resolved_keyword_args'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/tracing/trace.rb:52:in `execute_field'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:373:in `block in evaluate_selection_with_resolved_keyword_args'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:706:in `call_method_on_directives'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:362:in `evaluate_selection_with_resolved_keyword_args'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:340:in `block in evaluate_selection_with_args'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:825:in `after_lazy'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:288:in `evaluate_selection_with_args'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:282:in `block in evaluate_selection'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/arguments_cache.rb:51:in `block in dataload_for'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/member/has_arguments.rb:300:in `block (3 levels) in coerce_arguments'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/member/has_arguments.rb:281:in `block (2 levels) in coerce_arguments'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/member/has_arguments.rb:280:in `each'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/member/has_arguments.rb:280:in `block in coerce_arguments'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema/member/has_arguments.rb:309:in `coerce_arguments'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/arguments_cache.rb:49:in `dataload_for'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:280:in `evaluate_selection'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:220:in `block (3 levels) in evaluate_selections'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:219:in `block (2 levels) in evaluate_selections'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:218:in `each'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:218:in `block in evaluate_selections'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:706:in `call_method_on_directives'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:215:in `evaluate_selections'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:114:in `block (3 levels) in run_eager'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:113:in `block (2 levels) in run_eager'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:74:in `tap_or_each'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:104:in `block in run_eager'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:706:in `call_method_on_directives'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter/runtime.rb:95:in `run_eager'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:70:in `block (4 levels) in run_all'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/tracing/trace.rb:44:in `execute_query'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:69:in `block (3 levels) in run_all'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/dataloader/null_dataloader.rb:19:in `append_job'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:57:in `block (2 levels) in run_all'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:53:in `each'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:53:in `each_with_index'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:53:in `block in run_all'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/tracing/trace.rb:40:in `execute_multiplex'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/execution/interpreter.rb:37:in `run_all'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema.rb:1332:in `multiplex'
  /usr/local/bundle/gems/graphql-2.3.4/lib/graphql/schema.rb:1308:in `execute'
  /home/user/app/app/actions/graphql/api.rb:17:in `handle'
  /usr/local/bundle/gems/hanami-controller-2.1.0/lib/hanami/action.rb:326:in `block in call'
  /usr/local/bundle/gems/hanami-controller-2.1.0/lib/hanami/action.rb:307:in `catch'
  /usr/local/bundle/gems/hanami-controller-2.1.0/lib/hanami/action.rb:307:in `call'
  /usr/local/bundle/gems/hanami-2.1.1/lib/hanami/slice/routing/resolver.rb:78:in `block in resolve_slice_action'
  /usr/local/bundle/gems/hanami-router-2.1.0/lib/hanami/router.rb:109:in `call'
  /home/user/app/app/middlewares/authorization.rb:19:in `call'
  /usr/local/bundle/gems/hanami-router-2.1.0/lib/hanami/middleware/body_parser.rb:52:in `call'
  /usr/local/bundle/gems/rack-2.2.9/lib/rack/method_override.rb:24:in `call'
  /usr/local/bundle/gems/hanami-2.1.1/lib/hanami/middleware/render_errors.rb:57:in `call'
  /usr/local/bundle/gems/dry-monitor-1.0.1/lib/dry/monitor/rack/middleware.rb:36:in `block in call'
  /usr/local/bundle/gems/dry-monitor-1.0.1/lib/dry/monitor/clock.rb:15:in `measure'
  /usr/local/bundle/gems/dry-monitor-1.0.1/lib/dry/monitor/rack/middleware.rb:36:in `call'
  /usr/local/bundle/gems/hanami-router-2.1.0/lib/hanami/middleware/app.rb:40:in `call'
  /usr/local/bundle/gems/hanami-2.1.1/lib/hanami/slice.rb:758:in `call'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/configuration.rb:272:in `call'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/request.rb:100:in `block in handle_request'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/thread_pool.rb:378:in `with_force_shutdown'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/request.rb:99:in `handle_request'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/server.rb:464:in `process_client'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/server.rb:245:in `block in run'
  /usr/local/bundle/gems/puma-6.4.2/lib/puma/thread_pool.rb:155:in `block in spawn_thread'

I thought it might be a threading issue, but it doesn’t seem to be. It is not always the same SQL query that causes the crash. It seems arbitrary. Can anyone help me?

Thanks
best regards
Armin

cllns · June 12, 2024, 4:04pm

I suspect it might have something to do with the empty interpolation hash {} at the very end of the SQL string?

That’s the same syntax dry-logger uses to add in the the HTTP verb, so it might be getting mixed up.

Do all the instances of crashes have that trailing empty hash?

wuarmin · June 12, 2024, 7:01pm

Thanks @cllns.
You have found the reason. The error really only occurs if this interpolation hash is included at the very end.
Do you know why this interpolation hash is printed?

Do you have a solution approach?

cllns · June 13, 2024, 7:14pm

@wuarmin Can you provide a reproducible script/repo? Happy to debug and fix it in dry-logger but I’m having trouble reproducing it without more info

wuarmin · June 19, 2024, 6:39pm

@cllns Hi,
I have now taken a closer look. It is difficult to provide a script. I think it might have something to do with the fact that the SQL log ends up in the rack-logging-backend.

github.com

hanami/hanami/blob/65249961d32c99340bba9d74caf664f9f489fafa/lib/hanami/config/logger.rb#L153


      
            logger_constructor.call(env, app_name.name, **logger_constructor_options)
          end
          
          # Build an instance of a development logger
          #
          # This logger is used in both development and test
          #
          # @return [Dry::Logger::Dispatcher]
          # @since 2.0.0
          # @api private
          def development_logger(_env, app_name, **options)
            Dry.Logger(app_name, **options) do |setup|
              setup
                .add_backend(log_if: -> entry { !entry.tag?(:rack) })
                .add_backend(formatter: :rack, log_if: -> entry { entry.tag?(:rack) })
            end
          end
          
          # Build an instance of a production logger
          #
          # This logger is used in both development and test

If the Dry::Logger::Entry with the SQL-string has set the tag :rack, the logging crashes, cause the rack backend is used.

#<Dry::Logger::Entry:0x00007f8b22f311a0 @clock=#<Dry::Logger::Clock:0x00007f8b22e3b408 @unit=:nanosecond>, @progname="pay_n_red", @severity="info", @tags=[:rack, :rack], @level=1, @message="(0.001148s) SELECT \"output_types\".\"id\", \"output_types\".\"name\", \"output_types\".\"price\", \"output_types\".\"vat_rate\" FROM \"output_types\" WHERE (\"output_types\".\"id\" IN ('PD')) ORDER BY \"output_types\".\"id\"", @payload={}>

I suspect that it is a bug around the @tags at the Dispatcher. In the above output rack is even tagged 2 times. So it might be a threading issue.

Here happens creation of the Dry::Logger:Entries:

github.com

dry-rb/dry-logger/blob/0ec6da8be896f234da44b97fe0f63ab3db0d712a/lib/dry/logger/dispatcher.rb#L218


      
          def log(severity, message = nil, **payload, &block)
            case message
            when Hash then log(severity, **message, &block)
            else
              if block
                progname = message
                message = block.call
              end
              progname ||= id
          
              entry = Entry.new(
                clock: clock,
                progname: progname,
                severity: severity,
                tags: @tags,
                message: message,
                payload: {**context, **payload}
              )
          
              each_backend do |backend|
                backend.__send__(severity, entry) if backend.log?(entry)

…and here the :rack tag is added:

github.com

hanami/hanami/blob/65249961d32c99340bba9d74caf664f9f489fafa/lib/hanami/web/rack_logger.rb#L147


      
          
            rack_monitor.on :error do |event|
              # TODO: why we don't provide time on error?
              log_exception event[:env], event[:exception], 500, 0
            end
          end
          
          # @api private
          # @since 2.0.0
          def log_request(env, status, elapsed)
            logger.tagged(:rack) do
              logger.info(**data(env, status: status, elapsed: elapsed))
            end
          end
          
          # @api private
          # @since 2.0.0
          def log_exception(env, exception, status, elapsed)
            logger.tagged(:rack) do
              logger.error(exception, **data(env, status: status, elapsed: elapsed))
            end

…and here’s the implementation of tagged:

github.com

dry-rb/dry-logger/blob/0ec6da8be896f234da44b97fe0f63ab3db0d712a/lib/dry/logger/dispatcher.rb#L253


      
          #   logger.tagged("red") do
          #     logger.info "Hello World"
          #     # Hello World tag=red
          #   end
          #
          #   logger.info "Hello Again"
          #   # Hello Again
          #
          # @since 1.0.0
          # @api public
          def tagged(*tags)
            @tags.concat(tags)
            yield
          ensure
            @tags = []
          end
          
          # Add a new backend to an existing dispatcher
          #
          # @example
          #   logger.add_backend(template: "ERROR: %<message>s") { |b|

The member @tags is mutated. If other entries are created in the meantime, you will receive the wrong tags.

I tried it to fix with following change:

  def tagged(*tags)
    @mutex.synchronize do
      original_tags = @tags.dup
      @tags.concat(tags)
      yield self
    ensure
      @tags = original_tags
    end
  end

But it fails, cause Mutex is not reentrant. What do you think? Shoud we switch to Class: Monitor (Ruby 2.5.3)?
Do we need to refactor more roughly here? Maybe @solnic can help here.

wuarmin · June 23, 2024, 8:14am

Why don’t we just pass the tags to the log method?
For which specific use case is the tagged feature intended?

robisenberg · December 10, 2025, 11:27am

Hi. I was also experiencing this issue in my development logs. It took a while, but I’ve managed to fix the issue by adding the following to my config/app.rb up near the top, just after the requires:

# Patch dry-monitor's SQL logger BEFORE anything else loads.
# This must happen early because the SQL logger is instantiated when
# the db provider starts, which happens before initializers run.
#
# SQL queries logged during a rack request inherit the :rack tag from
# dry-monitor's rack middleware context. This causes them to be routed
# to the rack formatter backend, which crashes because SQL logs don't
# have the required HTTP-specific keys (verb, status, etc.).
#
# This patch adds a :sql tag to SQL logs, allowing them to be routed
# to the default formatter backend instead.
require "dry-monitor"
require "dry/monitor/sql/logger"

module SQLLoggerFix
  def log_query(time:, name:, query:)
    message = @template % [name.inspect, time, colorizer.call(query)]

    @logger.tagged(:sql) do
      @logger.info(message)
    end
  end
end

Dry::Monitor::SQL::Logger.prepend(SQLLoggerFix)

# Patch Hanami's development logger to handle SQL logs correctly.
#
# SQL logs inherit the :rack tag from dry-monitor's rack middleware context,
# causing them to be routed to the rack formatter which crashes. This patch
# routes SQL logs (tagged with :sql by sql_logger_fix.rb) to the default
# formatter instead.
module Hanami
  class Config
    class Logger
      def development_logger(_env, app_name, **options)
        Dry.Logger(app_name, **options) do |setup|
          setup
            .add_backend(log_if: -> entry { !entry.tag?(:rack) || entry.tag?(:sql) })
            .add_backend(formatter: :rack, log_if: -> entry { entry.tag?(:rack) && !entry.tag?(:sql) })
        end
      end
    end
  end
end

Hope this helps someone else seeing these.

timriley · December 10, 2025, 11:43am

Thanks for this, @robisenberg! One of my goals for the next Hanami release is to straighten out any kinks around logging (see Improve logging · Issue #8 · hanami/roadmap · GitHub). I’ve just added this to the roadmap item so we don’t lose track.

I’d love to take a look sooner, too, and see if we could get a fix out as a patch release. Is there any way you might be able to provide a reproduction of the issue as you were seeing it?

In the meantime, your workaround is very helpful, thanks for figuring it out and for sharing it with the community!

robisenberg · December 10, 2025, 1:20pm

Hi @timriley. Thanks for all your work on Hanami - such a great framework!

Sure thing. With a little help from Claude…

#!/usr/bin/env ruby
# frozen_string_literal: true

# Reproduction of SQL logging crash in Hanami 2.x development mode
#
# The issue: When SQL queries run during a rack request, they inherit the :rack
# tag from dry-monitor's rack middleware context. This routes them to the rack
# formatter backend, which crashes because SQL logs don't have HTTP-specific
# fields (verb, status, etc.).
#
# Run: bundle exec ruby sql_logger_bug_repro.rb
#
# Expected: Crash with "key<verb> not found (KeyError)"

require "bundler/inline"

gemfile do
  source "https://rubygems.org"
  gem "dry-logger", "~> 1.0"
  gem "dry-monitor", "~> 1.0"
end

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

# This is how Hanami configures its development logger (simplified from
# Hanami::Config::Logger#development_logger)
logger = Dry.Logger(:test_app) do |setup|
  setup
    .add_backend(log_if: ->(entry) { !entry.tag?(:rack) })
    .add_backend(formatter: :rack, log_if: ->(entry) { entry.tag?(:rack) })
end

# Set up SQL logging via dry-monitor (like ROM's instrumentation plugin does)
notifications = Dry::Monitor::Notifications.new(:test)
sql_logger = Dry::Monitor::SQL::Logger.new(logger)
sql_logger.subscribe(notifications)

puts "=== Test 1: SQL log WITHOUT rack context (works fine) ==="
notifications.instrument(:sql, name: :postgres, query: "SELECT 1") {}
puts "✓ Logged successfully\n\n"

puts "=== Test 2: SQL log WITHIN rack context (crashes) ==="
puts "Simulating what happens when SQL runs during a rack request..."
puts "(Look for '[FATAL] Logging crashed' below - that's the bug)"
puts

# This simulates what dry-monitor's Rack::Middleware does - it wraps the
# request in a tagged(:rack) context. Any logs within this block inherit
# the :rack tag, including SQL logs.
logger.tagged(:rack) do
  # This will crash because:
  # 1. The log entry gets tagged with :rack (inherited from context)
  # 2. The rack backend's log_if returns true (entry.tag?(:rack) == true)
  # 3. The rack formatter tries to format it with a template expecting
  #    HTTP fields like %<verb>s, %<status>s, etc.
  # 4. SQL logs don't have these fields -> KeyError
  notifications.instrument(:sql, name: :postgres, query: "SELECT * FROM users") {}
end

puts
puts "Note: dry-logger catches the error internally and logs it as FATAL,"
puts "but in a real Hanami app this causes SQL logs to be lost/corrupted."

Here’s the output:

% ruby sql_logger_bug_repro.rb
=== Test 1: SQL log WITHOUT rack context (works fine) ===
Loaded :postgres in 0ms SELECT 1
✓ Logged successfully

=== Test 2: SQL log WITHIN rack context (crashes) ===
Simulating what happens when SQL runs during a rack request...
(Look for '[FATAL] Logging crashed' below - that's the bug)

[test_app] [FATAL] [2025-12-10 13:18:55 +0000] Logging crashed
    Loaded :postgres in 0ms SELECT * FROM users {}
  key<verb> not found (KeyError)
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/formatters/template.rb:72:in 'String#%'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/formatters/template.rb:72:in 'Dry::Logger::Formatters::Template#%'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/formatters/string.rb:75:in 'Dry::Logger::Formatters::String#format'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/formatters/structured.rb:55:in 'Dry::Logger::Formatters::Structured#call'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/logger-1.7.0/lib/logger.rb:787:in 'Logger#format_message'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/logger-1.7.0/lib/logger.rb:692:in 'Logger#add'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/logger-1.7.0/lib/logger.rb:721:in 'Logger#info'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:235:in 'block in Dry::Logger::Dispatcher#log'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:300:in 'Array#each'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:300:in 'block in Dry::Logger::Dispatcher#each_backend'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:299:in 'Thread::Mutex#synchronize'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:299:in 'Dry::Logger::Dispatcher#each_backend'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:234:in 'Dry::Logger::Dispatcher#log'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:132:in 'Dry::Logger::Dispatcher#info'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-monitor-1.0.1/lib/dry/monitor/sql/logger.rb:56:in 'Dry::Monitor::SQL::Logger#log_query'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-monitor-1.0.1/lib/dry/monitor/sql/logger.rb:52:in 'block in Dry::Monitor::SQL::Logger#subscribe'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-monitor-1.0.1/lib/dry/monitor/notifications.rb:33:in 'block in Dry::Monitor::Notifications#instrument'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-events-1.1.0/lib/dry/events/bus.rb:38:in 'block in Dry::Events::Bus#process'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-events-1.1.0/lib/dry/events/bus.rb:34:in 'Array#each'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-events-1.1.0/lib/dry/events/bus.rb:34:in 'Dry::Events::Bus#process'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-events-1.1.0/lib/dry/events/publisher.rb:269:in 'Dry::Events::Publisher::InstanceMethods#process'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-monitor-1.0.1/lib/dry/monitor/notifications.rb:31:in 'Dry::Monitor::Notifications#instrument'
  sql_logger_bug_repro.rb:59:in 'block in <main>'
  /Users/dev/.asdf/installs/ruby/3.4.7/lib/ruby/gems/3.4.0/gems/dry-logger-1.2.0/lib/dry/logger/dispatcher.rb:262:in 'Dry::Logger::Dispatcher#tagged'
  sql_logger_bug_repro.rb:52:in '<main>'


Note: dry-logger catches the error internally and logs it as FATAL,
but in a real Hanami app this causes SQL logs to be lost/corrupted.

timriley · December 12, 2025, 1:47am

Thanks @robisenberg! And thanks @wuarmin for your input too!

This is indeed a thread safety issue, which I’ve fixed here: Ensure logger tags and context are threadsafe by timriley · Pull Request #38 · dry-rb/dry-logger

I’m leaving this PR open for a couple days to receive feedback from our maintainers. If you want to give it a test yourself, please feel free to try that branch

Pending feedback, I’ll aim merge this next week and make a new patch release of dry-logger.

timriley · December 15, 2025, 11:08pm

I’ve just released dry-logger v1.2.1 with this fix included

wuarmin · December 16, 2025, 7:42am

Thank you @timriley!

Topic		Replies	Views
Suppressing SQL logging in production questions	10	155	December 12, 2024
Disable RackLogger in favor of manually hooking into actions' "handle" for logging requests questions	1	101	March 19, 2025
Hanami.app["logger"] does not work as expected issues	3	461	November 10, 2022
No db logging in test suite issues	3	63	August 29, 2024
Adding attributes to default logger questions	1	910	March 2, 2023

dry-logger crashes fatally

Related topics