Forum: Ruby on Rails Strange callback behavior

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
E37ca8b3eee534fa6781f7ba13743afb?d=identicon&s=25 ryan.wood (Guest)
on 2005-12-11 04:25
(Received via mailing list)
I'm not sure if you guys can help on this one, but I'll give it a
shot. On my hosted site (running linux and RC5 (0.14.4)) I'm seeing
that the before_update callback is called multiple times on a single
update. This is a prblem because I'm using it to hash a password and
it's getting double hashed.

What's strange is that it works correctly on my WinXP dev box (on
RC5), but when I publish the same code to the shared box, I have
problems. I've added some additional logging to try to diagnose the
problem. I noticed that the active record callback "before_update"
gets fired twice in a row on one update. On my dev box it only fires
once. Any ideas on this one?

--Ryan
E37ca8b3eee534fa6781f7ba13743afb?d=identicon&s=25 ryan.wood (Guest)
on 2005-12-11 04:54
(Received via mailing list)
I wanted to add a little code to see if that gave any additional
insight.

>From my user class (based on login_generator):

    # Apply SHA1 encryption to the supplied password.
    # We will additionally surround the password with a salt
    # for additional security.
    def self.sha1(pass)
      Digest::SHA1.hexdigest("#{salt}--#{pass}--")
    end

    before_create :l1, :crypt_password

    # Before saving the record to database we will crypt the password
    # using SHA1.
    # We never store the actual password in the DB.
    def crypt_password
      logger.debug "** Hashing password: #{password}. **"
      write_attribute "password", self.class.sha1(password)
      logger.debug "** Hashed password is #{password}. **"
    end

    before_update :l2, :crypt_unless_empty

    #used only for temporary debug logging
    def l1
      logger.debug "** before_create event called."
    end

    def l2
      logger.debug "** before_update event called."
    end

    # If the record is updated we will check if the password is empty.
    # If its empty we assume that the user didn't want to change his
    # password and just reset it to the old value.
    def crypt_unless_empty
      # get original password for comparison
      user = self.class.find(self.id)

      if password.empty?
        # on update, blank password means that no change is desired
        self.password = user.password
      else
        # if the password is different from the original, assume
        # that it has been changed and needs hashing
        logger.debug "** Calling 'crypt_password' from
'crypt_unless_empty'."
        crypt_password if password != user.password
      end
    end

In the UserController class:

 def update
    begin
      @user = User.find(params[:id])
      logger.debug "** Before updating user **"
      if @user.update_attributes(params[:user])
        logger.debug "** User successully updated. **"
        flash[:notice] = "#{@user.name} was successfully updated."
        redirect_to :action => 'list'
      else
        load_options
        render :action => 'edit'
      end
    rescue Exception => ex
      flash[:notice] = ex
      edit
      render :action => 'edit'
    end
  end


Snippet from the log:

Processing UserController#update (for 71.12.25.100 at 2005-12-10
22:11:25) [POST]
  Parameters: {"user"=>{"password_confirmation"=>"123123",
"role_id"=>"2", "advertiser_id"=>"6", "first_name"=>"Test",
"login"=>"user", "password"=>"123123", "last_name"=>"User"},
"commit"=>"Edit", "action"=>"update", "id"=>"11",
"controller"=>"admin/user"}
User Columns (0.000854)  SHOW FIELDS FROM users
Role Load (0.000322)  SELECT * FROM roles WHERE (roles.id = 1) LIMIT 1
Role Columns (0.000570)  SHOW FIELDS FROM roles
User Load (0.000744)  SELECT * FROM users WHERE (users.id = '11') LIMIT
1
** Before updating user **
SQL (0.000108)  BEGIN
Role Load (0.000334)  SELECT * FROM roles WHERE (roles.id = 2) LIMIT 1
User Load (0.000960)  SELECT * FROM users WHERE (login = 'user' AND id
<> 11) LIMIT 1
User Load (0.000692)  SELECT * FROM users WHERE (login = 'user' AND id
<> 11) LIMIT 1
** before_update event called.
User Load (0.000858)  SELECT * FROM users WHERE (users.id = 11) LIMIT 1
** Calling 'crypt_password' from 'crypt_unless_empty'.
** Hashing password: 123123. **
** Hashed password is e54d12732c6a871bbcbe8e42f8d4e8ebf420b780. **
** before_update event called.
User Load (0.000737)  SELECT * FROM users WHERE (users.id = 11) LIMIT 1
** Calling 'crypt_password' from 'crypt_unless_empty'.
** Hashing password: e54d12732c6a871bbcbe8e42f8d4e8ebf420b780. **
** Hashed password is f581de6ded936f92101b37805e84c81529eabb28. **
User Update (0.000262)  UPDATE users SET `created_at` = '2005-12-09
14:37:24', `login` = 'user', `last_name` = 'User', `last_session_at` =
NULL, `first_name` = 'Test', `role_id` = 2, `advertiser_id` = 6,
`last_accessed_at` = NULL, `password` =
'f581de6ded936f92101b37805e84c81529eabb28', `updated_at` = '2005-12-10
22:11:25' WHERE id = 11
SQL (0.028787)  COMMIT
** User successully updated. **

You can see where it hashes the password twice because before_update
was fired twice. Any help is GREATLY appreciated. Thanks.

-Ryan
E37ca8b3eee534fa6781f7ba13743afb?d=identicon&s=25 Ryan Wood (Guest)
on 2005-12-11 20:02
(Received via mailing list)
Anyone have any ideas on this? It's driving me crazy.

I've also noticed that all of my validation errors are duplicating as
well. It's like called object.update_attributes(@params[object]) is
somehow running twice. Unfortunately, I can't debug very well as it is
only happening on a shared server. It started right after the upgrade
to RC5, but is only happening on my User object that is using the
login generator. Any help would really be appreciated.

--Ryan
This topic is locked and can not be replied to.