log

017-03-28T18:37:12.826Z 20268 TID-oxi3cqvik INFO: Running in ruby 2.3.3p222 (2016-11-21 revision 56859) [x86_64-darwin16]
2017-03-28T18:37:12.826Z 20268 TID-oxi3cqvik INFO: Sidekiq Pro 3.4.5, commercially licensed.  Thanks for your support!
2017-03-28T18:37:12.828Z 20268 TID-oxi3cqvik DEBUG: Client Middleware: Sidekiq::Batch::Client, SidekiqUniqueJobs::Client::Middleware
2017-03-28T18:37:12.828Z 20268 TID-oxi3cqvik DEBUG: Server Middleware: Sidekiq::Middleware::Server::Logging, Sidekiq::Middleware::Server::RetryJobs, Sidekiq::Middleware::Server::ActiveRecord, Sidekiq::Batch::Server, SidekiqUniqueJobs::Server::Middleware, Honeybadger::Plugins::Sidekiq::Middleware, NewRelic::SidekiqInstrumentation
2017-03-28T18:37:12.828Z 20268 TID-oxi3cqvik INFO: Starting processing, hit Ctrl-C to stop
2017-03-28T18:37:12.829Z 20268 TID-oxi3cqvik DEBUG: {:queues=>["default", "pentaho_job", "ruby_job"], :labels=>[], :concurrency=>10, :require=>".", :environment=>nil, :timeout=>8, :poll_interval_average=>nil, :average_scheduled_poll_interval=>15, :error_handlers=>[#<Sidekiq::ExceptionHandler::Logger:0x007feee99fd4b0>, #<Proc:0x007feeeb4eee40@/Users/steveburkett/.rvm/gems/ruby-2.3.3/gems/honeybadger-2.6.1/lib/honeybadger/plugins/sidekiq.rb:29 (lambda)>, #<Proc:0x007feeeb591c30@/Users/steveburkett/.rvm/gems/ruby-2.3.3/gems/newrelic_rpm-3.16.3.323/lib/new_relic/agent/instrumentation/sidekiq.rb:66>], :lifecycle_events=>{:startup=>[], :quiet=>[#<Proc:0x007feee8db81a0@/Users/steveburkett/.rvm/gems/ruby-2.3.3/gems/sidekiq-pro-3.4.5/lib/sidekiq/pro/config.rb:89>], :shutdown=>[], :heartbeat=>[]}, :dead_max_jobs=>10000, :dead_timeout_in_seconds=>15552000, :reloader=>#<Sidekiq::Rails::Reloader @app=G5Datawarehouse::Application>, :verbose=>true, :limits=>{"default"=>1, "pentaho_job"=>1, "ruby_job"=>1}, :config_file=>"config/sidekiq.yml", :strict=>true, :identity=>"Steve-Burketts-MacBook-Pro.local:20268:03f8802db9bb", :backup_limit=>1000, :fetch=>Sidekiq::Pro::BasicFetch, :tag=>"datawarehouse"}
2017-03-28T18:38:13.374Z 20268 TID-oxi4guel0 DwTestWorkflow JID-8b555736effae0fe28b724ab INFO: start
Dw Test workflow for foobar_urn is about to be started
Dw Test workflow-entering level1 enqueuing
2017-03-28T18:38:13.432Z 20268 TID-oxi4guel0 DwTestWorkflow JID-8b555736effae0fe28b724ab DEBUG: Adding 1 jobs to batch lJF0vevKZk6agg, JIDs ["262fb891fb939d08eb5f765b"]
Dw Test workflow for foobar_urn has started!
2017-03-28T18:38:13.435Z 20268 TID-oxi4guel0 DwTestWorkflow JID-8b555736effae0fe28b724ab INFO: done: 0.061 sec
2017-03-28T18:38:13.782Z 20268 TID-oxi4gufm8 DwTestSeqJob JID-262fb891fb939d08eb5f765b BID-lJF0vevKZk6agg INFO: start
Starting seq job
Ending seq job
2017-03-28T18:38:28.789Z 20268 TID-oxi4gufm8 DwTestSeqJob JID-262fb891fb939d08eb5f765b BID-lJF0vevKZk6agg INFO: done: 15.008 sec
2017-03-28T18:38:28.808Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-fffbfd6ede134f2a06544082 INFO: start
2017-03-28T18:38:28.808Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-fffbfd6ede134f2a06544082 DEBUG: BID-lJF0vevKZk6agg complete
2017-03-28T18:38:28.812Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-fffbfd6ede134f2a06544082 INFO: done: 0.004 sec
2017-03-28T18:38:28.831Z 20268 TID-oxi3rbqlc Sidekiq::Batch::Callback JID-45c71ae3446ba33ea823b076 INFO: start
2017-03-28T18:38:28.831Z 20268 TID-oxi3rbqlc Sidekiq::Batch::Callback JID-45c71ae3446ba33ea823b076 DEBUG: BID-lJF0vevKZk6agg success
Dw Test workflow-entering level_a enqueuing
2017-03-28T18:38:28.833Z 20268 TID-oxi3rbqlc Sidekiq::Batch::Callback JID-45c71ae3446ba33ea823b076 DEBUG: Adding 1 jobs to batch ec5JbyiOXHVaFQ, JIDs ["fcd8145b2bfe56db454c3361"]
2017-03-28T18:38:28.835Z 20268 TID-oxi3rbqlc Sidekiq::Batch::Callback JID-45c71ae3446ba33ea823b076 INFO: done: 0.004 sec
2017-03-28T18:38:28.852Z 20268 TID-oxi4gueew DwTestSeqJob JID-fcd8145b2bfe56db454c3361 BID-ec5JbyiOXHVaFQ INFO: start
Starting seq job
2017-03-28T18:38:29.399Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-df253aafff628d1f2ef3c092 INFO: start
2017-03-28T18:38:29.399Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-df253aafff628d1f2ef3c092 DEBUG: BID-omm_xTP4-_UbTg complete
2017-03-28T18:38:29.401Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-df253aafff628d1f2ef3c092 INFO: done: 0.002 sec
Ending seq job
2017-03-28T18:38:43.860Z 20268 TID-oxi4gueew DwTestSeqJob JID-fcd8145b2bfe56db454c3361 BID-ec5JbyiOXHVaFQ INFO: done: 15.008 sec
2017-03-28T18:38:43.884Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-51713de1bff713a017146e7d INFO: start
2017-03-28T18:38:43.884Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-51713de1bff713a017146e7d DEBUG: BID-ec5JbyiOXHVaFQ complete
2017-03-28T18:38:43.888Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-51713de1bff713a017146e7d INFO: done: 0.004 sec
2017-03-28T18:38:43.908Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-3e9dc67910c4582d401480b3 INFO: start
2017-03-28T18:38:43.908Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-3e9dc67910c4582d401480b3 DEBUG: BID-ec5JbyiOXHVaFQ success
Dw Test workflow-entering level_b enqueuing
2017-03-28T18:38:43.910Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-3e9dc67910c4582d401480b3 DEBUG: Adding 1 jobs to batch 8aZDe4u_kag5MA, JIDs ["80bf61874adc09a8723c6701"]
2017-03-28T18:38:43.912Z 20268 TID-oxi4gufa0 Sidekiq::Batch::Callback JID-3e9dc67910c4582d401480b3 INFO: done: 0.004 sec
2017-03-28T18:38:43.929Z 20268 TID-oxi3rbqlc DwTestSeqJob JID-80bf61874adc09a8723c6701 BID-8aZDe4u_kag5MA INFO: start
Starting seq job
Ending seq job
2017-03-28T18:38:58.934Z 20268 TID-oxi3rbqlc DwTestSeqJob JID-80bf61874adc09a8723c6701 BID-8aZDe4u_kag5MA INFO: done: 15.005 sec
2017-03-28T18:38:58.958Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-ca6565e7274ee585d91701d0 INFO: start
2017-03-28T18:38:58.959Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-ca6565e7274ee585d91701d0 DEBUG: BID-8aZDe4u_kag5MA complete
2017-03-28T18:38:58.964Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-ca6565e7274ee585d91701d0 INFO: done: 0.005 sec
2017-03-28T18:38:58.986Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-c964c7491c98ae9f7810cd82 INFO: start
2017-03-28T18:38:58.986Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-c964c7491c98ae9f7810cd82 DEBUG: BID-8aZDe4u_kag5MA success
Dw Test workflow-entering level_last enqueuing
2017-03-28T18:38:58.988Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-c964c7491c98ae9f7810cd82 DEBUG: Adding 1 jobs to batch QZCodj0NljQmOA, JIDs ["1b183e962a2fcaa01f6e73d8"]
2017-03-28T18:38:58.990Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-c964c7491c98ae9f7810cd82 INFO: done: 0.004 sec
2017-03-28T18:38:59.012Z 20268 TID-oxi4gufa0 DwTestSeqJob JID-1b183e962a2fcaa01f6e73d8 BID-QZCodj0NljQmOA INFO: start
Starting seq job
Ending seq job
2017-03-28T18:39:14.021Z 20268 TID-oxi4gufa0 DwTestSeqJob JID-1b183e962a2fcaa01f6e73d8 BID-QZCodj0NljQmOA INFO: done: 15.009 sec
2017-03-28T18:39:14.040Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-a8155821d69fa2b79c53abcc INFO: start
2017-03-28T18:39:14.041Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-a8155821d69fa2b79c53abcc DEBUG: BID-QZCodj0NljQmOA complete
2017-03-28T18:39:14.046Z 20268 TID-oxi3rbqrg Sidekiq::Batch::Callback JID-a8155821d69fa2b79c53abcc INFO: done: 0.005 sec
2017-03-28T18:39:14.066Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-374d6b42ab80a1158c0ded65 INFO: start
2017-03-28T18:39:14.067Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-374d6b42ab80a1158c0ded65 DEBUG: BID-QZCodj0NljQmOA success
Dw Test workflow-entering level2 enqueuing
2017-03-28T18:39:14.071Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-374d6b42ab80a1158c0ded65 DEBUG: Adding 5 jobs to batch o7y5xAj8F8oqGQ, JIDs ["80355b46ae6ef8a60cdf082e", "afcbae09ac878d597789656d", "86259fc3170a6ebe7d241ed8", "1e0fcbf1393e5be8567dc9b0", "7e55ca24cc9c1a655b04fba6"]
Dw Test workflow-leaving level2 enqueuing
2017-03-28T18:39:14.075Z 20268 TID-oxi4gufm8 Sidekiq::Batch::Callback JID-374d6b42ab80a1158c0ded65 INFO: done: 0.009 sec
2017-03-28T18:39:14.091Z 20268 TID-oxi4gueew DwTestParallelJob JID-86259fc3170a6ebe7d241ed8 BID-o7y5xAj8F8oqGQ INFO: start
Starting parallel job
2017-03-28T18:39:14.093Z 20268 TID-oxi4guel0 DwTestParallelJob JID-80355b46ae6ef8a60cdf082e BID-o7y5xAj8F8oqGQ INFO: start
Starting parallel job
2017-03-28T18:39:14.118Z 20268 TID-oxi3rbqlc DwTestParallelJob JID-afcbae09ac878d597789656d BID-o7y5xAj8F8oqGQ INFO: start
Starting parallel job
2017-03-28T18:39:14.766Z 20268 TID-oxi4gufg4 DwTestParallelJob JID-7e55ca24cc9c1a655b04fba6 BID-o7y5xAj8F8oqGQ INFO: start
Starting parallel job
Ending parallel job
2017-03-28T18:39:29.096Z 20268 TID-oxi4gueew DwTestParallelJob JID-86259fc3170a6ebe7d241ed8 BID-o7y5xAj8F8oqGQ INFO: done: 15.005 sec
Ending parallel job
2017-03-28T18:39:29.097Z 20268 TID-oxi4guel0 DwTestParallelJob JID-80355b46ae6ef8a60cdf082e BID-o7y5xAj8F8oqGQ INFO: done: 15.004 sec
Ending parallel job
2017-03-28T18:39:29.120Z 20268 TID-oxi3rbqlc DwTestParallelJob JID-afcbae09ac878d597789656d BID-o7y5xAj8F8oqGQ INFO: done: 15.002 sec
Ending parallel job
2017-03-28T18:39:29.770Z 20268 TID-oxi4gufg4 DwTestParallelJob JID-7e55ca24cc9c1a655b04fba6 BID-o7y5xAj8F8oqGQ INFO: done: 15.004 sec

parallel_job.rb

class DwTestParallelJob
  include Sidekiq::Worker
  sidekiq_options queue: :default, retry: false

  def perform(opts={})
    puts('Starting parallel job')
    sleep(15)
    puts('Ending parallel job')
  end
end

seq_job.rb

class DwTestSeqJob
  include Sidekiq::Worker
  sidekiq_options queue: :default, retry: false

  def perform(opts={})
    puts('Starting seq job')
    sleep(15)
    puts('Ending seq job')
  end
end

workflow.rb

class DwTestWorkflow
  include Sidekiq::Worker

  # This example creates a batch workflow.
  #   Level1 is sequential
  #   Level2 is parallel (assuming sidekiq is started w/ -c > 1)
  def perform(client_urn)
    puts "Dw Test workflow for #{client_urn} is about to be started"

    overall = Sidekiq::Batch.new
    overall.on(:success, 'DwTestWorkflow#all_done', client_urn: client_urn)
    overall.description = "Dw Test workflow (master) for #{client_urn}"
    level1(overall, client_urn)

    puts "Dw Test workflow for #{client_urn} has started!"
  end

  def level1(overall, client_urn)
    puts 'Dw Test workflow-entering level1 enqueuing'
    overall.jobs do
      level1 = Sidekiq::Batch.new
      level1.description = "Dw Test workflow (level1) for #{client_urn}"
      level1.on(:success, 'DwTestWorkflow#level1_a', client_urn: client_urn)
      level1.jobs { DwTestSeqJob.perform_async(client_urn) }
    end
  end

  def level1_a(status, options)
    puts 'Dw Test workflow-entering level_a enqueuing'
    client_urn = options['client_urn']
    overall = Sidekiq::Batch.new(status.parent_bid)
    overall.jobs do
      level1_a = Sidekiq::Batch.new
      level1_a.description = "Dw Test workflow (level1a) for #{client_urn}"
      level1_a.on(:success, 'DwTestWorkflow#level1_b', client_urn: client_urn)
      level1_a.jobs { DwTestSeqJob.perform_async(client_urn) }
    end
  end

  def level1_b(status, options)
    puts 'Dw Test workflow-entering level_b enqueuing'
    client_urn = options['client_urn']
    overall = Sidekiq::Batch.new(status.parent_bid)
    overall.jobs do
      level1_b = Sidekiq::Batch.new
      level1_b.description = "Dw Test workflow (level1b) for #{client_urn}"
      level1_b.on(:success, 'DwTestWorkflow#level1_last', client_urn: client_urn)
      level1_b.jobs { DwTestSeqJob.perform_async(client_urn) }
    end
  end

  def level1_last(status, options)
    puts 'Dw Test workflow-entering level_last enqueuing'
    client_urn = options['client_urn']
    overall = Sidekiq::Batch.new(status.parent_bid)
    overall.jobs do
      level1_last = Sidekiq::Batch.new
      level1_last.description = "Dw Test workflow (level1_last) for #{client_urn}"
      level1_last.on(:success, 'DwTestWorkflow#level2', client_urn: client_urn)
      level1_last.jobs { DwTestSeqJob.perform_async(client_urn) }
    end
  end

  def level2(status, options)
    puts 'Dw Test workflow-entering level2 enqueuing'
    client_urn = options['client_urn']
    overall = Sidekiq::Batch.new(status.parent_bid)
    overall.jobs do
      level2 = Sidekiq::Batch.new
      level2.description = "Dw Test workflow level2 for #{client_urn}"
      level2.jobs do
        DwTestParallelJob.perform_async(client_urn)
        DwTestParallelJob.perform_async(client_urn)
        DwTestParallelJob.perform_async(client_urn)
        DwTestParallelJob.perform_async(client_urn)
        DwTestParallelJob.perform_async(client_urn)
      end
    end
    puts 'Dw Test workflow-leaving level2 enqueuing'
  end

  def all_done(status, options)
    urn = options['client_urn']
    puts "Dw Test workflow for #{urn} has finished!!!"
  end
end