ActionDispatch middleware can improperly format output

[soulcutter]

I discovered this in a logger I was writing inspired by this implementation.

The problem is that this particular ActionDispatch logging looks specifically for tags_text which is fine for single-value tags, but not for hash key/value tags.

https://github.com/rails/rails/blob/fc734f28e65ef8829a1a939ee6702c1f349a1d5a/actionpack/lib/action_dispatch/middleware/debug_exceptions.rb#L155

My own solution was to undef :tags_text in the formatter.

[stevenharman]

What would a failure case look like? i.e., how do I reproduce the issue?

[soulcutter]

It's pretty gnarly. It inserts [{ "key" => "value"}] between each line of the log message.

In my case I tagged my logs with { "trace_origin" => "<stuff>", "uuid" => "<stuff>" } in a rack middleware and got this kind of junk:

{"trace_origin":"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB","uuid":"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB","message":"  \n[{\"trace_origin\"=\u003e\"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB\", \"uuid\"=\u003e\"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB\"}] ActiveRecord::ConnectionNotEstablished (connection to server at \"127.0.0.1\", port 5432 failed: Connection refused\n\tIs the server running on that host and accepting TCP/IP connections?\nconnection to server at \"::1\", port 5432 failed: Connection refused\n\tIs the server running on that host and accepting TCP/IP connections?\n):\n[{\"trace_origin\"=\u003e\"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB\", \"uuid\"=\u003e\"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB\"}]   \n[{\"trace_origin\"=\u003e\"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB\", \"uuid\"=\u003e\"01HAT6DA53YX5RCTXZQG2F8XK7-ECHELON-WEB\"}]

It goes on and on.

The expected output was

{"trace_origin":"01HAT6KX3RAT1CXCC5J43AQKDV-ECHELON-WEB","uuid":"01HAT6KX3RAT1CXCC5J43AQKDV-ECHELON-WEB","message":"  \nActiveRecord::ConnectionNotEstablished (connection to server at \"127.0.0.1\", port 5432 failed: Connection refused\n\tIs the server running on that host and accepting TCP/IP connections?\nconnection to server at \"::1\", port 5432 failed: Connection refused\n\tIs the server running on that host and accepting TCP/IP connections?\n):\n

And a bunch more (but not polluted with interspersed tags). In many ways I think that ActionDispatch output is nonsense - and somebody put that in for some reason - and this is a fairly extreme edge case that I'm sure only comes up when you have middleware that adds some tags - otherwise the likelihood of there existing tags there is very small.

[soulcutter]

For reproducing, here's the sort of middleware I had:

      class Middleware
        def initialize(app, config)
          @app = app
          @config = config
        end

        def call(env)
          tags = {
            "trace_origin" => env[CORRELATION_ID_KEY],
            "uuid" => env[REQUEST_ID_KEY],
          }.compact

          @config.logger.tagged(tags) { @app.call(env) }
        end
      end

[stevenharman]

Hmm. We use a logfmt/tagged_logger as our Rails.logger, and we have a piece of middleware that tags the current requests's "code owner," but we're not seeing this behavior.

The middleware:

class CodeOwnerLogTagger
  def initialize(app)
    @app = app
  end

  def call(env)
    request = ActionDispatch::Request.new(env)

    CodeOwners.lazy_owner_for(request.controller_class.name) do |lazy_owner|
      Rails.logger.tagged(code_owner: lazy_owner) do
        @app.call(env)
      end
    end
  end
end

The CodeOwners mechanism is a whole other topic of discussion (and something I should extract at some point), but it shouldn't have any impact on the behavior you're describing. Are you able to reproduce what you're seeing with logfmt?

[soulcutter]

Alright, here's what I got. You can run this via rackup logfmt.ru (it takes a little bit to spin up) and then hit http://localhost:9292 to trigger the log

logfmt.ru

require 'bundler/inline'

gemfile(true) do
  source 'https://rubygems.org'

  gem 'rails', '~> 7.0.4'
  gem 'sqlite3'
  gem 'logfmt-tagged_logger'
  gem 'webrick'
end

require 'webrick'
require 'rails/all'
require 'logfmt/tagged_logger'

# idk if there's a way to skip db setup
ENV['DATABASE_URL'] = "sqlite3:development.sqlite3"
ActiveRecord::Base.establish_connection(adapter: 'sqlite3', database: 'development.sqlite3')

# Some Railtie or something does this in a real app
Rails.logger = Logfmt::TaggedLogger.new($stdout)

class App < Rails::Application
  config.root = __dir__
  config.consider_all_requests_local = true
  config.secret_key_base = 'i_am_a_secret'
  config.active_storage.service_configurations = { 'local' => { 'service' => 'Disk', 'root' => './storage' } }

  routes.append do
    root to: 'welcome#index'
  end
end

class WelcomeController < ActionController::Base
  def index
    raise "hell"
    # render inline: 'Hi!'
  end
end

class TagLogsMiddleware
  def initialize(app) = @app = app

  def call(env)
    Rails.logger.tagged(funky: :tag, the_more: :the_worse_it_gets) { @app.call(env) }
  end
end

App.initialize!

# middlewares!

# Logfmt::TaggedLogger adds tags here
use TagLogsMiddleware

# Rails sets this up, you can see where in a
# "real" app with `bundle exec rails middleware`
use ActionDispatch::ShowExceptions, ActionDispatch::PublicExceptions.new("/")

run App

The logfmt output looks like

time=2023-09-22T16:48:41.506675Z severity=INFO  funky=tag the_more=the_worse_it_gets msg="Started GET \"/\" for ::1 at 2023-09-22 12:48:41 -0400"
time=2023-09-22T16:48:41.526633Z severity=INFO  funky=tag the_more=the_worse_it_gets msg="Processing by WelcomeController#index as HTML"
time=2023-09-22T16:48:41.530214Z severity=INFO  funky=tag the_more=the_worse_it_gets msg="Completed 500 Internal Server Error in 3ms (ActiveRecord: 0.0ms | Allocations: 1263)\n\n"
time=2023-09-22T16:48:41.530900Z severity=FATAL funky=tag the_more=the_worse_it_gets msg="  \n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] RuntimeError (hell):\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}]   \n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] logfmt.ru:44:in `index'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/abstract_controller/base.rb:215:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal/rendering.rb:165:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/abstract_controller/callbacks.rb:234:in `block in process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/callbacks.rb:118:in `block in run_callbacks'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actiontext (7.0.8) lib/action_text/rendering.rb:20:in `with_renderer'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actiontext (7.0.8) lib/action_text/engine.rb:69:in `block (4 levels) in <class:Engine>'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `instance_exec'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/callbacks.rb:138:in `run_callbacks'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/abstract_controller/callbacks.rb:233:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal/rescue.rb:23:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/notifications.rb:206:in `block in instrument'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/notifications/instrumenter.rb:24:in `instrument'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/notifications.rb:206:in `instrument'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal/instrumentation.rb:66:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activerecord (7.0.8) lib/active_record/railties/controller_runtime.rb:27:in `process_action'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/abstract_controller/base.rb:151:in `process'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionview (7.0.8) lib/action_view/rendering.rb:39:in `process'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal.rb:188:in `dispatch'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_controller/metal.rb:251:in `dispatch'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:32:in `serve'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/journey/router.rb:50:in `block in serve'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `each'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `serve'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:852:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/tempfile_reaper.rb:15:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/etag.rb:27:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/conditional_get.rb:27:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/head.rb:12:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/http/permissions_policy.rb:38:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/http/content_security_policy.rb:36:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/session/abstract/id.rb:266:in `context'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/session/abstract/id.rb:260:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/cookies.rb:704:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/callbacks.rb:99:in `run_callbacks'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/callbacks.rb:26:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/executor.rb:14:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] railties (7.0.8) lib/rails/rack/logger.rb:40:in `call_app'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] railties (7.0.8) lib/rails/rack/logger.rb:25:in `block in call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `block in tagged'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/tagged_logging.rb:37:in `tagged'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `tagged'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] railties (7.0.8) lib/rails/rack/logger.rb:25:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/request_id.rb:26:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/method_override.rb:24:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/runtime.rb:22:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/executor.rb:14:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/static.rb:23:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/sendfile.rb:110:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/host_authorization.rb:138:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] railties (7.0.8) lib/rails/engine.rb:530:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] railties (7.0.8) lib/rails/railtie.rb:226:in `public_send'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] railties (7.0.8) lib/rails/railtie.rb:226:in `method_missing'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] actionpack (7.0.8) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] logfmt.ru:54:in `block in call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `block in tagged'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/tagged_logging.rb:37:in `tagged'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] activesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `tagged'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] logfmt.ru:54:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/tempfile_reaper.rb:15:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/lint.rb:50:in `_call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/lint.rb:38:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/show_exceptions.rb:23:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/common_logger.rb:38:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/content_length.rb:17:in `call'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] rack (2.2.8) lib/rack/handler/webrick.rb:95:in `service'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] webrick (1.8.1) lib/webrick/httpserver.rb:140:in `service'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] webrick (1.8.1) lib/webrick/httpserver.rb:96:in `run'\n[{:funky=>:tag, :the_more=>:the_worse_it_gets}] webrick (1.8.1) lib/webrick/server.rb:310:in `block in start_thread'"
::1 - - [22/Sep/2023:12:48:41 -0400] "GET / HTTP/1.1" 500 114255 0.1589

The part you probably don't want is [{:funky=>:tag, :the_more=>:the_worse_it_gets}]

Add this in to the example

class Logfmt::TaggedLogger::Formatter
  undef :tags_text
end

and you get:

time=2023-09-22T16:59:39.859134Z severity=INFO  funky=tag the_more=the_worse_it_gets msg="Started GET \"/\" for ::1 at 2023-09-22 12:59:39 -0400"
time=2023-09-22T16:59:39.876848Z severity=INFO  funky=tag the_more=the_worse_it_gets msg="Processing by WelcomeController#index as HTML"
time=2023-09-22T16:59:39.879734Z severity=INFO  funky=tag the_more=the_worse_it_gets msg="Completed 500 Internal Server Error in 3ms (ActiveRecord: 0.0ms | Allocations: 1263)\n\n"
time=2023-09-22T16:59:39.880473Z severity=FATAL funky=tag the_more=the_worse_it_gets msg="  \nRuntimeError (hell):\n  \nlogfmt.ru:40:in `index'\nactionpack (7.0.8) lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'\nactionpack (7.0.8) lib/abstract_controller/base.rb:215:in `process_action'\nactionpack (7.0.8) lib/action_controller/metal/rendering.rb:165:in `process_action'\nactionpack (7.0.8) lib/abstract_controller/callbacks.rb:234:in `block in process_action'\nactivesupport (7.0.8) lib/active_support/callbacks.rb:118:in `block in run_callbacks'\nactiontext (7.0.8) lib/action_text/rendering.rb:20:in `with_renderer'\nactiontext (7.0.8) lib/action_text/engine.rb:69:in `block (4 levels) in <class:Engine>'\nactivesupport (7.0.8) lib/active_support/callbacks.rb:127:in `instance_exec'\nactivesupport (7.0.8) lib/active_support/callbacks.rb:127:in `block in run_callbacks'\nactivesupport (7.0.8) lib/active_support/callbacks.rb:138:in `run_callbacks'\nactionpack (7.0.8) lib/abstract_controller/callbacks.rb:233:in `process_action'\nactionpack (7.0.8) lib/action_controller/metal/rescue.rb:23:in `process_action'\nactionpack (7.0.8) lib/action_controller/metal/instrumentation.rb:67:in `block in process_action'\nactivesupport (7.0.8) lib/active_support/notifications.rb:206:in `block in instrument'\nactivesupport (7.0.8) lib/active_support/notifications/instrumenter.rb:24:in `instrument'\nactivesupport (7.0.8) lib/active_support/notifications.rb:206:in `instrument'\nactionpack (7.0.8) lib/action_controller/metal/instrumentation.rb:66:in `process_action'\nactionpack (7.0.8) lib/action_controller/metal/params_wrapper.rb:259:in `process_action'\nactiverecord (7.0.8) lib/active_record/railties/controller_runtime.rb:27:in `process_action'\nactionpack (7.0.8) lib/abstract_controller/base.rb:151:in `process'\nactionview (7.0.8) lib/action_view/rendering.rb:39:in `process'\nactionpack (7.0.8) lib/action_controller/metal.rb:188:in `dispatch'\nactionpack (7.0.8) lib/action_controller/metal.rb:251:in `dispatch'\nactionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:49:in `dispatch'\nactionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:32:in `serve'\nactionpack (7.0.8) lib/action_dispatch/journey/router.rb:50:in `block in serve'\nactionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `each'\nactionpack (7.0.8) lib/action_dispatch/journey/router.rb:32:in `serve'\nactionpack (7.0.8) lib/action_dispatch/routing/route_set.rb:852:in `call'\nrack (2.2.8) lib/rack/tempfile_reaper.rb:15:in `call'\nrack (2.2.8) lib/rack/etag.rb:27:in `call'\nrack (2.2.8) lib/rack/conditional_get.rb:27:in `call'\nrack (2.2.8) lib/rack/head.rb:12:in `call'\nactionpack (7.0.8) lib/action_dispatch/http/permissions_policy.rb:38:in `call'\nactionpack (7.0.8) lib/action_dispatch/http/content_security_policy.rb:36:in `call'\nrack (2.2.8) lib/rack/session/abstract/id.rb:266:in `context'\nrack (2.2.8) lib/rack/session/abstract/id.rb:260:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/cookies.rb:704:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'\nactivesupport (7.0.8) lib/active_support/callbacks.rb:99:in `run_callbacks'\nactionpack (7.0.8) lib/action_dispatch/middleware/callbacks.rb:26:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/executor.rb:14:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/debug_exceptions.rb:28:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'\nrailties (7.0.8) lib/rails/rack/logger.rb:40:in `call_app'\nrailties (7.0.8) lib/rails/rack/logger.rb:25:in `block in call'\nactivesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `block in tagged'\nactivesupport (7.0.8) lib/active_support/tagged_logging.rb:37:in `tagged'\nactivesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `tagged'\nrailties (7.0.8) lib/rails/rack/logger.rb:25:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/remote_ip.rb:93:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/request_id.rb:26:in `call'\nrack (2.2.8) lib/rack/method_override.rb:24:in `call'\nrack (2.2.8) lib/rack/runtime.rb:22:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/executor.rb:14:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/static.rb:23:in `call'\nrack (2.2.8) lib/rack/sendfile.rb:110:in `call'\nactionpack (7.0.8) lib/action_dispatch/middleware/host_authorization.rb:138:in `call'\nrailties (7.0.8) lib/rails/engine.rb:530:in `call'\nrailties (7.0.8) lib/rails/railtie.rb:226:in `public_send'\nrailties (7.0.8) lib/rails/railtie.rb:226:in `method_missing'\nactionpack (7.0.8) lib/action_dispatch/middleware/show_exceptions.rb:29:in `call'\nlogfmt.ru:49:in `block in call'\nactivesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `block in tagged'\nactivesupport (7.0.8) lib/active_support/tagged_logging.rb:37:in `tagged'\nactivesupport (7.0.8) lib/active_support/tagged_logging.rb:99:in `tagged'\nlogfmt.ru:49:in `call'\nrack (2.2.8) lib/rack/tempfile_reaper.rb:15:in `call'\nrack (2.2.8) lib/rack/lint.rb:50:in `_call'\nrack (2.2.8) lib/rack/lint.rb:38:in `call'\nrack (2.2.8) lib/rack/show_exceptions.rb:23:in `call'\nrack (2.2.8) lib/rack/common_logger.rb:38:in `call'\nrack (2.2.8) lib/rack/content_length.rb:17:in `call'\nrack (2.2.8) lib/rack/handler/webrick.rb:95:in `service'\nwebrick (1.8.1) lib/webrick/httpserver.rb:140:in `service'\nwebrick (1.8.1) lib/webrick/httpserver.rb:96:in `run'\nwebrick (1.8.1) lib/webrick/server.rb:310:in `block in start_thread'"

An alternative to undefing might be to implement a version of tags_text that strips out the hash tags so you preserve the non-hash tags.

[stevenharman]

OK, I've finally had a chance to dig into this and it looks like the extra tags are being added by the ActionDispatch::DebugExceptions middleware - which is only present in development mode, IIRC.

I've not see this with our big Rails app b/c we explicitly remove that middleware since we rely on a canonical log line that adds error='ErrorName: Truncated error msg…' and on our error reporters in production environments.

That said, DebugExceptions is grabbing tags_text from the formatter instance, which is our Logfmt::Logger::KeyValueFormatter, as you've pointed out. And since our Logfmt::Logger::KeyValueFormatter formatter doesn't actually need/use/depend on the base ActiveSupport::TaggedLogging::Formatter, we could just redefine it to be the empty string, or undef it, as you've proposed.

I'm not sure which is more clean/clear. Thoughts?

[soulcutter]

I like undef because it improves the API of the logger, and (thankfully) the call-site causing this to occur manages without it.

This is the edgiest of edge cases, heh

[stevenharman]

One thing I dislike about undef is #tags_text is a private method of the ActiveSupport::TaggedLogging::Formatter. So if that API ever changes, and they remove that method, the undef is going to blow up. But I'm thinking this could work:

module Logfmt
  class TaggedLogger < ActiveSupport::Logger

    # … code and stuff

    class Formatter < SimpleDelegator

      # … yadda yadda

      undef_method :tags_text if (method_defined?(:tags_text) || private_method_defined?(:tags_text))

    end

    # … more code
  end
end

Maybe that's being overly-defensive though?

[stevenharman]

Hmm, the more I think about it, I worry that undef-ing (or undef_method-ing) might be more trouble than it's worth. I say that b/c it will undefined the method on the ActiveSupport::TaggedLogging::Formatter module. Meaning if someone were to change their logger, or have multiple loggers, or different loggers for different components (don't ask me why, I'm just sayin'…) our undef could "break" them in that the tags would be omitted.

Like, imagine you define your Rails and Sidekiq loggers separately (again, I don't know why):

# Rails
MyApp::Application.configure do
  config.logger = ActiveSupport::TaggedLogging.new(Logger.new($stdout))
end

# Sidekiq
Sidekiq.configure_client do |config|
  config.logger = Logfmt::TaggedLogger.new($stdout)
end

In that case, when using the DebugExceptions middleware, your Rails log lines would inexplicably be missing the tags. Whereas if we redefined #tags_text in the Logfmt::TaggedLogger::Formatter, we'd only impact log lines from that formatter. Which is what we want.

Does that track?