MySQL server has gone away error in delayed_job task

Question

I'm trying to debug a scenario in which the delayed_job process dies under certain circumstances because of a Mysql2::Error: MySQL server has gone away error.

My setup is a bit complex, but I tried to whittle it down to the basics. The run method in the ClustalwFlowTask class is handled as a background job. It basically runs a clustalw2 command (a program that does multiple sequence alignment for DNA and proteins)

The details of the command and any error that occurs during its execution should be logged in the flow_tasks table and not caught by delayed_job (see the update_attribute statements).

require 'open3'
class ClustalwFlowTask < FlowTask

  def run
    # setup code ------

    # fasta is a file object
    cmd = "clustalw2 -INFILE=#{fasta.path}"

    Rails.logger.info "[INFO #{Time.now}] #{self} running #{cmd}"
    #update_attribute(:command, cmd)

    raw_stdin,  raw_stdout, raw_stderr = Open3.popen3(cmd)

    Rails.logger.info "*********** RAW STDERR: #{raw_stderr} ************"

    stdin, stdout, stderr = [raw_stdin,  raw_stdout, raw_stderr].map do |io|
      s = io.read.strip rescue nil
      io.close
      s
    end

    Rails.logger.info "*************** #{stderr} *******************"
    unless stderr.blank?
      Rails.logger.info "============  THERE IS AN ERROR  ============"
      #update_attribute(:error, stderr)
      return false
    end

    # more code here -----
end

The weird behavior starts when a user doesn't have the clustalw2 binary installed, that is if the stderr variable in the method is not blank. Note that I uncommented all the update_attribute statements from the #run method during debugging, so there is no apparent MySQL involvement. (One of my first hunches was that the stderr message is too big or contains something that causes the MySQL server to shut down, but that doesn't seem to be the case)

The delayed_job log contains the following:

2012-03-26T09:19:25-0700: [Worker(delayed_job host:JadeDragon.local pid:8998)] ClustalwFlowTask failed with ActiveRecord::StatementInvalid: Mysql2::Error: closed MySQL connection: DELETE FROM `delayed_jobs` WHERE `delayed_jobs`.`id` = 107 - 0 failed attempts

What seems to be happening here is that delayed_job attempted to delete a successful task from the db, but was unable to do so because the mysql connection had been severed. This occurs after the return false statement in the ClustalwFlowTask#run code, since that's when, according to delayed_job, the task is finished successfully.

The development log has this:

================  THERE IS AN ERROR  ================
   (0.5ms)  BEGIN
Mysql2::Error: MySQL server has gone away: BEGIN
  SQL (0.2ms)  DELETE FROM `delayed_jobs` WHERE `delayed_jobs`.`id` = 110
Mysql2::Error: closed MySQL connection: DELETE FROM `delayed_jobs` WHERE `delayed_jobs`.`id` = 110
   (0.1ms)  ROLLBACK
Mysql2::Error: closed MySQL connection: ROLLBACK
   (0.1ms)  BEGIN
Mysql2::Error: closed MySQL connection: BEGIN
   (0.1ms)  ROLLBACK
Mysql2::Error: closed MySQL connection: ROLLBACK
closed MySQL connection

I'm running out of ideas on how to debug this, so any help would be greatly appreciated.

Answer 1

Try adding reconnect: true to your database.yml