search

contribsys / faktory_worker_ruby

Faktory worker for Ruby
GNU Lesser General Public License v3.0
214 stars 31 forks source link

Client middleware is not used when pushing jobs from a worker #39

Closed ttilberg closed 5 years ago

ttilberg commented 5 years ago

I have a job that may conditionally en-queue other jobs when it's running. I have found that the Client Middleware is not evoked when the code is run from within the worker.

I would expect that the client middleware would still get used even when used from inside faktory-worker (since it's still using the Faktory client to push more jobs out).

Here's a small demo app:

require 'faktory_worker_ruby'

class LoudMiddleware
  def call(*_)
    puts "BEFORE THE JOB!"
    puts "!!!!!!!!!!!!!!!\n"* 3
    yield
    puts "AFTER THE JOB!\n"
    puts "!!!!!!!!!!!!!!!\n"* 3

  end
end

Faktory.configure_client do |config|
  config.client_middleware do |chain|
    chain.add LoudMiddleware
  end
end

class MyJob
  include Faktory::Job
  def perform *args
    5.times {|i| SecondaryJob.perform_async i}
    puts "Doing #{args}"
  end
end

class SecondaryJob
  include Faktory::Job
  def perform *args
    puts "Wrapping up: #{args}"
  end
end

MyJob.perform_async 'some stuff'
$ ruby app.rb
# Enqueues a single job, and the middleware shouts as it pushes the job to faktory

$ faktory-worker -r ./app.rb
# Also enqueues that job, since it's at the end, but does not shout.
# Also, the processing of the job includes enqueing 5 more jobs, which also do not get middlewared.
ttilberg@timdesktop:~/dev/fkt_middleware$ ruby app.rb 
BEFORE THE JOB!
!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!
AFTER THE JOB!
!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!
!!!!!!!!!!!!!!!
ttilberg@timdesktop:~/dev/fkt_middleware$ faktory-worker -r ./app.rb 

                    ,,,,
            ,,,,    |  |
            |  |    |  |
            |  |    |  |
            |  |,,~~'  '~,          ___       _
       ,,~~''   ,~~,      '~,      / __)     | |      _
 ,,~~''   ,~~,  |  |        |    _| |__ _____| |  _ _| |_ ___   ____ _   _
 |  ,~~,  |  |  |  |        |   (_   __|____ | |_/ |_   _) _ \ / ___) | | |
 |  |  |  |  |  |  |        |     | |  / ___ |  _ (  | || |_| | |   | |_| |
 |  |__|  |__|  |__|        |     |_|  \_____|_| \_)  \__)___/|_|    \__  |
 |__________________________|                                       (____/

2019-05-24T19:51:19.067Z 15827 TID-gptgbogs0 INFO: Running in ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-linux]
2019-05-24T19:51:19.067Z 15827 TID-gptgbogs0 INFO: See LICENSE and the LGPL-3.0 for licensing details.
2019-05-24T19:51:19.067Z 15827 TID-gptgbogs0 INFO: Starting processing, hit Ctrl-C to stop
2019-05-24T19:51:19.075Z 15827 TID-gptgejawo MyJob JID-63b98e5eea80d8594cd5d7e2 INFO: start
2019-05-24T19:51:19.075Z 15827 TID-gptgej9s4 MyJob JID-5b0871c9b745362a6cda047a INFO: start
2019-05-24T19:51:19.075Z 15827 TID-gptgej9m0 SecondaryJob JID-5e713e7cb88f0682cf001549 INFO: start
Wrapping up: [0]
2019-05-24T19:51:19.075Z 15827 TID-gptgej9m0 SecondaryJob JID-5e713e7cb88f0682cf001549 INFO: done: 0.0 sec
2019-05-24T19:51:19.075Z 15827 TID-gptgej9fw SecondaryJob JID-f17c4ac4a1111af538bccbd8 INFO: start
Wrapping up: [0]
2019-05-24T19:51:19.076Z 15827 TID-gptgej9fw SecondaryJob JID-f17c4ac4a1111af538bccbd8 INFO: done: 0.0 sec
2019-05-24T19:51:19.076Z 15827 TID-gptgej93o SecondaryJob JID-d75c75c75e66ca36b5ee6eea INFO: start
Wrapping up: [1]
2019-05-24T19:51:19.076Z 15827 TID-gptgej93o SecondaryJob JID-d75c75c75e66ca36b5ee6eea INFO: done: 0.0 sec
2019-05-24T19:51:19.077Z 15827 TID-gptgej8lc SecondaryJob JID-9408c4c062de490c8c4283e8 INFO: start
Doing ["do some stuff"]
Doing ["do some stuff"]
Wrapping up: [3]
2019-05-24T19:51:19.077Z 15827 TID-gptgej9m0 SecondaryJob JID-04a8ae11a5f3ba5669b02723 INFO: start
Wrapping up: [4]
2019-05-24T19:51:19.077Z 15827 TID-gptgej9m0 SecondaryJob JID-04a8ae11a5f3ba5669b02723 INFO: done: 0.0 sec
2019-05-24T19:51:19.077Z 15827 TID-gptgej9fw SecondaryJob JID-e5d1cac96085eca6dc4f1b9a INFO: start
Wrapping up: [4]
2019-05-24T19:51:19.077Z 15827 TID-gptgejawo MyJob JID-63b98e5eea80d8594cd5d7e2 INFO: done: 0.002 sec
2019-05-24T19:51:19.077Z 15827 TID-gptgej8f8 SecondaryJob JID-3b1e572fba828ed10d9c81c7 INFO: start
Wrapping up: [3]
2019-05-24T19:51:19.077Z 15827 TID-gptgej8f8 SecondaryJob JID-3b1e572fba828ed10d9c81c7 INFO: done: 0.001 sec
2019-05-24T19:51:19.076Z 15827 TID-gptgej8rg SecondaryJob JID-92e701ca2896b314bb304c91 INFO: start
Wrapping up: [2]
2019-05-24T19:51:19.078Z 15827 TID-gptgej8rg SecondaryJob JID-92e701ca2896b314bb304c91 INFO: done: 0.001 sec
2019-05-24T19:51:19.076Z 15827 TID-gptgej8xk SecondaryJob JID-7338f7c156be7b94353ab587 INFO: start
Wrapping up: [2]
2019-05-24T19:51:19.076Z 15827 TID-gptgej99s SecondaryJob JID-0ab401372a385d341923f55b INFO: start
Wrapping up: [1]
2019-05-24T19:51:19.077Z 15827 TID-gptgej9fw SecondaryJob JID-e5d1cac96085eca6dc4f1b9a INFO: done: 0.0 sec
2019-05-24T19:51:19.077Z 15827 TID-gptgej9s4 MyJob JID-5b0871c9b745362a6cda047a INFO: done: 0.002 sec
2019-05-24T19:51:19.077Z 15827 TID-gptgej8lc SecondaryJob JID-9408c4c062de490c8c4283e8 INFO: done: 0.0 sec
2019-05-24T19:51:19.078Z 15827 TID-gptgej8xk SecondaryJob JID-7338f7c156be7b94353ab587 INFO: done: 0.001 sec
2019-05-24T19:51:19.078Z 15827 TID-gptgej99s SecondaryJob JID-0ab401372a385d341923f55b INFO: done: 0.002 sec
^C2019-05-24T19:51:25.290Z 15827 TID-gptgbogs0 INFO: Shutting down
2019-05-24T19:51:25.290Z 15827 TID-gptgbogs0 INFO: Terminating quiet threads
2019-05-24T19:51:25.390Z 15827 TID-gptgbogs0 INFO: Pausing to allow threads to finish...
2019-05-24T19:51:28.393Z 15827 TID-gptgbogs0 INFO: Bye!
mperham commented 5 years ago

