NoMethodError: undefined method `current_tags' for nil:NilClass; Rails 5 + ActionCable

[msg7086]

Rails -- Exception: NoMethodError: undefined method `current_tags' for nil:NilClass                                                                     
/var/lib/gems/2.3.0/gems/actioncable-5.0.1/lib/action_cable/connection/tagged_logger_proxy.rb:21:in `tag'
/var/lib/gems/2.3.0/gems/actioncable-5.0.1/lib/action_cable/connection/tagged_logger_proxy.rb:36:in `log'
/var/lib/gems/2.3.0/gems/actioncable-5.0.1/lib/action_cable/connection/tagged_logger_proxy.rb:30:in `block (2 levels) in <class:TaggedLoggerProxy>'
/var/lib/gems/2.3.0/gems/actioncable-5.0.1/lib/action_cable/connection/base.rb:71:in `process'
/var/lib/gems/2.3.0/gems/actioncable-5.0.1/lib/action_cable/server/base.rb:28:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/routing/mapper.rb:17:in `block in <class:Constraints>'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/routing/mapper.rb:46:in `serve'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/journey/router.rb:39:in `block in serve'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/journey/router.rb:26:in `each'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/journey/router.rb:26:in `serve'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/routing/route_set.rb:725:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/etag.rb:25:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/conditional_get.rb:25:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/head.rb:12:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/session/abstract/id.rb:222:in `context'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/session/abstract/id.rb:216:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/var/lib/gems/2.3.0/gems/activerecord-5.0.1/lib/active_record/migration.rb:553:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
/var/lib/gems/2.3.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/var/lib/gems/2.3.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
/var/lib/gems/2.3.0/gems/activesupport-5.0.1/lib/active_support/callbacks.rb:90:in `run_callbacks'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/callbacks.rb:36:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/var/lib/gems/2.3.0/gems/better_errors-2.1.1/lib/better_errors/middleware.rb:59:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
/var/lib/gems/2.3.0/gems/web-console-3.4.0/lib/web_console/middleware.rb:135:in `call_app'
/var/lib/gems/2.3.0/gems/web-console-3.4.0/lib/web_console/middleware.rb:28:in `block in call'
/var/lib/gems/2.3.0/gems/web-console-3.4.0/lib/web_console/middleware.rb:18:in `catch'
/var/lib/gems/2.3.0/gems/web-console-3.4.0/lib/web_console/middleware.rb:18:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/var/lib/gems/2.3.0/gems/railties-5.0.1/lib/rails/rack/logger.rb:36:in `call_app'
/var/lib/gems/2.3.0/gems/railties-5.0.1/lib/rails/rack/logger.rb:24:in `block in call'
/home/msg7086/.bundle/ruby/2.3.0/semantic_logger-f8d2970cb247/lib/semantic_logger/semantic_logger.rb:299:in `tagged'
/home/msg7086/.bundle/ruby/2.3.0/semantic_logger-f8d2970cb247/lib/semantic_logger/base.rb:146:in `tagged'
/var/lib/gems/2.3.0/gems/railties-5.0.1/lib/rails/rack/logger.rb:24:in `call'
/var/lib/gems/2.3.0/gems/sprockets-rails-3.2.0/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/request_id.rb:24:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/method_override.rb:22:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/runtime.rb:22:in `call'
/var/lib/gems/2.3.0/gems/activesupport-5.0.1/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/executor.rb:12:in `call'
/var/lib/gems/2.3.0/gems/actionpack-5.0.1/lib/action_dispatch/middleware/static.rb:136:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/sendfile.rb:111:in `call'
/var/lib/gems/2.3.0/gems/railties-5.0.1/lib/rails/engine.rb:522:in `call'
/var/lib/gems/2.3.0/gems/rack-2.0.1/lib/rack/handler/webrick.rb:86:in `service'
/usr/lib/ruby/2.3.0/webrick/httpserver.rb:140:in `service'
/usr/lib/ruby/2.3.0/webrick/httpserver.rb:96:in `run'
/usr/lib/ruby/2.3.0/webrick/server.rb:296:in `block in start_thread'

Where action_cable/connection/tagged_logger_proxy.rb:21 says

if logger.respond_to?(:tagged)
  current_tags = tags - logger.formatter.current_tags  <--
  logger.tagged(*current_tags) { yield }
else
  yield
end

Problem only gets hit by action cable connections. On latest github version.

[msg7086]

Just noticed that it may belongs to semantic_logger repo, not the rails one, as indicated by backtrace.

[reidmorrison]

Rails Semantic Logger attempts to monkey patch several rails components to make them less dependent on the Rails Logger extensions.

In this case Action Cable is supposed to be patched with the following code in Rails Semantic Logger: https://github.com/rocketjob/rails_semantic_logger/blob/master/lib/rails_semantic_logger/extensions/action_cable/tagged_logger_proxy.rb

Can you tell if the method tag_logger is being called by this particular version of action cable?
There were changes between the Beta and GA versions of Rails 5 where the name of this method changed in Action Cable.

[reidmorrison]

Looks like I removed the wrong method. I put the correct one back, can you please try again against master, or let me know if you need a Gem ASAP.

Thank you,
Reid

[msg7086]

Works nicely. Thank you so much for the quick patch. I can live with github head until you have a new release, so no rush 😃

[harry43]

@reidmorrison I am using good_job gem for background jobs and I am facing the same issue.

NoMethodError: undefined method `current_tags' for nil:NilClass ["good_job-1.3.2/lib/good_job/log_subscriber.rb:198

