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.

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

NameError uninitialized constant X, but works several minutes later on retry #276

Open
kaka-ruto opened this issue Aug 8, 2024 · 15 comments

Comments

@kaka-ruto
Copy link

kaka-ruto commented Aug 8, 2024

I have a NewsletterMailer class inside the mailers directory

That is being called in one of the controllers this way

          if @subscriber.save
            NewsletterMailer.with(email: @subscriber.email).welcome_email.deliver_later
          end

When the subscriber is created, the job is scheduled, except I get an error with the following logs

NameError uninitialized constant NewsletterMailer

/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/inflector/methods.rb:290:in `constantize'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/core_ext/string/inflections.rb:74:in `constantize'
/usr/local/bundle/ruby/3.3.0/gems/actionmailer-7.1.3.4/lib/action_mailer/mail_delivery_job.rb:36:in `mailer_class'
/usr/local/bundle/ruby/3.3.0/gems/actionmailer-7.1.3.4/lib/action_mailer/mail_delivery_job.rb:41:in `handle_exception_with_mailer_class'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/rescuable.rb:94:in `call'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/rescuable.rb:94:in `rescue_with_handler'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/rescuable.rb:167:in `rescue_with_handler'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:54:in `rescue in perform_now'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:46:in `perform_now'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:26:in `block in perform_now'
/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/railties/job_runtime.rb:13:in `block in instrument'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:40:in `block in instrument'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `block in instrument'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `instrument'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:39:in `instrument'
/usr/local/bundle/ruby/3.3.0/gems/activerecord-7.1.3.4/lib/active_record/railties/job_runtime.rb:11:in `instrument'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:26:in `perform_now'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/logging.rb:18:in `block in perform_now'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:135:in `block in tagged'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:39:in `tagged'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:135:in `tagged'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/broadcast_logger.rb:240:in `method_missing'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/logging.rb:25:in `tag_logger'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/logging.rb:18:in `perform_now'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:30:in `block in execute'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/railtie.rb:67:in `block (4 levels) in <class:Railtie>'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:77:in `block in wrap'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:88:in `wrap'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:74:in `wrap'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/railtie.rb:66:in `block (3 levels) in <class:Railtie>'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:28:in `execute'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/app/models/solid_queue/claimed_execution.rb:67:in `execute'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/app/models/solid_queue/claimed_execution.rb:41:in `perform'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/lib/solid_queue/pool.rb:23:in `block (2 levels) in post'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/lib/solid_queue/app_executor.rb:7:in `wrap_in_app_executor'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/lib/solid_queue/pool.rb:22:in `block in post'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/future.rb:55:in `block in execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'
<internal:kernel>:187:in `loop'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'

This is the raw data

{
  "id": 27,
  "queue_name": "autohaven_staging_default",
  "class_name": "ActionMailer::MailDeliveryJob",
  "arguments": {
    "job_class": "ActionMailer::MailDeliveryJob",
    "provider_job_id": null,
    "queue_name": "autohaven_staging_default",
    "priority": null,
    "arguments": [
      "NewsletterMailer",
      "welcome_email",
      "deliver_now",
      {
        "params": {
          "email": "example@autohaven.io",
          "_aj_symbol_keys": [
            "email"
          ]
        },
        "args": [

        ],
        "_aj_ruby2_keywords": [
          "params",
          "args"
        ]
      }
    ],
    "executions": 0,
    "exception_executions": {
    },
    "locale": "en",
    "timezone": "Edinburgh",
    "enqueued_at": "2024-08-08T10:25:20.098990852Z",
    "scheduled_at": "2024-08-08T10:25:20.098570239Z"
  },
  "priority": 0,
  "active_job_id": "35c5d282-c59c-4221-a3e1-1c71dfad99f3",
  "scheduled_at": "2024-08-08T10:25:20.098Z",
  "finished_at": null,
  "concurrency_key": null,
  "created_at": "2024-08-08T10:25:20.100Z",
  "updated_at": "2024-08-08T10:25:20.100Z"
}

Here's the weird thing, when I retry the job a couple of minutes later on Mission Control, about more than 10 minutes later, it works and the jobs succeeds! The email is sent without error.

And using deliver_now instead of deliver_later works well

Also, this error does not occur in development

I am using solid_queue version 0.4.1 with the default configuration, Rails 7.1.3.4, Ruby 3.3.4

