Strange callback behavior

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

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

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