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?

Topic		Replies	Views
How can I avoid 40x error from logging as ERROR? issues	5	444	October 7, 2023
Hanami.app["logger"] does not work as expected issues	3	426	November 10, 2022
Can't spin up `hanami dev` on 2.2.0.beta1 issues	4	68	September 16, 2024
How to fix incompatible dry-core dependency issue? issues	4	402	November 14, 2022
Hanami 1.3 -> Hanami 2.0 questions	21	1539	June 16, 2023

dry-logger crashes fatally

Related topics