@kaka-ruto kaka-ruto changed the title NameError uninitialised content X, but works several minutes later on retry NameError uninitialized constant X, but works several minutes later on retry Aug 8, 2024
@kaka-ruto
Copy link
Author

@rosa
Copy link
Member

rosa commented Aug 12, 2024

Hey @kaka-ruto, thanks for this. I'm quite puzzled about why this could happen. We don't do anything special with the class, not even try to instantiate it... we just pass the serialized data over to Active Job, where it's deserialized and instantiated. It's really strange.

What is the exact path to the file that defines NewsletterMailer?

@kaka-ruto
Copy link
Author

Thanks for having a look @rosa

I found it very strange too. The NewsletterMailer is in app/mailers/newsletter_mailer.rb

To just be sure the issue was not in the mailer, I decided to first call a job that will the call the mailer.

I placed the job in app/jobs/newsletter_subscribers/send_welcome_email_job.rb with the following code

class NewsletterSubscribers::SendWelcomeEmailJob < ApplicationJob
  queue_as :real_time

  def perform(email)
    NewsletterMailer.with(email: email).welcome_email.deliver_later
  end
end

And now the error that I get is NameError uninitialized constant NewsletterSubscribers, with the same stacktrace.

However, when I use deliver_now instead of deliver_later in the same job class above, it works!

It appears to me that when the worker is running, it has not yet loaded my classes, which is strange.

I thought it was a zeitwerk issue related to some deprecations that came into effect in rails 7.1 but I cannot seem to find any in my usage. Very strange.

@kaka-ruto
Copy link
Author

Update: Enqueueing of the job works well, but when the worker tries to execute/run the job, it cannot find the class!

However, when I added this on an initializer, requiring the job class, it works!

I cannot figure out why this is happening. Any ideas?

Rails.application.config.to_prepare do
    require Rails.root.join("app/jobs/newsletter_subscribers/send_welcome_email_job.rb")
end

@rosa
Copy link
Member

rosa commented Aug 23, 2024

Huh... silly question.. do you have NewsletterSubscribers defined anywhere (as a module or class)? That is, not just as NewsletterSubscribers::SendWelcomeEmailJob, but on its own.

@rosa
Copy link
Member

rosa commented Sep 2, 2024

Hey @kaka-ruto, did you make any progress on this one at all? Is the error still happening?

@tmimura39
Copy link
Contributor

This may be due to the fact that SolidQueue was originally started by a Rake Task

Rake Task is not eager_load by default.
https://guides.rubyonrails.org/autoloading_and_reloading_constants.html#eager-loading

However, if you start SolidQueue with bin/jobs released in v0.7.0, it will be eager_load.

If you have difficulty updating SolidQueue, you can set config.rake_eager_load = true so that it is eager_loaded.
https://guides.rubyonrails.org/configuring.html#config-rake-eager-load

Sorry if this is irrelevant to the case.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

@tmimura39, that's a great theory! It seems it came up in the forum thread, and the thing is that even if eager loading is disabled, the class should be loaded automatically by Zeitwerk 🤔 It's super weird!

@tmimura39
Copy link
Contributor

In fact, one of the Rails products I know of that uses SolidQueue has a problem where constants cannot be referenced and errors “sometimes” occur.
It is frustrating that we have not been able to establish a reliable reproduction procedure and cannot report it in an appropriate form.
We have not yet confirmed whether this issue can be resolved by eager_load, and will report back as soon as we know something.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

Ohhh, interesting! Yes, it'd be quite useful to know that, and if bin/jobs also helps there 🤔

@kaka-ruto
Copy link
Author

Hi @rosa ! It was still happening when I last tested two weeks ago. I then switched to using the :async adapter on staging for the time being. I just upgraded solid queue to v 0.8 on development so I should be testing on staging in a few days. Will report back 🤞

@rosa
Copy link
Member

rosa commented Sep 9, 2024

Thank you! Could you also let me know what is the exact path to the file that defines NewsletterMailer?

@kaka-ruto
Copy link
Author

Hi Rosa, I've now merged to staging and unfortunately the error persisted, although it's now more like at a 50-50 chance, failing a bit, working a bit.

I also moved things bit, so this is the new structure:

I have app/controllers/admin/newsletter_issue/tastes_controller.rb that looks like this

