Failed jobs are performed twice

[carlson]

Under normal conditions delayed jobs run and report results as expected:

*** Starting job worker host:Erics-MacBook.local pid:19112
About to perform job
1 jobs processed at 6.1079 j/s, 0 failed ...

However, when a job fails, it attempts to perform it a second time and displays the result as 2 errors:

*** Starting job worker host:Erics-MacBook.local pid:19103
About to perform job
About to perform job
2 jobs processed at 22.1354 j/s, 2 failed ...
About to perform job
About to perform job
2 jobs processed at 89.2026 j/s, 2 failed ...
2 jobs processed at 47.0045 j/s, 2 failed ...
About to perform job
About to perform job
2 jobs processed at 90.6083 j/s, 2 failed ...

Here is the code that performs the delayed job:

class TestJob
  def initialize
    puts "Job created"
  end

  def perform
    puts "About to perform job"
    raise "Ooops"
  end
end

[carlson]

Looks like it may have been related to using sqlite - will verify

[plashchynski]

On Sqlite:

> script/console
> Loading development environment (Rails 2.3.4)
>> class A
>> def b
>> raise "some error"
>> end
>> end
=> nil
>> a = A.new
=> #<A:0x7fd2921a8f58>
>> Delayed::Job.destroy_all
=> [#<Delayed::Job id: 14, priority: 0, attempts: 1, handler: "<CUTED>", run_at: "2009-12-14 09:21:58", locked_at: "2009-12-14 09:21:52", failed_at: nil, locked_by: "host:dmitry-laptop pid:8822", created_at: "2009-12-14 09:21:27", updated_at: "2009-12-14 09:21:52">]
>> a.send_later(:b)
=> #<Delayed::Job id: 15, priority: 0, attempts: 0, handler: "<CUTED>", last_error: nil, run_at: "2009-12-14 09:22:47", locked_at: nil, failed_at: nil, locked_by: nil, created_at: "2009-12-14 09:22:47", updated_at: "2009-12-14 09:22:47"> >> Delayed::Worker.new.start
*** Starting job worker host:dmitry-laptop pid:9039

• [Worker(host:dmitry-laptop pid:9039)] acquired lock on Unknown#b
  
• [Worker(host:dmitry-laptop pid:9039)] acquired lock on Unknown#b
  2 jobs processed at 4.6158 j/s, 2 failed ...
  
• [Worker(host:dmitry-laptop pid:9039)] acquired lock on Unknown#b
  
• [Worker(host:dmitry-laptop pid:9039)] acquired lock on Unknown#b
  2 jobs processed at 4.9809 j/s, 2 failed ...
  

On MySQL: script/console Loading development environment (Rails 2.3.4) ?> class A
>> def b
>> raise "some error"
>> end
>> end
=> nil
>> a = A.new
=> #<A:0x7fad615e1dc8>
>> Delayed::Job.destroy_all
=> []
>> a.send_later(:b)
=> #<Delayed::Job id: 1, priority: 0, attempts: 0, handler: "--- !ruby/struct:Delayed::PerformableMethod \nobject...", last_error: nil, run_at: "2009-12-14 09:33:38", locked_at: nil, failed_at: nil, locked_by: nil, created_at: "2009-12-14 09:33:38", updated_at: "2009-12-14 09:33:38">
>> Delayed::Worker.new.start
*** Starting job worker host:dmitry-laptop pid:10479

• [Worker(host:dmitry-laptop pid:10479)] acquired lock on Unknown#b
  
• [Worker(host:dmitry-laptop pid:10479)] failed to acquire exclusive lock for Unknown#b
  1 jobs processed at 4.9080 j/s, 1 failed ...
  
• [Worker(host:dmitry-laptop pid:10479)] failed to acquire exclusive lock for Unknown#b
  
• [Worker(host:dmitry-laptop pid:10479)] acquired lock on Unknown#b
  1 jobs processed at 8.3198 j/s, 1 failed ...