search

bensheldon / good_job

Multithreaded, Postgres-based, Active Job backend for Ruby on Rails.
https://goodjob-demo.herokuapp.com/
MIT License
2.65k stars 195 forks source link

Setting `logger: Rails.logger` breaks BroadcastLogger #1236

Open rgaufman opened 7 months ago

rgaufman commented 7 months ago

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 commented 7 months ago

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:

https://github.com/bensheldon/good_job/blob/131e0cc8cfca183b736d5bdab1e348a8801cea21/lib/good_job/log_subscriber.rb#L211-L213

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 commented 7 months ago

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 commented 7 months ago

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

rgaufman commented 7 months ago

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

bensheldon commented 7 months ago

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.