Why is one role duplicated for a user?

[afuno]

I created a Rails 5.2.3 application. Next, I added Devise and Rolify.

In the application, I need to automatically assign a role to new users. For this, I wrote the following code (BTW, the similar code is in your documentation):

# ...
after_create :assign_default_role
# ...
def assign_default_role
  return if is_manager?

  Rails.logger.debug 'LOG START'
  add_role :manager
  Rails.logger.debug 'LOG END'
end

All User model code:

class User < ApplicationRecord
  devise :database_authenticatable,
         :registerable,
         :confirmable,
         :lockable,
         :recoverable,
         :rememberable,
         :validatable,
         :trackable

  rolify

  after_create :assign_default_role

  has_many :users_roles
  has_many :roles,
           through: :users_roles,
           dependent: :destroy

  private

  def assign_default_role
    return if is_manager?

    Rails.logger.debug 'LOG START'
    add_role :manager
    Rails.logger.debug 'LOG END'
  end
end

Next, I fill out the Devise registration form and send it:

16:16:04 web.1       | Started POST "/users" for ::1 at 2019-06-11 16:16:04 +0300
16:16:04 web.1       | Processing by Devise::RegistrationsController#create as HTML
16:16:04 web.1       |   Parameters: {"utf8"=>"✓", "authenticity_token"=>"StHyPxZJMuxAGvqkKgho7UgFVQUWPybG7kEnWbv8Wh08NcbNDcxwvLVdudtIysY4udlxba4b7lz5V3HktlBsEA==", "user"=>{"email"=>"my@email.com", "password"=>"[FILTERED]", "password_confirmation"=>"[FILTERED]"}, "commit"=>"Send"}
16:16:04 web.1       |    (0.2ms)  BEGIN
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
16:16:04 web.1       |   User Exists (1.2ms)  SELECT  1 AS one FROM "users" WHERE "users"."email" = $1 LIMIT $2  [["email", "my@email.com"], ["LIMIT", 1]]
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
16:16:04 web.1       |   User Create (0.7ms)  INSERT INTO "users" ("email", "encrypted_password", "confirmation_token", "confirmation_sent_at", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id"  [["email", "my@email.com"], ["encrypted_password", "$2a$11$0O9d2G9w10GBwkiXYAAXuOedRfnG/SXm7Ndr2DxcQrblXV6UL5GQe"], ["confirmation_token", "q_eh96JRWpjByAVr8fk7"], ["confirmation_sent_at", "2019-06-11 13:16:04.783969"], ["created_at", "2019-06-11 13:16:04.783765"], ["updated_at", "2019-06-11 13:16:04.783765"]]
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
16:16:04 web.1       |   Role Exists (0.8ms)  SELECT  1 AS one FROM "roles" WHERE "roles"."name" = $1 LIMIT $2  [["name", "manager"], ["LIMIT", 1]]
16:16:04 web.1       |   ↳ app/models/user.rb:58
16:16:04 web.1       |   Role Load (2.1ms)  SELECT "roles".* FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND (((roles.name = 'manager') AND (roles.resource_type IS NULL) AND (roles.resource_id IS NULL)))  [["user_id", 9]]
16:16:04 web.1       |   ↳ app/models/user.rb:58
16:16:04 web.1       | LOG START
16:16:04 web.1       |   Role Load (0.4ms)  SELECT  "roles".* FROM "roles" WHERE "roles"."name" = $1 AND "roles"."resource_type" IS NULL AND "roles"."resource_id" IS NULL ORDER BY "roles"."id" ASC LIMIT $2  [["name", "manager"], ["LIMIT", 1]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   Role Create (0.5ms)  INSERT INTO "roles" ("name", "created_at", "updated_at") VALUES ($1, $2, $3) RETURNING "id"  [["name", "manager"], ["created_at", "2019-06-11 13:16:04.831979"], ["updated_at", "2019-06-11 13:16:04.831979"]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   Role Exists (0.5ms)  SELECT  1 AS one FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1 AND "roles"."id" = $2 LIMIT $3  [["user_id", 9], ["id", 7], ["LIMIT", 1]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   Role Exists (0.3ms)  SELECT  1 AS one FROM "roles" WHERE "roles"."name" = $1 LIMIT $2  [["name", "manager"], ["LIMIT", 1]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |    (0.4ms)  SELECT "roles"."id" FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1  [["user_id", 9]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   Role Load (0.2ms)  SELECT "roles".* FROM "roles" WHERE "roles"."id" = $1  [["id", 7]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   Role Load (0.5ms)  SELECT "roles".* FROM "roles" INNER JOIN "users_roles" ON "roles"."id" = "users_roles"."role_id" WHERE "users_roles"."user_id" = $1  [["user_id", 9]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   UsersRole Create (0.4ms)  INSERT INTO "users_roles" ("user_id", "role_id") VALUES ($1, $2)  [["user_id", 9], ["role_id", 7]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       | LOG END
16:16:04 web.1       |   UsersRole Create (0.2ms)  INSERT INTO "users_roles" ("user_id", "role_id") VALUES ($1, $2)  [["user_id", 9], ["role_id", 7]]
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
16:16:04 web.1       |    (0.5ms)  COMMIT
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
16:16:05 web.1       |   Rendering devise/mailer/confirmation_instructions.html.slim
16:16:05 web.1       |   Rendered devise/mailer/confirmation_instructions.html.slim (6.0ms)
16:16:05 web.1       | Devise::Mailer#confirmation_instructions: processed outbound mail in 65.7ms
16:16:05 web.1       | Sent mail to my@email.com (17.7ms)
16:16:05 web.1       | Date: Tue, 11 Jun 2019 16:16:05 +0300
16:16:05 web.1       | From: noreply@email.com
16:16:05 web.1       | Reply-To: noreply@email.com
16:16:05 web.1       | To: my@email.com
16:16:05 web.1       | Message-ID: <5cffa9951a5c3_21d63fd656c1e85c953ef@MacBook.local.mail>
16:16:05 web.1       | Subject: =?UTF-8?Q?=D0=98=D0=BD=D1=81=D1=82=D1=80=D1=83=D0=BA=D1=86=D0=B8=D0=B8?=
16:16:05 web.1       |  =?UTF-8?Q?_=D0=BF=D0=BE?=
16:16:05 web.1       |  =?UTF-8?Q?_=D0=BF=D0=BE=D0=B4=D1=82=D0=B2=D0=B5=D1=80=D0=B6=D0=B4=D0=B5=D0=BD=D0=B8=D1=8E?=
16:16:05 web.1       |  =?UTF-8?Q?_=D1=83=D1=87=D1=91=D1=82=D0=BD=D0=BE=D0=B9?=
16:16:05 web.1       |  =?UTF-8?Q?_=D0=B7=D0=B0=D0=BF=D0=B8=D1=81=D0=B8.?=
16:16:05 web.1       | Mime-Version: 1.0
16:16:05 web.1       | Content-Type: text/html;
16:16:05 web.1       |  charset=UTF-8
16:16:05 web.1       | Content-Transfer-Encoding: 7bit
16:16:05 web.1       |
16:16:05 web.1       | <p>Welcome my@email.com!</p><p>You can confirm your account email through the link below:</p><p><a href="http://localhost:3120/users/confirmation?confirmation_token=q_eh96JRWpjByAVr8fk7">Confirm my account</a></p>
16:16:05 web.1       | Redirected to http://localhost:3120/
16:16:05 web.1       | Completed 302 Found in 508ms (ActiveRecord: 15.9ms)
16:16:05 web.1       |
16:16:05 web.1       |
16:16:05 web.1       | Started GET "/" for ::1 at 2019-06-11 16:16:05 +0300
16:16:05 web.1       | Processing by Public::HomeController#index as HTML
16:16:05 web.1       |   Rendering public/home/index.html.slim within layouts/public/main
16:16:05 web.1       |   Rendered public/home/index.html.slim within layouts/public/main (16.4ms)
16:16:05 web.1       | Completed 200 OK in 94ms (Views: 90.6ms | ActiveRecord: 0.0ms)
16:16:05 web.1       |
16:16:05 web.1       |

In the log you need to pay attention to the LOG END. Before and after it you can see these lines:

UsersRole Create (0.4ms)  INSERT INTO "users_roles" ("user_id", "role_id") VALUES ($1, $2)  [["user_id", 9], ["role_id", 7]]

UsersRole Create (0.2ms)  INSERT INTO "users_roles" ("user_id", "role_id") VALUES ($1, $2)  [["user_id", 9], ["role_id", 7]]

Creating a connection comes from the same place:

app/models/user.rb:61

Moreover, the second creation is called before the LOG END, but actually occurs after the LOG END:

16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       |   UsersRole Create (0.4ms)  INSERT INTO "users_roles" ("user_id", "role_id") VALUES ($1, $2)  [["user_id", 9], ["role_id", 7]]
16:16:04 web.1       |   ↳ app/models/user.rb:61
16:16:04 web.1       | LOG END
16:16:04 web.1       |   UsersRole Create (0.2ms)  INSERT INTO "users_roles" ("user_id", "role_id") VALUES ($1, $2)  [["user_id", 9], ["role_id", 7]]
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98
16:16:04 web.1       |    (0.5ms)  COMMIT
16:16:04 web.1       |   ↳ /Users/afuno/.rbenv/versions/2.6.3/lib/ruby/gems/2.6.0/gems/activerecord-5.2.3/lib/active_record/log_subscriber.rb:98

Why is this happening?

If I delete this line, no roles will be created and linked:

add_role :manager

[afuno]

I also want to add that if I create a user without roles, and then manually write in the console this:

User.first.add_role(:manager)

Then everything will be fine. One role and one relationship will be created.

[afuno]

What the hell guys... 😀 Why did this fix my problem?

class User < ApplicationRecord
  devise :database_authenticatable,
         :registerable,
         :confirmable,
         :lockable,
         :recoverable,
         :rememberable,
         :validatable,
         :trackable

  has_many :users_roles
  has_many :roles,
           through: :users_roles,
           dependent: :destroy

  rolify

  after_create :assign_default_role

  private

  def assign_default_role
    return if is_manager?

    Rails.logger.debug 'LOG START'
    add_role :manager
    Rails.logger.debug 'LOG END'
  end
end

[jerome-diver]

I think you can remove

has_many :users_roles 
has_many :roles, through: :users_roles 

and just hold rolify (at start), because it will do the job. roles has_many users through users_roles can stay in the Role model (no rolify there).

Also, you are starting your logger after to create User, if you start logger before you should see more interesting actions happening (maybe).

[kapso]

I am having the issue, the above fixes did not work for me. Looks like this issue is not closed yet?

[jerome-diver]

@kapso there is no issue there. which issue do you have from which code ?

[kapso]

@jerome-diver when trying to add_role in after_create callback creates a duplicate record in user_roles. I moved the add_role out of the callback, and now there's no dup record.

[jerome-diver]

@kapso, please, show your model source code for user. maybe paste it there... if there is double, it is because there is something happening two times because of wrong model (or dirty controller is also possible). Actually rofily lib seems to works pretty well on my side.

[skukx]

I can confirm, having similar issue as poster. One call to add_role but multiple queries executed. However I'm not convinced this is a rolify issue and may be related to activerecord autosave for HABTM records.

Logs:

[DEBUG] [ActiveRecord] User::HABTM_Roles Create
  INSERT INTO `users_roles` (`user_id`, `role_id`) VALUES (?, ?)
[INFO] User role added (manager)
...
[DEBUG] [ActiveRecord] User::HABTM_Roles Create
  INSERT INTO `users_roles` (`user_id`, `role_id`) VALUES (?, ?)

This seems to only occur on new users where add_role is called within the after_create callback.

[yorch]

@skukx did you figure what the problem was? I'm experiencing the exact same issue with Rails 6. My User model is pretty straightforward, so not sure what's going on

class User < ApplicationRecord
  include Clearance::User

  validates :email, uniqueness: true
  validates :first_name, :last_name, presence: true

  after_create :assign_default_role

  rolify

  has_paper_trail

  default_scope { order(email: :asc) }

  def assign_default_role
    self.add_role(:user) if self.roles.blank?
  end

  def role_names
    roles.collect { |r| r.name }
  end

  def is_admin?
    self.has_role? :admin
  end

  def is_admin_or_manager?
    self.has_role?(:admin) || self.has_role?(:manager)
  end
end

[wooly]

@yorch I imagine you've fixed this, but I just hit this and think I've gotten past it by moving the after_create callback underneath the rolify call.

[klueless-io]

@yorch I imagine you've fixed this, but I just hit this and think I've gotten past it by moving the after_create callback underneath the rolify call.

This worked for me, thank you wooly.

It is clear that there is a bug Rolify around this issue, but the bug may indeed be related to ActiveRecord HABTM records, as mentioned by skukx

[paulodeon]

In my case the ordering of the rolify/after_create didnt make any difference, but switching to after_create_commit did fix the issue