Just like Sidekiq, you have to add it in the Faktory.configure_worker block.

On May 24, 2019, at 12:52, Tim Tilberg notifications@github.com wrote:

I have a job that may conditionally en-queue other jobs when it's running. I have found that the Client Middleware is not evoked when the code is run from within the worker.

I would expect that the client middleware would still get used even when used from inside faktory-worker (since it's still using the Faktory client to push more jobs out).

Here's a small demo app:

require 'faktory_worker_ruby'

class LoudMiddleware def call(_) puts "BEFORE THE JOB!" puts "!!!!!!!!!!!!!!!\n" 3 yield puts "AFTER THE JOB!\n" puts "!!!!!!!!!!!!!!!\n"* 3

end end

Faktory.configure_client do |config| config.client_middleware do |chain| chain.add LoudMiddleware end end

class MyJob include Faktory::Job def perform *args 5.times {|i| SecondaryJob.perform_async i} puts "Doing #{args}" end end

class SecondaryJob include Faktory::Job def perform *args puts "Wrapping up: #{args}" end end

MyJob.perform_async 'some stuff' $ ruby app.rb

Enqueues a single job, and the middleware shouts as it pushes the job to faktory

$ faktory-worker -r ./app.rb

Also enqueues that job, since it's at the end, but does not shout.

Also, the processing of the job includes enqueing 5 more jobs, which also do not get middlewared.

ttilberg@timdesktop:~/dev/fkt_middleware$ ruby app.rb BEFORE THE JOB! !!!!!!!!!!!!!!! !!!!!!!!!!!!!!! !!!!!!!!!!!!!!! AFTER THE JOB! !!!!!!!!!!!!!!! !!!!!!!!!!!!!!! !!!!!!!!!!!!!!! ttilberg@timdesktop:~/dev/fkt_middleware$ faktory-worker -r ./app.rb 

                ,,,,
        ,,,,    |  |
        |  |    |  |
        |  |    |  |
        |  |,,~~'  '~,          ___       _
   ,,~~''   ,~~,      '~,      / __)     | |      _

,,'' ,, | | | _| | ____| | | | _ __ | ,~~, | | | | | (_ |_ | |/ | ) _ \ / __) | | | | | | | | | | | | | / | ( | || || | | | |_| | | || || || | |_| ___|| _) _)/|| \ | |__| (____/

2019-05-24T19:51:19.067Z 15827 TID-gptgbogs0 INFO: Running in ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-linux] 2019-05-24T19:51:19.067Z 15827 TID-gptgbogs0 INFO: See LICENSE and the LGPL-3.0 for licensing details. 2019-05-24T19:51:19.067Z 15827 TID-gptgbogs0 INFO: Starting processing, hit Ctrl-C to stop 2019-05-24T19:51:19.075Z 15827 TID-gptgejawo MyJob JID-63b98e5eea80d8594cd5d7e2 INFO: start 2019-05-24T19:51:19.075Z 15827 TID-gptgej9s4 MyJob JID-5b0871c9b745362a6cda047a INFO: start 2019-05-24T19:51:19.075Z 15827 TID-gptgej9m0 SecondaryJob JID-5e713e7cb88f0682cf001549 INFO: start Wrapping up: [0] 2019-05-24T19:51:19.075Z 15827 TID-gptgej9m0 SecondaryJob JID-5e713e7cb88f0682cf001549 INFO: done: 0.0 sec 2019-05-24T19:51:19.075Z 15827 TID-gptgej9fw SecondaryJob JID-f17c4ac4a1111af538bccbd8 INFO: start Wrapping up: [0] 2019-05-24T19:51:19.076Z 15827 TID-gptgej9fw SecondaryJob JID-f17c4ac4a1111af538bccbd8 INFO: done: 0.0 sec 2019-05-24T19:51:19.076Z 15827 TID-gptgej93o SecondaryJob JID-d75c75c75e66ca36b5ee6eea INFO: start Wrapping up: [1] 2019-05-24T19:51:19.076Z 15827 TID-gptgej93o SecondaryJob JID-d75c75c75e66ca36b5ee6eea INFO: done: 0.0 sec 2019-05-24T19:51:19.077Z 15827 TID-gptgej8lc SecondaryJob JID-9408c4c062de490c8c4283e8 INFO: start Doing ["do some stuff"] Doing ["do some stuff"] Wrapping up: [3] 2019-05-24T19:51:19.077Z 15827 TID-gptgej9m0 SecondaryJob JID-04a8ae11a5f3ba5669b02723 INFO: start Wrapping up: [4] 2019-05-24T19:51:19.077Z 15827 TID-gptgej9m0 SecondaryJob JID-04a8ae11a5f3ba5669b02723 INFO: done: 0.0 sec 2019-05-24T19:51:19.077Z 15827 TID-gptgej9fw SecondaryJob JID-e5d1cac96085eca6dc4f1b9a INFO: start Wrapping up: [4] 2019-05-24T19:51:19.077Z 15827 TID-gptgejawo MyJob JID-63b98e5eea80d8594cd5d7e2 INFO: done: 0.002 sec 2019-05-24T19:51:19.077Z 15827 TID-gptgej8f8 SecondaryJob JID-3b1e572fba828ed10d9c81c7 INFO: start Wrapping up: [3] 2019-05-24T19:51:19.077Z 15827 TID-gptgej8f8 SecondaryJob JID-3b1e572fba828ed10d9c81c7 INFO: done: 0.001 sec 2019-05-24T19:51:19.076Z 15827 TID-gptgej8rg SecondaryJob JID-92e701ca2896b314bb304c91 INFO: start Wrapping up: [2] 2019-05-24T19:51:19.078Z 15827 TID-gptgej8rg SecondaryJob JID-92e701ca2896b314bb304c91 INFO: done: 0.001 sec 2019-05-24T19:51:19.076Z 15827 TID-gptgej8xk SecondaryJob JID-7338f7c156be7b94353ab587 INFO: start Wrapping up: [2] 2019-05-24T19:51:19.076Z 15827 TID-gptgej99s SecondaryJob JID-0ab401372a385d341923f55b INFO: start Wrapping up: [1] 2019-05-24T19:51:19.077Z 15827 TID-gptgej9fw SecondaryJob JID-e5d1cac96085eca6dc4f1b9a INFO: done: 0.0 sec 2019-05-24T19:51:19.077Z 15827 TID-gptgej9s4 MyJob JID-5b0871c9b745362a6cda047a INFO: done: 0.002 sec 2019-05-24T19:51:19.077Z 15827 TID-gptgej8lc SecondaryJob JID-9408c4c062de490c8c4283e8 INFO: done: 0.0 sec 2019-05-24T19:51:19.078Z 15827 TID-gptgej8xk SecondaryJob JID-7338f7c156be7b94353ab587 INFO: done: 0.001 sec 2019-05-24T19:51:19.078Z 15827 TID-gptgej99s SecondaryJob JID-0ab401372a385d341923f55b INFO: done: 0.002 sec ^C2019-05-24T19:51:25.290Z 15827 TID-gptgbogs0 INFO: Shutting down 2019-05-24T19:51:25.290Z 15827 TID-gptgbogs0 INFO: Terminating quiet threads 2019-05-24T19:51:25.390Z 15827 TID-gptgbogs0 INFO: Pausing to allow threads to finish... 2019-05-24T19:51:28.393Z 15827 TID-gptgbogs0 INFO: Bye! — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