https://github.com/bensheldon/good_job/blob/2bb47821963f374d122d9d2384193535ae318195/lib/good_job/log_subscriber.rb#L198

Do we have any solution for that as well?

[reidmorrison]

You will need to either remove the good job log subscriber, or monkey patch it in some way. Consider using Rocket Job <https://rocketjob.io> since it has natively adopted Semantic Logger.

…

On Mon, Nov 23, 2020 at 12:53 PM harry43 ***@***.***> wrote: @reidmorrison <https://github.com/reidmorrison> I am using good_job gem for background jobs and I am facing the same issue. NoMethodError: undefined method `current_tags' for nil:NilClass ["good_job-1.3.2/lib/good_job/log_subscriber.rb:198 https://github.com/bensheldon/good_job/blob/main/lib/good_job/log_subscriber.rb Do we have any solution for that as well? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#29 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABD3JCIB7WEWOPRVL33YNLSRKOTHANCNFSM4DBWEHCQ> .

[harry43]

You will need to either remove the good job log subscriber, or monkey patch it in some way. Consider using Rocket Job https://rocketjob.io since it has natively adopted Semantic Logger.
…
On Mon, Nov 23, 2020 at 12:53 PM harry43 @.***> wrote: @reidmorrison https://github.com/reidmorrison I am using good_job gem for background jobs and I am facing the same issue. NoMethodError: undefined method `current_tags' for nil:NilClass ["good_job-1.3.2/lib/good_job/log_subscriber.rb:198 https://github.com/bensheldon/good_job/blob/main/lib/good_job/log_subscriber.rb Do we have any solution for that as well? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#29 (comment)>, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABD3JCIB7WEWOPRVL33YNLSRKOTHANCNFSM4DBWEHCQ .

Thanks for the quick reply. I will definitely look into rocket job.

[adibsaad]

@harry43 I ran into the same issue when using good_job.

The issue is that rails_semantic_logger sets Rails.logger to a new Logger object with no formatter

rails_semantic_logger/lib/rails_semantic_logger/engine.rb

Line 71 in e83a306

SemanticLogger[Rails]

Simple solution is to add a formatter. Put this in an initializer

formatter = ActiveSupport::Logger::SimpleFormatter.new
formatter.extend ActiveSupport::TaggedLogging::Formatter
Rails.logger.formatter = formatter