Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Setting logger: Rails.logger breaks BroadcastLogger #1236

Open
rgaufman opened this issue Feb 8, 2024 · 5 comments
Open

Setting logger: Rails.logger breaks BroadcastLogger #1236

rgaufman opened this issue Feb 8, 2024 · 5 comments

Comments

@rgaufman
Copy link

rgaufman commented Feb 8, 2024

When I run:

MyJob.perform_later

On Rails 7.1.3 I get this exception:

 NoMethodError:
       undefined method `error' for nil
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/broadcast_logger.rb:134:in `block in error'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/broadcast_logger.rb:231:in `block in dispatch'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/broadcast_logger.rb:231:in `each'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/broadcast_logger.rb:231:in `dispatch'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/broadcast_logger.rb:134:in `error'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/log_subscriber.rb:199:in `log_exception'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/log_subscriber.rb:152:in `rescue in call'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/log_subscriber.rb:149:in `call'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:181:in `block in finish'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:26:in `block in iterate_guarding_exceptions'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:25:in `each'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:25:in `iterate_guarding_exceptions'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:125:in `each'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:180:in `finish'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:262:in `block in finish_with_values'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:26:in `block in iterate_guarding_exceptions'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:25:in `each'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:25:in `iterate_guarding_exceptions'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:261:in `finish_with_values'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/fanout.rb:254:in `finish'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/instrumenter.rb:64:in `instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications.rb:206:in `instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/app/models/good_job/execution.rb:408:in `block (2 levels) in perform'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/lib/good_job/current_thread.rb:106:in `within'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/app/models/good_job/execution.rb:371:in `block in perform'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/app/models/good_job/batch.rb:78:in `within_thread'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/app/models/good_job/execution.rb:562:in `reset_batch_values'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:141:in `run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/app/models/good_job/execution.rb:367:in `perform'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/lib/good_job/adapter.rb:152:in `block in enqueue_at'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/execution_wrapper.rb:88:in `wrap'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/lib/good_job/adapter.rb:142:in `enqueue_at'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/good_job-3.23.0/lib/good_job/adapter.rb:42:in `enqueue'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/enqueuing.rb:97:in `block in enqueue'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/instrumentation.rb:40:in `block in instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications.rb:206:in `block in instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/notifications.rb:206:in `instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/instrumentation.rb:39:in `instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activerecord-7.1.3/lib/active_record/railties/job_runtime.rb:18:in `instrument'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/instrumentation.rb:21:in `block (2 levels) in <module:Instrumentation>'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:130:in `instance_exec'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/tagged_logging.rb:135:in `block in tagged'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/tagged_logging.rb:39:in `tagged'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/tagged_logging.rb:135:in `tagged'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/broadcast_logger.rb:240:in `method_missing'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/logging.rb:25:in `tag_logger'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/logging.rb:14:in `block (2 levels) in <module:Logging>'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:130:in `instance_exec'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activesupport-7.1.3/lib/active_support/callbacks.rb:141:in `run_callbacks'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/enqueuing.rb:93:in `enqueue'
     # /opt/homebrew/lib/ruby/gems/3.3.0/gems/activejob-7.1.3/lib/active_job/enqueuing.rb:60:in `perform_later'
     # ./app/controllers/api/v3/activations_controller.rb:28:in `create'

This works fine if I downgrade back to Rails 7.0.8.

Any ideas?
@bensheldon
Copy link
Owner

bensheldon commented Feb 8, 2024 •
edited

That's strange! I'm having trouble reproducing it. If I go to that line in Rails where the exception is raised, it appears like the logger is nil:

https://github.com/rails/rails/blob/36c1591bcb5e0ee3084759c7f42a706fe5bb7ca7/activesupport/lib/active_support/broadcast_logger.rb#L134

The BroadcastLogger was introduced in Rails v7.1, and GoodJob does hook into it:

good_job/lib/good_job/log_subscriber.rb

Lines 211 to 213 in 131e0cc

@_logger ||= if defined?(ActiveSupport::BroadcastLogger)
ActiveSupport::BroadcastLogger.new(*loggers)
else

Just going logically, I will hypothesize that for some reason GoodJob.logger or Rails.logger is nil. Does that seem like something that's configured in your application?

@rgaufman
Copy link
Author

rgaufman commented Feb 8, 2024

I have this config for good_job, the rest is the default. The only change from not working to working is updating to Rails 7.1:

    config.good_job = {
      preserve_job_records: true,
      cleanup_discarded_jobs: true,
      cleanup_interval_seconds: 60*60,
      cleanup_preserved_jobs_before_seconds_ago: 60*60*8,
      retry_on_unhandled_error: false,
      on_thread_error: ->(exception) { Airbrake.notify(exception) },
      execution_mode: :async,
      queues: goodjob_queues,
      max_threads: goodjob_max_threads, # WARNING: Doesn't actually enforce max_threads!
      max_cache: 5_000, # Number of jobs to keep in memory, 10k = ~20MB
      poll_interval: 1,
      shutdown_timeout: 30,
      enable_cron: true,
      logger: Rails.logger
    }

@bensheldon
Copy link
Owner

Could you try removing the logger: Rails.logger line. That should be duplicative of the default (and maybe the problem).

@rgaufman
Copy link
Author

rgaufman commented Feb 9, 2024

You're right, removing that fixed the issue, thank you!

@rgaufman rgaufman closed this as completed Feb 9, 2024
@bensheldon
Copy link
Owner

Yay! I'm glad removing that line fixed it for you.

I'm going to reopen this because I would like to try to reproduce that and see if I can have it not break because you might not be the only person doing that.

@bensheldon bensheldon reopened this Feb 9, 2024
@bensheldon bensheldon changed the title undefined method `error' for nil with Rails 7.1.3 Setting logger: Rails.logger breaks BroadcastLogger Feb 9, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
GoodJob Backlog v2
Status: Inbox
Milestone
No milestone
Development

No branches or pull requests
2 participants
@bensheldon @rgaufman