ttilberg commented 5 years ago

Thanks for your lightning fast response. I see now that regardless of the run configuration being used, I'm calling config.client_middleware -- so I'm able to hook into the correct action. I was previously assuming that using .configure_worker would be adding worker_middleware only, even though your example in the Wiki details both client and worker middleware getting attached.

Sometimes this code is called from within a worker process, but sometimes it is called from a Rake task to enqueue jobs. So, I end up with:

Faktory.configure_client do |config|
  config.client_middleware do |chain|
    chain.add LogFaktoryJobToTimber
  end
end

Faktory.configure_worker do |config|
  config.client_middleware do |chain|
    chain.add LogFaktoryJobToTimber
  end
end

I notice that the definition for both #configure_client and #configure_worker are yield self depending on how the process was started. It also appears that configuring it like this works:

Faktory.client_middleware do |chain|
  chain.add LoudMiddleware
end

Is there a specific reason to not do this style if the middleware is appropriate for both run configs?

I'd like to somehow improve this information as I spent a lot of time on it today wondering why my jobs weren't getting logged on Push from the Worker. I thought I understood the different between the two configuration methods, but clearly did not.

mperham commented 5 years ago

Yes, you can use that shortcut. I don’t document it because it does require you implicitly understand what’s happening in configuring the different processes.

On May 24, 2019, at 13:16, Tim Tilberg notifications@github.com wrote:

Thanks for your lightning fast response. I see now that regardless of the run configuration being used, I'm calling config.client_middleware -- so I'm able to hook into the correct action. I was previously assuming that using .configure_worker would be adding worker_middleware only, even though your example in the Wiki details both client and worker middleware getting attached.

Sometimes this code is called from within a worker process, but sometimes it is called from a Rake task to enqueue jobs. So, I end up with:

Faktory.configure_client do |config| config.client_middleware do |chain| chain.add LogFaktoryJobToTimber end end

Faktory.configure_worker do |config| config.client_middleware do |chain| chain.add LogFaktoryJobToTimber end end I notice that the definition for both #configure_client and #configure_worker are yield self depending on how the process was started. It also appears that configuring it like this works:

Faktory.client_middleware do |chain| chain.add LoudMiddleware end Is there a specific reason to not do this style if the middleware is appropriate for both run configs?

I'd like to somehow improve this information as I spent a lot of time on it today wondering why my jobs weren't getting logged on Push from the Worker. I thought I understood the different between the two configuration methods, but clearly did not.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.