My app is double-processing some requests

[Phrogz]

(First off, let me say that I'm not sure who is at fault here, and am
guessing at culprits based on the symptoms.)

Summary:
My application is sometimes recording duplicate database fields, and I
can't figure out why. I'm concerned that it may be Ramaze/Mongrel
having multiple threads that are processing the same data. I hope
someone can either confirm or deny this, or help me narrow down the
problem.

Details:
I have a Ramaze app running on Mongrel, using Ngnix as a reverse-proxy
for static files and gzipping. I'm using Sequel and SQLite for the
database.

All of this is running on Windows XP. (I'm off to a bad start already,
I know.)

The application is a bug tracking database. Every change to a bug (an
HTTP POST request) records the change in a DB log. (The actual code
that does this is at the end of the post.)

Most of the time, this is working fine. However, occasionally I'll get
duplicate entries recorded, with the same values and same timestamp.
When this happens, the Nginx logs and the Ramaze logs both show that
only one HTTP request came in for the code that updates the bug. But
the Sequel log clearly shows the insert occurring twice.

I have seen this problem occur across multiple browsers (Chrome, FF,
IE and Safari). I have seen this problem occur on my own development
machine (OS X) as well as the production server (Windows). When this
starts to happen, it happens more and more frequently. This morning,
one of my coworkers was able to reproduce the problem for every edit
he made. Then I quit Ramaze (ctrl-c the process) and restarted it
(ruby start.rb), and it got better.

As I said above, it seems like maybe Ramaze and/or Mongrel are leaving
threads around that are double-handling the same request. I'm pretty
sure this isn't the browser or JS double-submitting the data. (Some of
these changes do come through AJAX that might plausibly JS submitting
the form and then the web-browser doing so. However, as noted above
only one HTTP request is seen by Nginx and Ramaze. Further, I have
explicitly seen this problem on a form that is not JS-submitted, but a
simple HTML form with POST method.)

Has anyone seen this? Any thoughts on how to isolate the problem?
Workaround it? Prevent it?

Thanks for any help you can provide.

Here is the code that processes the request:
def update_bug( in_partial_name=nil )
if request['cancel']!='cancel'
@bug = Bug[ request['bug_id'] ]
bug_is_new_flag = !@bug
unless @bug
user = active_user
Ramaze::Log.debug( "Creating new bug!" )
@bug = Bug.new do |bug|
bug.created_on = Time.now
bug.updated_on = Time.now
bug.reporter_id = user.pk
if user.trust_bug_reports_for_project?
( request['project_id'] )
bug.status_id = Status::OPEN
else
bug.status_id = Status::UNCONFIRMED
end
bug.maturity = 0
end
end
@bug.updated_on = Time.now
db_schema = Bug.db_schema
request.params.each do |field, value|
next if field==""
next if bug_is_new_flag && field=='tag_names'
if db_schema[ field.to_sym ] && db_schema[ field.to_sym ]
[ :db_type ] == "INTEGER"
value = value.to_i
end
if @bug.respond_to?( "#{field}=" )
@bug.send( "#{field}=", value )
Ramaze::Log.debug( "Updated bug: '#{field}' to
#{value.inspect}" )
end
end
@bug.save

# Do this after the bug has been saved so it has an ID to join
tags to
if bug_is_new_flag && request['tag_names']
@bug.tag_names = request['tag_names']
@bug.save
end
end

Here is the code in the model that is actually recording the change:
class Bug < Sequel::Model
before_save do
updated_on = Time.now

if old_bug = Bug[ id ]
DB.transaction do
%w| name description status_id priority severity likelihood
pain assignee_id |.each do |field|
new_value = self.send( field )
old_value = old_bug.send( field )
if new_value != old_value
BugLogEntry << {
:created_on => Time.new,
:bug_id => id,
:user_id => Ramaze::Session.current[:active_user_id],
:field_id => BugLogField.const_get( field.upcase ),
:new_value => new_value,
:old_value => old_value
}
end
end
end
end
end
end

[Phrogz]

On Oct 30, 10:41 am, Phrogz <phr...@mac.com> wrote:
> Summary:
> My application is sometimes recording duplicate database fields, and I
> can't figure out why. I'm concerned that it may be Ramaze/Mongrel
> having multiple threads that are processing the same data. I hope
> someone can either confirm or deny this, or help me narrow down the
> problem.

In case someone else is having the same problem and needs to clean
their data (in lieu of a real fix) here's a script I put together to
clean up the database table. It removes 'duplicate' entries, using a
custom subset of fields in the row to determine a collision:

module Enumerable
def dups_by
keyvals = Hash.new{|h,v|h[v]=[]}
each{ |v| keyvals[yield(v)] << v }
result = []
keyvals.each{ |k,v| result << v if v.length > 1 }
result
end
end

require 'rubygems'
require 'sequel'

DB = Sequel.sqlite 'bugs.db'
require 'bug.rb'

DB.transaction do
BugLogEntry.dups_by{ |log|

log.values.values_at( :bug_id, :user_id, :created_on, :field_id, :new_value )
}.each{ |dups|
dups[ 1..-1 ].each{ |duplicate_entry| duplicate_entry.destroy }
}
end

[Phrogz]

Solution inline below.

On Oct 30, 10:41 am, Phrogz <phr...@mac.com> wrote:

> (First off, let me say that I'm not sure who is at fault here, and am
> guessing at culprits based on the symptoms.)

I guessed incorrectly.

> I have a Ramaze app running on Mongrel, using Ngnix as a reverse-proxy
> for static files and gzipping. I'm using Sequel and SQLite for the
> database.

A combination of Sequel, Ramaze, and programmer 'error' is at fault
here.

> Here is the code in the model that is actually recording the change:
> class Bug < Sequel::Model
>   before_save do

The above code is the problem.

As explained by tmm1 on #ramaze on IRC, Sequel allows an arbitrary
number of before_save handlers to be registered. Since I was running
Ramaze with :sourcereload enabled, every time I changed the file with
the Bug model in it, Ramaze reloaded it. Which caused another copy of
the before_save handler to be added.

The solution (as described, but not yet tested) is simply to provide a
unique name for the callback:
before_save( :log_stuff ) do
...
end

By putting a symbol in there, each time the file is reloaded, it
should run over the older handler, since now it can uniquely identify
which handler replaces which. Another solution would be not to run the
server with :sourcereload enabled.

Thanks very much to tmm1 for this insight!

Happy Ramazing to all!