DJ and Ruby upgrade to 2.5.3

[Soundarya]

Hi All,

We upgraded to Ruby 2.5.3 from 2.4.4 with the following gem versions:

delayed_job (4.1.5)

      activesupport (>= 3.0, < 5.3)

delayed_job_active_record (4.1.3)

      activerecord (>= 3.0, < 5.3)

      delayed_job (>= 3.0, < 5)

delayed_job_web (1.4.3)

      activerecord (> 3.0.0)

      delayed_job (> 2.0.3)

      rack-protection (>= 1.5.5)

      sinatra (>= 1.4.4)

We started seeing "SystemStackError: stack level too deep" error immediately after deployment. Sorry for the long stack trace but I figured it would be helpful.

SystemStackError: stack level too deep

  from active_record/attribute_methods/time_zone_conversion.rb:8:in `deserialize'

  from active_model/attribute.rb:165:in `type_cast'

  from active_model/attribute.rb:42:in `value'

  from active_model/attribute_set.rb:48:in `fetch_value'

  from active_record/attribute_methods/read.rb:77:in `_read_attribute'

  from active_record/attribute_methods/read.rb:40:in `__temp__2757e6f51647'

  from delayed/backend/base.rb:142:in `set_default_run_at'

  from active_support/callbacks.rb:426:in `block in make_lambda'

  from active_support/callbacks.rb:198:in `block (2 levels) in halting'

  from active_support/callbacks.rb:606:in `block (2 levels) in default_terminator'

  from active_support/callbacks.rb:605:in `catch'

  from active_support/callbacks.rb:605:in `block in default_terminator'

  from active_support/callbacks.rb:199:in `block in halting'

  from active_support/callbacks.rb:513:in `block in invoke_before'

  from active_support/callbacks.rb:513:in `each'

  from active_support/callbacks.rb:513:in `invoke_before'

  from active_support/callbacks.rb:131:in `run_callbacks'

  from active_support/callbacks.rb:816:in `_run_save_callbacks'

  from active_record/callbacks.rb:342:in `create_or_update'

  from active_record/persistence.rb:273:in `save'

  from active_record/validations.rb:46:in `save'

  from active_record/transactions.rb:310:in `block (2 levels) in save'

  from active_record/transactions.rb:387:in `block in with_transaction_returning_status'

  from active_record/connection_adapters/abstract/database_statements.rb:259:in `block in transaction'

  from active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'

  from monitor.rb:226:in `mon_synchronize'

  from active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'

  from active_record/connection_adapters/abstract/database_statements.rb:259:in `transaction'

  from active_record/transactions.rb:212:in `transaction'

  from active_record/transactions.rb:385:in `with_transaction_returning_status'

  from active_record/transactions.rb:310:in `block in save'

  from active_record/transactions.rb:325:in `rollback_active_record_state!'

  from active_record/transactions.rb:309:in `save'

  from active_record/suppressor.rb:44:in `save'

  from new_relic/agent/instrumentation/active_record_prepend.rb:16:in `block in save'

  from new_relic/agent/transaction.rb:813:in `with_database_metric_name'

  from new_relic/agent.rb:643:in `with_database_metric_name'

  from new_relic/agent/instrumentation/active_record_prepend.rb:15:in `save'

  from delayed/backend/base.rb:19:in `block (2 levels) in enqueue_job'

  from delayed/lifecycle.rb:61:in `block in initialize'

  from delayed/lifecycle.rb:66:in `execute'

  from delayed/lifecycle.rb:40:in `run_callbacks'

  from delayed/backend/base.rb:17:in `block in enqueue_job'

  from delayed/backend/base.rb:16:in `tap'

  from delayed/backend/base.rb:16:in `enqueue_job'

  from delayed/backend/base.rb:12:in `enqueue'

  from active_job/queue_adapters/delayed_job_adapter.rb:19:in `enqueue'

  from active_job/enqueuing.rb:53:in `block in enqueue'

  from active_support/callbacks.rb:109:in `block in run_callbacks'

  from new_relic/agent/instrumentation/active_job.rb:61:in `block in run_in_trace'

  from new_relic/agent/method_tracer.rb:74:in `block in trace_execution_scoped'

  from new_relic/agent/method_tracer_helpers.rb:30:in `trace_execution_scoped'

  from new_relic/agent/method_tracer.rb:72:in `trace_execution_scoped'

  from new_relic/agent/instrumentation/active_job.rb:60:in `run_in_trace'

  from new_relic/agent/instrumentation/active_job.rb:38:in `enqueue'

  from new_relic/agent/instrumentation/active_job.rb:19:in `block (4 levels) in <top (required)>'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from active_job/logging.rb:17:in `block (3 levels) in <module:Logging>'

  from active_job/logging.rb:46:in `block in tag_logger'

  from active_support/tagged_logging.rb:71:in `block in tagged'

  from active_support/tagged_logging.rb:28:in `tagged'

  from active_support/tagged_logging.rb:71:in `tagged'

  from active_job/logging.rb:46:in `tag_logger'

  from active_job/logging.rb:16:in `block (2 levels) in <module:Logging>'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from active_support/callbacks.rb:136:in `run_callbacks'

  from active_job/enqueuing.rb:49:in `enqueue'

  from active_job/enqueuing.rb:20:in `perform_later'

  from app/jobs/polling_job.rb:9:in `block (2 levels) in perform'

  from app/jobs/polling_job.rb:8:in `each'

  from app/jobs/polling_job.rb:8:in `block in perform'

  from app/models/connection.rb:30:in `with_open'

  from app/jobs/polling_job.rb:7:in `perform'

  from active_job/execution.rb:39:in `block in perform_now'

  from active_support/callbacks.rb:109:in `block in run_callbacks'

  from raven/integrations/rails/active_job.rb:18:in `capture_and_reraise_with_sentry'

  from raven/integrations/rails/active_job.rb:12:in `block (2 levels) in included'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from new_relic/agent/instrumentation/active_job.rb:53:in `perform'

  from new_relic/agent/instrumentation/active_job.rb:23:in `block (4 levels) in <top (required)>'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from i18n.rb:297:in `with_locale'

  from active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from active_job/logging.rb:26:in `block (4 levels) in <module:Logging>'

  from active_support/notifications.rb:168:in `block in instrument'

  from active_support/notifications/instrumenter.rb:23:in `instrument'

  from active_support/notifications.rb:168:in `instrument'

  from active_job/logging.rb:25:in `block (3 levels) in <module:Logging>'

  from active_job/logging.rb:46:in `block in tag_logger'

  from active_support/tagged_logging.rb:71:in `block in tagged'

  from active_support/tagged_logging.rb:28:in `tagged'

  from active_support/tagged_logging.rb:71:in `tagged'

  from active_job/logging.rb:46:in `tag_logger'

  from active_job/logging.rb:22:in `block (2 levels) in <module:Logging>'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from active_support/callbacks.rb:136:in `run_callbacks'

  from active_job/execution.rb:38:in `perform_now'

  from active_job/execution.rb:24:in `block in execute'

  from active_support/callbacks.rb:109:in `block in run_callbacks'

  from active_job/railtie.rb:28:in `block (4 levels) in <class:Railtie>'

  from active_support/execution_wrapper.rb:87:in `wrap'

  from active_support/reloader.rb:73:in `block in wrap'

  from active_support/execution_wrapper.rb:87:in `wrap'

  from active_support/reloader.rb:72:in `wrap'

  from active_job/railtie.rb:27:in `block (3 levels) in <class:Railtie>'

  from active_support/callbacks.rb:118:in `instance_exec'

  from active_support/callbacks.rb:118:in `block in run_callbacks'

  from active_support/callbacks.rb:136:in `run_callbacks'

  from active_job/execution.rb:22:in `execute'

  from active_job/queue_adapters/delayed_job_adapter.rb:42:in `perform'

  from delayed/backend/base.rb:81:in `block in invoke_job'

  from raven/integrations/delayed_job.rb:10:in `block (2 levels) in <class:Raven>'

  from delayed/lifecycle.rb:79:in `block (2 levels) in add'

  from delayed/lifecycle.rb:61:in `block in initialize'

  from delayed/lifecycle.rb:79:in `block in add'

  from delayed/lifecycle.rb:66:in `execute'

  from delayed/lifecycle.rb:40:in `run_callbacks'

  from delayed/backend/base.rb:78:in `invoke_job'

  from new_relic/agent/instrumentation/delayed_job_instrumentation.rb:129:in `block in invoke_job'

  from new_relic/agent/instrumentation/controller_instrumentation.rb:376:in `perform_action_with_newrelic_trace'

  from new_relic/agent/instrumentation/delayed_job_instrumentation.rb:128:in `invoke_job'

  from delayed/worker.rb:230:in `block (2 levels) in run'

  from timeout.rb:93:in `block in timeout'

  from timeout.rb:103:in `timeout'

  from delayed/worker.rb:230:in `block in run'

  from benchmark.rb:308:in `realtime'

  from delayed/worker.rb:229:in `run'

  from delayed/worker.rb:312:in `block in reserve_and_run_one_job'

  from delayed/lifecycle.rb:61:in `block in initialize'

  from delayed/lifecycle.rb:66:in `execute'

  from delayed/lifecycle.rb:40:in `run_callbacks'

  from delayed/worker.rb:312:in `reserve_and_run_one_job'

  from delayed/worker.rb:213:in `block in work_off'

  from delayed/worker.rb:212:in `times'

  from delayed/worker.rb:212:in `work_off'

  from delayed/worker.rb:175:in `block (4 levels) in start'

  from benchmark.rb:308:in `realtime'

  from delayed/worker.rb:174:in `block (3 levels) in start'

  from delayed/lifecycle.rb:61:in `block in initialize'

  from delayed/lifecycle.rb:66:in `execute'

  from delayed/lifecycle.rb:40:in `run_callbacks'

  from delayed/worker.rb:173:in `block (2 levels) in start'

  from delayed/worker.rb:172:in `loop'

  from delayed/worker.rb:172:in `block in start'

  from delayed/plugins/clear_locks.rb:7:in `block (2 levels) in <class:ClearLocks>'

  from delayed/lifecycle.rb:79:in `block (2 levels) in add'

  from delayed/lifecycle.rb:61:in `block in initialize'

  from delayed/lifecycle.rb:79:in `block in add'

  from delayed/lifecycle.rb:66:in `execute'

  from delayed/lifecycle.rb:40:in `run_callbacks'

  from delayed/worker.rb:171:in `start'

  from delayed/tasks.rb:9:in `block (2 levels) in <top (required)>'

  from rake/task.rb:273:in `block in execute'

  from rake/task.rb:273:in `each'

  from rake/task.rb:273:in `execute'

  from rake/task.rb:214:in `block in invoke_with_call_chain'

  from monitor.rb:226:in `mon_synchronize'

  from rake/task.rb:194:in `invoke_with_call_chain'

  from rake/task.rb:183:in `invoke'

  from rake/application.rb:160:in `invoke_task'

  from rake/application.rb:116:in `block (2 levels) in top_level'

  from rake/application.rb:116:in `each'

  from rake/application.rb:116:in `block in top_level'

  from rake/application.rb:125:in `run_with_threads'

  from rake/application.rb:110:in `top_level'

  from rake/application.rb:83:in `block in run'

  from rake/application.rb:186:in `standard_exception_handling'

  from rake/application.rb:80:in `run'

  from /gems/gems/rake-12.3.2/exe/rake:27:in `<top (required)>'

  from /gems/bin/rake:23:in `load'

  from /gems/bin/rake:23:in `<top (required)>'

  from bundler/cli/exec.rb:74:in `load'

  from bundler/cli/exec.rb:74:in `kernel_load'

  from bundler/cli/exec.rb:28:in `run'

  from bundler/cli.rb:463:in `exec'

  from bundler/vendor/thor/lib/thor/command.rb:27:in `run'

  from bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'

  from bundler/vendor/thor/lib/thor.rb:387:in `dispatch'

  from bundler/cli.rb:27:in `dispatch'

  from bundler/vendor/thor/lib/thor/base.rb:466:in `start'

  from bundler/cli.rb:18:in `start'

  from /root/.rbenv/versions/2.5.3/bin/bundle:30:in `block in <main>'

  from bundler/friendly_errors.rb:124:in `with_friendly_errors'

  from /root/.rbenv/versions/2.5.3/bin/bundle:22:in `<main>'

The line of code that's causing the error is:  

  NotifyJob.perform_later("Received file: #{file.basename}")

The classes are defined as follows:

  class NotifyJob < ApplicationJob

  ....

  end

  class ApplicationJob < ActiveJob::Base

  end

Would really appreciate any help or tips. Thank you!

-Soundarya

[David Genord II]

That is a failure buried within a normal ActiveRecord save operation. My suspicion is that something in your app is not autoloading properly after the upgrade. Even in production DJ does not eager load the app files because rails prevents rake tasks from eager loading. You could test this by disabling eager loading and load up a console to try queuing that job.

David Genord II

--

---
You received this message because you are subscribed to the Google Groups "delayed_job" group.
To unsubscribe from this group and stop receiving emails from it, send an email to delayed_job...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Soundarya]

Thank you! I kind of understand but not fully. Sorry, how will disabling eager loading help?

On Tuesday, April 2, 2019 at 2:03:07 PM UTC-7, albus522 wrote:

That is a failure buried within a normal ActiveRecord save operation. My suspicion is that something in your app is not autoloading properly after the upgrade. Even in production DJ does not eager load the app files because rails prevents rake tasks from eager loading. You could test this by disabling eager loading and load up a console to try queuing that job.

David Genord II

To unsubscribe from this group and stop receiving emails from it, send an email to delay...@googlegroups.com.

[David Genord II]

It will tell you if the failure is related to an autoloading loop failure.

David

To unsubscribe from this group and stop receiving emails from it, send an email to delayed_job...@googlegroups.com.

[Soundarya]

Ok thanks, eager loading is disabled in development mode. In config/environments/development.rb:

   config.eager_load = false

I'm able to enqueue a DelayedJob successfully from my local environment.

  

On Tuesday, April 2, 2019 at 5:23:01 PM UTC-7, albus522 wrote:

It will tell you if the failure is related to an autoloading loop failure.

David