undefined method `current_tags' for nil:NilClass

[es1o]

Hello.
I use logstash-logger 0.22.0 with my rails application and sidekiq. When I run perform_later function I get an error:
undefined method `current_tags' for nil:NilClass

This is my logger configuration:

  config.log_formatter = ::Logger::Formatter.new

  config.logstash.error_logger = Logger.new($stderr)
  config.logstash.type = :multi_logger
  config.logstash.outputs = [
    {
      type: :tcp,
      port: 5228,
      host: 'localhost'
    },
    {
      type: :stdout,
    }
  ]

[dwbutler]

Hi,

MultiLogger implements ActiveSupport's tagged logging interface - namely, the tagged method. Can you attach the full backtrace so I can understand what part of the stack is expecting to be able to call current_tags?

[es1o]

Hello, sorry for delay, it is a full trace:

activejob (5.0.0.1) lib/active_job/logging.rb:51:in `logger_tagged_by_active_job?'
activejob (5.0.0.1) lib/active_job/logging.rb:43:in `tag_logger'
activejob (5.0.0.1) lib/active_job/logging.rb:14:in `block (2 levels) in <module:Logging>'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:391:in `instance_exec'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:391:in `block in make_lambda'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:285:in `block in halting'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:447:in `block in around'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:455:in `call'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:101:in `__run_callbacks__'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:750:in `_run_enqueue_callbacks'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:90:in `run_callbacks'
activejob (5.0.0.1) lib/active_job/enqueuing.rb:72:in `enqueue'
activejob (5.0.0.1) lib/active_job/enqueuing.rb:18:in `perform_later'
app/controllers/builds_controller.rb:68:in `refresh'
actionpack (5.0.0.1) lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
actionpack (5.0.0.1) lib/abstract_controller/base.rb:188:in `process_action'
actionpack (5.0.0.1) lib/action_controller/metal/rendering.rb:30:in `process_action'
actionpack (5.0.0.1) lib/abstract_controller/callbacks.rb:20:in `block in process_action'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:126:in `call'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:455:in `call'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:101:in `__run_callbacks__'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:90:in `run_callbacks'
actionpack (5.0.0.1) lib/abstract_controller/callbacks.rb:19:in `process_action'
actionpack (5.0.0.1) lib/action_controller/metal/rescue.rb:20:in `process_action'
actionpack (5.0.0.1) lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
activesupport (5.0.0.1) lib/active_support/notifications.rb:164:in `block in instrument'
activesupport (5.0.0.1) lib/active_support/notifications/instrumenter.rb:21:in `instrument'
activesupport (5.0.0.1) lib/active_support/notifications.rb:164:in `instrument'
actionpack (5.0.0.1) lib/action_controller/metal/instrumentation.rb:30:in `process_action'
actionpack (5.0.0.1) lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
activerecord (5.0.0.1) lib/active_record/railties/controller_runtime.rb:18:in `process_action'
actionpack (5.0.0.1) lib/abstract_controller/base.rb:126:in `process'
actionview (5.0.0.1) lib/action_view/rendering.rb:30:in `process'
actionpack (5.0.0.1) lib/action_controller/metal.rb:190:in `dispatch'
actionpack (5.0.0.1) lib/action_controller/metal.rb:262:in `dispatch'
actionpack (5.0.0.1) lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
actionpack (5.0.0.1) lib/action_dispatch/routing/route_set.rb:32:in `serve'
actionpack (5.0.0.1) lib/action_dispatch/journey/router.rb:39:in `block in serve'
actionpack (5.0.0.1) lib/action_dispatch/journey/router.rb:26:in `each'
actionpack (5.0.0.1) lib/action_dispatch/journey/router.rb:26:in `serve'
actionpack (5.0.0.1) lib/action_dispatch/routing/route_set.rb:725:in `call'
warden (1.2.6) lib/warden/manager.rb:35:in `block in call'
warden (1.2.6) lib/warden/manager.rb:34:in `catch'
warden (1.2.6) lib/warden/manager.rb:34:in `call'
rack (2.0.1) lib/rack/etag.rb:25:in `call'
rack (2.0.1) lib/rack/conditional_get.rb:25:in `call'
rack (2.0.1) lib/rack/head.rb:12:in `call'
rack (2.0.1) lib/rack/session/abstract/id.rb:222:in `context'
rack (2.0.1) lib/rack/session/abstract/id.rb:216:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/cookies.rb:613:in `call'
activerecord (5.0.0.1) lib/active_record/migration.rb:552:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:97:in `__run_callbacks__'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
activesupport (5.0.0.1) lib/active_support/callbacks.rb:90:in `run_callbacks'
actionpack (5.0.0.1) lib/action_dispatch/middleware/callbacks.rb:36:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/executor.rb:12:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
web-console (3.4.0) lib/web_console/middleware.rb:135:in `call_app'
web-console (3.4.0) lib/web_console/middleware.rb:28:in `block in call'
web-console (3.4.0) lib/web_console/middleware.rb:18:in `catch'
web-console (3.4.0) lib/web_console/middleware.rb:18:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
railties (5.0.0.1) lib/rails/rack/logger.rb:36:in `call_app'
railties (5.0.0.1) lib/rails/rack/logger.rb:24:in `block in call'
logstash-logger (0.22.0) lib/logstash-logger/multi_logger.rb:60:in `tag_loggers'
logstash-logger (0.22.0) lib/logstash-logger/multi_logger.rb:63:in `block in tag_loggers'
logstash-logger (0.22.0) lib/logstash-logger/tagged_logging.rb:5:in `block in tagged'
logstash-logger (0.22.0) lib/logstash-logger/tagged_logging.rb:16:in `tagged'
logstash-logger (0.22.0) lib/logstash-logger/tagged_logging.rb:5:in `tagged'
logstash-logger (0.22.0) lib/logstash-logger/multi_logger.rb:62:in `tag_loggers'
logstash-logger (0.22.0) lib/logstash-logger/multi_logger.rb:63:in `block in tag_loggers'
logstash-logger (0.22.0) lib/logstash-logger/tagged_logging.rb:5:in `block in tagged'
logstash-logger (0.22.0) lib/logstash-logger/tagged_logging.rb:16:in `tagged'
logstash-logger (0.22.0) lib/logstash-logger/tagged_logging.rb:5:in `tagged'
logstash-logger (0.22.0) lib/logstash-logger/multi_logger.rb:62:in `tag_loggers'
logstash-logger (0.22.0) lib/logstash-logger/multi_logger.rb:56:in `tagged'
railties (5.0.0.1) lib/rails/rack/logger.rb:24:in `call'
sprockets-rails (3.2.0) lib/sprockets/rails/quiet_assets.rb:13:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/request_id.rb:24:in `call'
rack (2.0.1) lib/rack/method_override.rb:22:in `call'
rack (2.0.1) lib/rack/runtime.rb:22:in `call'
activesupport (5.0.0.1) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/executor.rb:12:in `call'
actionpack (5.0.0.1) lib/action_dispatch/middleware/static.rb:136:in `call'
rack (2.0.1) lib/rack/sendfile.rb:111:in `call'
sentry-raven (2.2.0) lib/raven/integrations/rack.rb:50:in `call'
railties (5.0.0.1) lib/rails/engine.rb:522:in `call'
puma (3.6.2) lib/puma/configuration.rb:225:in `call'
puma (3.6.2) lib/puma/server.rb:578:in `handle_request'
puma (3.6.2) lib/puma/server.rb:415:in `process_client'
puma (3.6.2) lib/puma/server.rb:275:in `block in run'
puma (3.6.2) lib/puma/thread_pool.rb:116:in `block in spawn_thread'

It occurs only if I use a delayed job.

[dwbutler]

Thanks, that's helpful. IMO, ActiveJob is doing the "wrong" thing here by reaching into the formatter to get current_tags. It breaks the Law of Demeter. But as usual, I'll modify LogStashLogger to be compatible with how Rails actually works.

Exposing MultiLogger#formatter should fix it.

[es1o]

@dwbutler Thank you, It will be grat. Let me know if ou need more details to debug that problem.

[dwbutler]

@es1o Can you try out the referenced patch and see if that resolves the issue for you? Thanks!

[es1o]

@dwbutler It works! When it will be in release? Now I use specific revision in my gemfile, but it will be grat if I could install version of logstash-logger.

[dwbutler]

The fix has been released in 0.22.1.