sending duplicate confirmation emails when using my own after_create callback

Question

sending duplicate confirmation emails when using my own after_create callback

Closed this issue 12 years ago · 3 comments

Hello, I'd like to help debug this, I'm getting two emails sent to my new user when I have my own after_create callback set up for my User model.

When I commented out my after_create method, only one confirmation email was sent, but if I leave it in, two are sent. Here's my log talking about the creation of a user, enqueuing a delayed job, doing my own after_create callback (listing_credit) and then another job is enqueued after listing_credit is created:

18:46:21 thin.1 |   SQL (1.8ms)  INSERT INTO "users" (removing all my user attributes for ease of reading)
18:46:21 thin.1 |   User Exists (0.4ms)  SELECT 1 FROM "users" WHERE ("users"."email" = 'ti3341@zoaxe.com' AND "users"."id" != 603) LIMIT 1
18:46:21 thin.1 |    (0.3ms)  UPDATE "users" SET "phone" = '', "encrypted_password" = '$2a$10$2307dpkG40mXCDI65xgdUuZwhoDnp6g7jtiVhkim3/biL3p79fwvm', "tos" = 't', "confirmation_token" = 'fKKJn9qq4gHonHBNuq6E', "confirmation_sent_at" = '2013-02-12 23:46:21.013395', "created_at" = '2013-02-12 23:46:21.014126', "updated_at" = '2013-02-12 23:46:21.014126', "unconfirmed_email" = 'ti3341@zoaxe.com', "roles" = '---
18:46:21 thin.1 | - normal
18:46:21 thin.1 | ' WHERE "users"."id" = 603
18:46:21 thin.1 |   User Load (0.5ms)  SELECT "users".* FROM "users" WHERE "users"."confirmation_token" = 'c3XujxpV5EByGDiFNJM1' LIMIT 1
18:46:21 thin.1 |    (0.4ms)  UPDATE "users" SET "phone" = '', "encrypted_password" = '$2a$10$2307dpkG40mXCDI65xgdUuZwhoDnp6g7jtiVhkim3/biL3p79fwvm', "tos" = 't', "confirmation_sent_at" = '2013-02-12 23:46:21.022552', "created_at" = '2013-02-12 23:46:21.014126', "updated_at" = '2013-02-12 23:46:21.014126', "unconfirmed_email" = 'ti3341@zoaxe.com', "confirmation_token" = 'c3XujxpV5EByGDiFNJM1', "roles" = '---
18:46:21 thin.1 | - normal
18:46:21 thin.1 | ' WHERE "users"."id" = 603

18:46:21 thin.1 |   SQL (0.7ms)  INSERT INTO "delayed_jobs" ("attempts", "created_at", "failed_at", "handler", "last_error", "locked_at", "locked_by", "priority", "queue", "run_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) RETURNING "id"  [["attempts", 0], ["created_at", Tue, 12 Feb 2013 18:46:21 EST -05:00], ["failed_at", nil], ["handler", "--- !ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:Devise::Async::Backend::DelayedJob {}\nmethod_name: :perform\nargs:\n- :confirmation_instructions\n- User\n- '603'\n- :to: ti3341@zoaxe.com\n"], ["last_error", nil], ["locked_at", nil], ["locked_by", nil], ["priority", 0], ["queue", :mailer], ["run_at", Tue, 12 Feb 2013 18:46:21 EST -05:00], ["updated_at", Tue, 12 Feb 2013 18:46:21 EST -05:00]]
18:46:21 thin.1 |   SystemSetting Load (0.5ms)  SELECT "system_settings".* FROM "system_settings" ORDER BY "system_settings"."id" DESC LIMIT 1
18:46:21 thin.1 |   ListingCredit Load (0.9ms)  SELECT "listing_credits".* FROM "listing_credits" WHERE "listing_credits"."user_id" = 603 LIMIT 1
18:46:21 thin.1 |   ListingCredit Exists (0.5ms)  SELECT 1 FROM "listing_credits" WHERE "listing_credits"."user_id" = 603 LIMIT 1

18:46:21 thin.1 |   SQL (1.1ms)  INSERT INTO "listing_credits" (removing listing_credit attributes for ease of reading)

18:46:21 thin.1 |   SQL (0.7ms)  INSERT INTO "delayed_jobs" ("attempts", "created_at", "failed_at", "handler", "last_error", "locked_at", "locked_by", "priority", "queue", "run_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) RETURNING "id"  [["attempts", 0], ["created_at", Tue, 12 Feb 2013 18:46:21 EST -05:00], ["failed_at", nil], ["handler", "--- !ruby/object:Delayed::PerformableMethod\nobject: !ruby/object:Devise::Async::Backend::DelayedJob {}\nmethod_name: :perform\nargs:\n- :confirmation_instructions\n- User\n- '603'\n- {}\n"], ["last_error", nil], ["locked_at", nil], ["locked_by", nil], ["priority", 0], ["queue", :mailer], ["run_at", Tue, 12 Feb 2013 18:46:21 EST -05:00], ["updated_at", Tue, 12 Feb 2013 18:46:21 EST -05:00]]

my callback that seems to cause it:

  after_create :create_listing_credit

  private

  def create_listing_credit
    # also adding normal role
    add_role!("normal")
    setting = SystemSetting.last 
    setting = SystemSetting.new() if setting.nil?
    if listing_credit.nil?
      listing_credit = ListingCredit.create(:user_id=>self.id,:ticket_credits=>setting.ticket_credits,:group_credits=>setting.group_credits,:refill_at=>Time.now+30.days)
    end
    listing_credit
  end

Answer 1 · 2013-02-13T01:32:12.000Z

I would think it's something to do with https://github.com/mhfs/devise-async/blob/master/lib/devise/async/model.rb - possibly two notifications are being sent to the send_devise_notification method?

def send_devise_notification(notification, opts = {})
        # If the record is dirty we keep pending notifications to be enqueued
        # by the callback and avoid before commit job processing.
        if changed?
          devise_pending_notifications << [ notification, opts ]
        # If the record isn't dirty (aka has already been saved) enqueue right away
        # because the callback has already been triggered.
        else
          Devise::Async::Worker.enqueue(notification, self.class.name, self.id.to_s, opts)
        end
      end

As a temporary fix, I placed my after_create callback method in a custom devise registrations controller in the create method, and took out the after_create callback I had in my user model.

Answer 2 · 2013-02-20T23:35:12.000Z

Did you try to disable devise-async and check if the problem persists with only devise in place. I'd guess it's something in you callback logic that's triggering the devise callbacks twice.

Answer 3 · 2013-03-20T17:55:38.000Z

Closing due to lack of feedback.