Rails delayed_job doesn't perform

Question

I've defined two custom jobs. One works and the other does not. The one not working enqueues but nothing else ever happens. No failure or success.

After trying all the tips at collectiveidea where I found the documentation and on SO, I'm stumped. I have job failures being retained. I'm logging all DJ events in a separate log. They provide no clues. My DJ log shows the job being enqueued and that's it.

The job is to post to a web site.

This is what appears in the delayed_job table for the bad job.

2.1.2 :004 > Delayed::Job.last
 => #<Delayed::Backend::ActiveRecord::Job id: 2515456, priority: 0, attempts: 0, handler: "--- !ruby/struct:SendHubCommandJob\ncmd: getOptions...", last_error: nil, run_at: "2015-08-14 02:07:32", locked_at: nil, failed_at: nil, locked_by: nil, queue: nil, created_at: "2015-08-14 02:07:32", updated_at: "2015-08-14 02:07:32">

My custom job:

SendHubCommandJob = Struct.new(:cmd, :hub, :badge, :arg1, :arg2) do
  # Send a command to the hub to forward to badge

  def enqueue(job)
    #called
    Delayed::Worker.logger.info "SendHubCommandJob enqueue: #{cmd} #{hub} #{badge} #{arg1} #{arg2}"
  end

  def success(job)
    #not called
    Delayed::Worker.logger.info "SendHubCommandJob: success"
  end

  def error(job, exception)
    #not called
    Delayed::Worker.logger.info "SendHubCommandJob: error"
    # Send email notification / alert / alarm
  end

  def failure(job)
    #not called
    Delayed::Worker.logger.info "SendHubCommandJob: failure"  
  end

  def perform
    #not called
    Delayed::Worker.logger.info "SendHubCommandJob: got here"
    Delayed::Worker.logger.info "SendHubCommandJob perform: #{:cmd} #{hub} #{badge} #{arg1} #{arg2}"

    require "open-uri"
    require "net/http"

    @@cmd_count = @@cmd_count + 1
    s = "http://#{hub}.local:9090/cmd"
    uri = URI(s)
    req = Net::HTTP::Post.new(uri)
    Delayed::Worker.logger.info "SendHubCommandJob: #{uri}"

    # Set where hub should send asynch response
    response_addr = "mark.local:3000"

    #TODO Implement other commands here
    case @cmd
    when 'getOptions'
      req.set_form_data('type' => 'cmd', 'cmd'=>'READ', 'subcmd'=>'GENERAL', 'datatype'=>'OPTIONS', 'modulename'=>'BTPENDANT', 
      'sensorid'=>'#{@badge}', 'moduleidx'=>'0', 'processtype'=>'1', 'count_or_ms'=>'0', 'trackingid'=>@@cmd_count, 'response_addr'=>response_addr,
      'jsontxt'=>{'device'=>'#{@hub}'})

    when 'setOptions'  #arg1 is 12 byte hex string per badge spec
      req.set_form_data('type' => 'cmd', 'cmd'=>'WRITE', 'subcmd'=>'GENERAL', 'datatype'=>'OPTIONS', 'modulename'=>'BTPENDANT', 
      'sensorid'=>'#{@badge}', 'moduleidx'=>'0', 'processtype'=>'1', 'count_or_ms'=>'0', 'trackingid'=>@@cmd_count, 'response_addr'=>response_addr, 
      'jsontxt'=>{'device'=>'#{@hub}', 'value'=>'#{@arg1}'})

    when 'getBadgeInfo'  #arg1 is string DEVICE_NAME, MODEL_NUMBER, SERIAL_NUMBER, FIRMWARE_REV, MANUFACTURER_NAME
      req.set_form_data('type' => 'cmd', 'cmd'=>'READ', 'subcmd'=>'#{@arg1}', 'datatype'=>'ID', 'modulename'=>'BTPENDANT', 
      'sensorid'=>'#{@badge}', 'moduleidx'=>'0', 'processtype'=>'1', 'count_or_ms'=>'0', 'trackingid'=>@@cmd_count, 'response_addr'=>response_addr,
      'jsontxt'=>{'device'=>'#{@hub}'})

    else
      Delayed::Worker.logger.error "SendHubCommandJob: Unexpected command"
    end

    res = Net::HTTP.start(uri.hostname, uri.port) do |http|
      http.request(req)
      #Delayed::Worker.logger.info response.inspect
    end

    case res
      when Net::HTTPSuccess, Net::HTTPRedirection
      # OK
    else
      # TODO figure how handle error
      res.value
    end
    Delayed::Worker.logger.debug "SendHubCommandJob: #{@res.to_s}"
  end  #perform
end

Answer 1

I realized I was not starting the delayed job worker properly. The command needed the trailing "start":

RAILS_ENV=development bin/delayed_job start