module Admin
  class NewsletterIssue::TastesController < Admin::ApplicationController
    def create
      newsletter_issue = ::NewsletterIssue.find(params[:newsletter_issue_id])
      ::NewsletterIssues::TasteJob.perform_later(newsletter_issue:, test_email: current_user.email)
      redirect_to admin_newsletter_issue_path(newsletter_issue), notice: "Hmmmm, tastes good?"
    end
  end
end

The bone of contention is this line ::NewsletterIssues::TasteJob.perform_later(newsletter_issue:, test_email: current_user.email), and it doesn't matter whether I have the namespace :: or not

That file is in app/jobs/newsletter_issues/taste_job.rb and it looks like this:

class NewsletterIssues::TasteJob < ApplicationJob
  queue_as :background

  def perform(**args)
    newsletter_issue = args[:newsletter_issue]
    test_email = args[:test_email]

    newsletter_issue.taste!(test_email: test_email)
  end
end

A few images from a few minutes ago as I was testing

Screenshot 2024-09-09 at 22 50 13 Screenshot 2024-09-09 at 22 50 43 Screenshot 2024-09-09 at 22 51 31

The error is still NameError : uninitialized constant NewsletterIssues with the trace

/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/inflector/methods.rb:290:in `constantize'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/core_ext/string/inflections.rb:74:in `constantize'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/core.rb:65:in `deserialize'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:29:in `block in execute'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/railtie.rb:67:in `block (4 levels) in <class:Railtie>'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:77:in `block in wrap'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:88:in `wrap'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:74:in `wrap'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/railtie.rb:66:in `block (3 levels) in <class:Railtie>'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
/usr/local/bundle/ruby/3.3.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:28:in `execute'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/app/models/solid_queue/claimed_execution.rb:67:in `execute'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/app/models/solid_queue/claimed_execution.rb:41:in `perform'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/lib/solid_queue/pool.rb:23:in `block (2 levels) in post'
/usr/local/bundle/ruby/3.3.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/lib/solid_queue/app_executor.rb:7:in `wrap_in_app_executor'
/usr/local/bundle/ruby/3.3.0/gems/solid_queue-0.3.1/lib/solid_queue/pool.rb:22:in `block in post'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/future.rb:55:in `block in execute'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'
<internal:kernel>:187:in `loop'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'
/usr/local/bundle/ruby/3.3.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'

And the raw data

{
  "id": 205,
  "queue_name": "staging_background",
  "class_name": "NewsletterIssues::TasteJob",
  "arguments": {
    "job_class": "NewsletterIssues::TasteJob",
    "job_id": "e787fa62-7735-4406-b2da-0252a29bca54",
    "provider_job_id": null,
    "queue_name": "staging_background",
    "priority": null,
    "arguments": [
      {
        "newsletter_issue": {
          "_aj_globalid": "gid://autohaven/NewsletterIssue/2"
        },
        "test_email": "some email",
        "_aj_ruby2_keywords": [
          "newsletter_issue",
          "test_email"
        ]
      }
    ],
    "executions": 0,
    "exception_executions": {
    },
    "locale": "en",
    "timezone": "UTC",
    "enqueued_at": "2024-09-09T21:49:03.697620101Z",
    "scheduled_at": "2024-09-09T21:49:03.696948969Z"
  },
  "priority": 0,
  "active_job_id": "e787fa62-7735-4406-b2da-0252a29bca54",
  "scheduled_at": "2024-09-09T21:49:03.696Z",
  "finished_at": null,
  "concurrency_key": null,
  "created_at": "2024-09-09T21:49:03.699Z",
  "updated_at": "2024-09-09T21:49:03.699Z"
}

I haven't merged version 0.8.2 of Solid queue to prod yet but v 0.4.1 is working well with all background jobs with this one, so I am not sure if it could be an issue with my staging env as well? Though I tried to replicate both as much as possible

@tmimura39
Copy link
Contributor

Sorry for interrupting.

After starting SolidQueue with the following settings, the constant reference error no longer occurs (SolidQueue version is v0.3.4, by the way).

config.rake_eager_load = true

My problem still seemed to be solved by eager_load.
I don't know if this is equivalent to the problem that kaka-ruto is having, but for your information.

@rosa
Copy link
Member

rosa commented Sep 10, 2024

Ooh, @tmimura39, that's super helpful and great to know! Thank you so much 🙏 🙏 ❤️
This makes me think it'll also go away if using bin/jobs, in your case at least.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants