I have a form that sends with { remote: true } and an Adopter model that has a uniqueness validator on the email field. Now I have a weird bug in production environment (and I wasn't able to reproduce it in development):
Sometimes if people are creating an Adopter the post request will be sent twice (most of the time everything works fine). When that happens, my Rails app creates two Adopters with the same email. The following is a excerpt from the issue causing requests (I removed boring and private stuff):
Started GET "/" for 123.456.789.012 at 2016-06-25 15:03:37 +0000
Processing by LandingController#index as HTML
request http://ipinfo.io/123.456.789.012
{
"ip": "123.456.789.012",
"hostname": "12345678.dip0.t-ipconnect.de",
"city": "",
"region": "",
"country": "DE",
"loc": "1.0000,1.0000",
"org": "Organistion name"
}
Rendered landing/index.html.slim within layouts/application (1.6ms)
Rendered layouts/application/_head.html.slim (2.0ms)
Rendered layouts/application/_ga.html.slim (0.1ms)
Completed 200 OK in 39ms (Views: 6.8ms | ActiveRecord: 0.0ms)
Started POST "/adopters" for 123.456.789.012 at 2016-06-25 15:05:42 +0000
Processing by AdoptersController#create as JS
Parameters: {"utf8"=>"✓", "name"=>"Mika", "answer"=>{"for"=>"friend", "for_precise"=>"male_friend", "nature"=>"humorous", "interests"=>["technology", "music"]}, "email"=>"nobody@shouldknow.com"}
request http://ipinfo.io/123.456.789.012
{
"ip": "123.456.789.012",
"hostname": "12345678.dip0.t-ipconnect.de",
"city": "",
"region": "",
"country": "DE",
"loc": "1.0000,1.0000",
"org": "Organistion name"
}
Adopter Load (0.7ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "97f32b"]]
CACHE (0.0ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "97f32b"]]
(0.3ms) BEGIN
(0.4ms) SELECT COUNT(*) FROM "adopters" WHERE "adopters"."sign_up_ip" = $1 [["sign_up_ip", "123.456.789.012/32"]]
Adopter Exists (0.9ms) SELECT 1 AS one FROM "adopters" WHERE "adopters"."email" = 'nobody@shouldknow.com' LIMIT 1
Adopter Exists (0.4ms) SELECT 1 AS one FROM "adopters" WHERE "adopters"."referral_code" IS NULL LIMIT 1
Adopter Load (0.4ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "58b7fd"]]
(0.2ms) SELECT COUNT(*) FROM "adopters" WHERE "adopters"."sign_up_ip" = $1 [["sign_up_ip", "89.15.237.123/32"]]
Adopter Exists (0.4ms) SELECT 1 AS one FROM "adopters" WHERE ("adopters"."email" = 'lukas.thorr@web.de' AND "adopters"."id" != 52) LIMIT 1
Adopter Exists (0.3ms) SELECT 1 AS one FROM "adopters" WHERE ("adopters"."referral_code" = '97f32b' AND "adopters"."id" != 52) LIMIT 1
SQL (2.0ms) UPDATE "adopters" SET "referred_count" = $1, "updated_at" = $2 WHERE "adopters"."id" = $3 [["referred_count", 1], ["updated_at", "2016-06-25 15:05:42.492589"], ["id", 52]]
SQL (1.2ms) INSERT INTO "adopters" ("name", "email", "gift_for_person", "gift_for_person_nature", "gift_for_person_interests", "sign_up_ip", "referred_by", "locale", "created_at", "updated_at", "referral_code", "referred_count") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12) RETURNING "id" [["name", "Mika"], ["email", "nobody@shouldknow.com"], ["gift_for_person", "male_friend"], ["gift_for_person_nature", "humorous"], ["gift_for_person_interests", "[\"technology\",\"music\"]"], ["sign_up_ip", "123.456.789.012/32"], ["referred_by", 52], ["locale", "de"], ["created_at", "2016-06-25 15:05:42.484886"], ["updated_at", "2016-06-25 15:05:42.484886"], ["referral_code", "58b7fd"], ["referred_count", 0]]
[ActiveJob] Adopter Load (0.6ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."id" = $1 LIMIT 1 [["id", 54]]
[ActiveJob] [ActionMailer::DeliveryJob] [3f82f6c1-3f4e-4411-a377-2a667d32559f] Performing ActionMailer::DeliveryJob from Inline(mailers) with arguments: "AdopterMailer", "signup_email", "deliver_now", gid://Mycoolsite-prelauncher/Adopter/54
[ActiveJob] [ActionMailer::DeliveryJob] [3f82f6c1-3f4e-4411-a377-2a667d32559f] Rendered adopter_mailer/signup_email.html.slim (3.0ms)
[ActiveJob] [ActionMailer::DeliveryJob] [3f82f6c1-3f4e-4411-a377-2a667d32559f]
AdopterMailer#signup_email: processed outbound mail in 8.1ms
Started POST "/adopters" for 123.456.789.012 at 2016-06-25 15:05:44 +0000
Processing by AdoptersController#create as JS
Parameters: {"utf8"=>"✓", "name"=>"Mika", "answer"=>{"for"=>"friend", "for_precise"=>"male_friend", "nature"=>"humorous", "interests"=>["technology", "music"]}, "email"=>"nobody@shouldknow.com"}
request http://ipinfo.io/123.456.789.012
{
"ip": "123.456.789.012",
"hostname": "12345678.dip0.t-ipconnect.de",
"city": "",
"region": "",
"country": "DE",
"loc": "1.0000,1.0000",
"org": "Organistion name"
}
Adopter Load (1.2ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "97f32b"]]
CACHE (0.0ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "97f32b"]]
(0.2ms) BEGIN
(0.3ms) SELECT COUNT(*) FROM "adopters" WHERE "adopters"."sign_up_ip" = $1 [["sign_up_ip", "123.456.789.012/32"]]
Adopter Exists (0.5ms) SELECT 1 AS one FROM "adopters" WHERE "adopters"."email" = 'nobody@shouldknow.com' LIMIT 1
Adopter Exists (0.3ms) SELECT 1 AS one FROM "adopters" WHERE "adopters"."referral_code" IS NULL LIMIT 1
Adopter Load (0.2ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "860fc4"]]
(0.2ms) SELECT COUNT(*) FROM "adopters" WHERE "adopters"."sign_up_ip" = $1 [["sign_up_ip", "89.15.237.123/32"]]
Adopter Exists (0.4ms) SELECT 1 AS one FROM "adopters" WHERE ("adopters"."email" = 'lukas.thorr@web.de' AND "adopters"."id" != 52) LIMIT 1
Adopter Exists (0.3ms) SELECT 1 AS one FROM "adopters" WHERE ("adopters"."referral_code" = '97f32b' AND "adopters"."id" != 52) LIMIT 1
[ActiveJob] [ActionMailer::DeliveryJob] [3f82f6c1-3f4e-4411-a377-2a667d32559f]
Sent mail to nobody@shouldknow.com (1613.9ms)
[ActiveJob] [ActionMailer::DeliveryJob] [3f82f6c1-3f4e-4411-a377-2a667d32559f] Date: Sat, 25 Jun 2016 15:05:42 +0000
From: Mycoolsite <subscribed@mysite.io>
To: nobody@shouldknow.com
Message-ID: <576e9dc67f160_83f98bcce081c5454@1c50fd29020a.mail>
Subject: Mycoolsite - Deine Anmeldung
Mime-Version: 1.0
Content-Type: text/html;
charset=UTF-8
Content-Transfer-Encoding: quoted-printable
some email content
[ActiveJob] [ActionMailer::DeliveryJob] [3f82f6c1-3f4e-4411-a377-2a667d32559f] Performed ActionMailer::DeliveryJob from Inline(mailers) in 1625.69ms
[ActiveJob] Enqueued ActionMailer::DeliveryJob (Job ID: 3f82f6c1-3f4e-4411-a377-2a667d32559f) to Inline(mailers) with arguments: "AdopterMailer", "signup_email", "deliver_now", gid://Mycoolsite-prelauncher/Adopter/54
(1.3ms) COMMIT
SQL (62.8ms) UPDATE "adopters" SET "referred_count" = $1, "updated_at" = $2 WHERE "adopters"."id" = $3 [["referred_count", 1], ["updated_at", "2016-06-25 15:05:44.074420"], ["id", 52]]
SQL (0.6ms) INSERT INTO "adopters" ("name", "email", "gift_for_person", "gift_for_person_nature", "gift_for_person_interests", "sign_up_ip", "referred_by", "locale", "created_at", "updated_at", "referral_code", "referred_count") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12) RETURNING "id" [["name", "Mika"], ["email", "nobody@shouldknow.com"], ["gift_for_person", "male_friend"], ["gift_for_person_nature", "humorous"], ["gift_for_person_interests", "[\"technology\",\"music\"]"], ["sign_up_ip", "123.456.789.012/32"], ["referred_by", 52], ["locale", "de"], ["created_at", "2016-06-25 15:05:44.068500"], ["updated_at", "2016-06-25 15:05:44.068500"], ["referral_code", "860fc4"], ["referred_count", 0]]
Completed 200 OK in 1716ms (Views: 0.3ms | ActiveRecord: 9.1ms)
[ActiveJob] Adopter Load (4.3ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."id" = $1 LIMIT 1 [["id", 55]]
[ActiveJob] [ActionMailer::DeliveryJob] [d91eebb4-14ce-43e3-845c-6655c293de60] Performing ActionMailer::DeliveryJob from Inline(mailers) with arguments: "AdopterMailer", "signup_email", "deliver_now", gid://Mycoolsite-prelauncher/Adopter/55
[ActiveJob] [ActionMailer::DeliveryJob] [d91eebb4-14ce-43e3-845c-6655c293de60] Rendered adopter_mailer/signup_email.html.slim (1.7ms)
[ActiveJob] [ActionMailer::DeliveryJob] [d91eebb4-14ce-43e3-845c-6655c293de60]
AdopterMailer#signup_email: processed outbound mail in 4.0ms
Started GET "/rank/58b7fd" for 123.456.789.012 at 2016-06-25 15:05:44 +0000
Processing by AdoptersController#refer as HTML
Parameters: {"code"=>"58b7fd"}
request http://ipinfo.io/123.456.789.012
{
"ip": "123.456.789.012",
"hostname": "12345678.dip0.t-ipconnect.de",
"city": "",
"region": "",
"country": "DE",
"loc": "1.0000,1.0000",
"org": "Organistion name"
}
Adopter Load (0.8ms) SELECT "adopters".* FROM "adopters" WHERE "adopters"."referral_code" = $1 LIMIT 1 [["referral_code", "58b7fd"]]
(0.6ms) SELECT COUNT(*) FROM "adopters" WHERE "adopters"."referred_by" = $1 [["referred_by", 54]]
(0.8ms)
SELECT * FROM (
SELECT adopters.id as id, adopters.referred_count as referred_count, row_number() over(order by adopters.referred_count desc) as rn FROM adopters
) t where id = 54
Adopter Load (0.6ms) SELECT "adopters".* FROM "adopters" ORDER BY "adopters"."referred_count" DESC, "adopters"."created_at" ASC LIMIT 15
Rendered adopters/refer.html.slim within layouts/application (7.1ms)
Rendered layouts/application/_head.html.slim (1.9ms)
Rendered layouts/application/_ga.html.slim (0.1ms)
Completed 200 OK in 29ms (Views: 9.0ms | ActiveRecord: 2.8ms)
[ActiveJob] [ActionMailer::DeliveryJob] [d91eebb4-14ce-43e3-845c-6655c293de60]
Sent mail to nobody@shouldknow.com (1356.5ms)
[ActiveJob] [ActionMailer::DeliveryJob] [d91eebb4-14ce-43e3-845c-6655c293de60] Date: Sat, 25 Jun 2016 15:05:44 +0000
From: Mycoolsite <subscribed@mysite.io>
To: nobody@shouldknow.com
Message-ID: <576e9dc8265ef_83f98bc2ae3e4546d8@1c50fd29020a.mail>
Subject: Mycoolsite - Deine Anmeldung
Mime-Version: 1.0
Content-Type: text/html;
charset=UTF-8
Content-Transfer-Encoding: quoted-printable
some email content again
[ActiveJob] [ActionMailer::DeliveryJob] [d91eebb4-14ce-43e3-845c-6655c293de60] Performed ActionMailer::DeliveryJob from Inline(mailers) in 1363.09ms
[ActiveJob] Enqueued ActionMailer::DeliveryJob (Job ID: d91eebb4-14ce-43e3-845c-6655c293de60) to Inline(mailers) with arguments: "AdopterMailer", "signup_email", "deliver_now", gid://Mycoolsite-prelauncher/Adopter/55
(1.1ms) COMMIT
Completed 200 OK in 1491ms (Views: 0.2ms | ActiveRecord: 72.7ms)
This is the Adopter#create action (which is being called twice):
def create
ref_code = cookies[:h_ref]
@adopter = Adopter.new
@adopter.name = params[:name]
@adopter.email = params[:email]
@adopter.gift_for_person = params[:answer][:for_precise] if !params[:answer][:for_precise].blank?
@adopter.gift_for_person = params[:answer][:for] if params[:answer][:for_precise].blank?
@adopter.gift_for_person_nature = params[:answer][:nature]
@adopter.gift_for_person_interests = params[:answer][:interests].to_json
@adopter.sign_up_ip = request.remote_ip
if ref_code && Adopter.find_by(referral_code: ref_code)
@adopter.referrer = Adopter.find_by(referral_code: ref_code)
end
@adopter.locale = I18n.locale
respond_to do |format|
if @adopter.save
cookies[:h_email] = { value: @adopter.email }
#format.html { redirect_to rank_path(code: @adopter.referral_code) }
format.js {
render :js => "window.location = '#{rank_path(code: @adopter.referral_code)}'"
}
else
logger.info("Error saving user with email, #{@adopter.email}")
# redirect_to root_path, alert: 'Something went wrong!'
# format.js { flash[:notice] = @adopter.errors }
format.js { flash[:notice] = @adopter.errors }
end
end
end
This is my Adopter model:
require 'adopters_helper'
class Adopter < ActiveRecord::Base
belongs_to :referrer, class_name: 'Adopter', foreign_key: 'referred_by'
has_many :referrals, class_name: 'Adopter', foreign_key: 'referred_by'
validate :not_more_than_two_adopters_per_ip
validates :email, presence: true, uniqueness: true, format: {
with: /\w+([-+.']\w+)*@\w+([-.]\w+)*\.\w+([-.]\w+)*/i,
message: 'Invalid email format.'
}
validates :referral_code, uniqueness: true
validates :name, :locale, presence: true, allow_blank: false
before_create :create_referral_code
after_create :send_welcome_email
before_create :compute_queue_positions
def rank
row_number_tupel = ActiveRecord::Base.connection.execute("
SELECT * FROM (
SELECT adopters.id as id, adopters.referred_count as referred_count, row_number() over(order by adopters.referred_count desc) as rn FROM adopters
) t where id = #{self.id}
")
row_number_tupel[0]['rn']
end
private
def create_referral_code
self.referral_code = AdoptersHelper.unused_referral_code
end
def not_more_than_two_adopters_per_ip
if !Rails.env.development?
adopter_count_with_current_ip = Adopter.where(sign_up_ip: sign_up_ip).count
if adopter_count_with_current_ip >= 3
errors.add(:sign_up_ip, I18n.t('activerecord.errors.models.adopter.attributes.sign_up_ip.max_ips'))
end
end
end
def send_welcome_email
AdopterMailer.signup_email(self).deliver_later
end
def compute_queue_positions
self.referred_count = 0
if !self.referrer.blank?
self.referrer.update_attributes! referred_count: (self.referrer.referred_count + 1)
end
end
end
So basically there are two issues. First one, that sometimes the Post request is being sent and processed twice. And second one, that if the first one happens, the uniqueness validator fails.
First one: I noticed that users still think they have to double click likes.
Seconds one: No, it does not fail, it is a race condition. Two requests end up at two different instances of the app and both instances check if a similar record already exists, both notice that it does not and therefore both create one. The solution is that you need a unique index on your database to avoid these kind of problems.
Quote from the Rails Guides about ActiveRecord uniqueness validations:
This helper validates that the attribute's value is unique right before the object gets saved. It does not create a uniqueness constraint in the database, so it may happen that two different database connections create two records with the same value for a column that you intend to be unique. To avoid that, you must create a unique index on both columns in your database.