Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

DeleteMessageBatchRequestEntry errors, extraneous logging #375

Closed
dotpyfe opened this issue Jun 1, 2017 · 9 comments
Closed

DeleteMessageBatchRequestEntry errors, extraneous logging #375

dotpyfe opened this issue Jun 1, 2017 · 9 comments

Comments

@dotpyfe
Copy link

dotpyfe commented Jun 1, 2017 •
edited
Loading

Currently using shoryuken v3.0.7, with the following shoryuken.yml:

delay: 25
concurrency: 25

starting it via:

bundle exec shoryuken --rails --config shoryuken.yml --require ./setup_shoryuken.rb

setup_shoryuken.rb looks like:

Shoryuken.configure_server do |_config|
  Application.shoryuken_queues.each_value do |q_cfg|
    Shoryuken.add_queue(q_cfg[:q_name], q_cfg[:q_weight])
  end
end

worker itself is defined as:

class ProcessTurkSqs < ActiveJob::Base
  self.queue_adapter = :shoryuken

  include Shoryuken::Worker

  shoryuken_options queue: QUEUE_NAME,
    auto_delete: true,
    batch: true,
    body_parser: :json

  def perform(_sqs_messages, bodies)
    ...
  end
end

In the logs, I see lots of AWS errors on batches with 0 items, as well as extraneous warnings about exponential backoff and auto extend visibility when neither of those options has been set:

2017-06-01T22:16:24Z 4900 TID-oxi322j90 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages INFO: started at 2017-06-01 22:16:24 +0000
2017-06-01T22:16:24Z 4900 TID-oxi322j90 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages WARN: Exponential backoff isn't supported for batch workers
2017-06-01T22:16:24Z 4900 TID-oxi322j90 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages WARN: Auto extend visibility isn't supported for batch workers
2017-06-01T22:16:24Z 4900 TID-oxi322j90 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages INFO: failed in: 75.42301599999999 ms
2017-06-01T22:16:24Z 4900 TID-oxi322j90 ERROR: There should be at least one DeleteMessageBatchRequestEntry in the request.
2017-06-01T22:16:24Z 4900 TID-oxi322j90 ERROR: /home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/plugins/raise_response_errors.rb:15:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/aws-sdk-core/plugins/idempotency_token.rb:18:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/aws-sdk-core/plugins/param_converter.rb:20:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/plugins/response_target.rb:21:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/request.rb:70:in `send_request'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/base.rb:207:in `block (2 levels) in define_operation_methods'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/queue.rb:22:in `delete_messages'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/auto_delete.rb:15:in `call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:96:in `block in invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/exponential_backoff_retry.rb:10:in `call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:96:in `block in invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/timing.rb:14:in `block in call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/logging.rb:21:in `with_context'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/timing.rb:8:in `call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:96:in `block in invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:99:in `invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/processor.rb:13:in `process'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/manager.rb:97:in `block in assign'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
@phstc
Copy link
Collaborator

phstc commented Jun 1, 2017 •
edited
Loading

Hi @dotpyfe

I couldn't test it yet. But just something that feels strange is combining shoryuken_options with ActiveJob::Base. I don't think shoryuken_options works with shoryuken_options, since ActiveJob uses a wrapper worker.

ActiveJob workers shouldn't include Shoryuken::Worker or use shoryuken_options, they should be like this. Not sure if that's the issue though, it's just something that caught my attention.

@phstc
Copy link
Collaborator

phstc commented Jun 1, 2017 •
edited
Loading

@dotpyfe could you try to remove < ActiveJob::Base and test it as a regular worker? This should also change the way you enqueue messages, you should use perform_async instead.

@dotpyfe
Copy link
Author

dotpyfe commented Jun 2, 2017

i tried the following worker variant:

class ProcessTurkSqs
  include Shoryuken::Worker

  shoryuken_options queue: QUEUE_NAME,
    auto_delete: true,
    batch: true,
    body_parser: :json

  def perform(_sqs_messages, bodies)
    ...
  end
end

i get the same output,

$ bundle exec shoryuken --rails --config shoryuken.yml --require ./setup_shoryuken.rb
2017-06-02T15:59:30Z 31168 TID-oswblzjpk INFO: Starting
2017-06-02T15:59:50Z 31168 TID-oswdenmrc ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages INFO: started at 2017-06-02 15:59:50 +0000
2017-06-02T15:59:50Z 31168 TID-oswdenmrc ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages WARN: Exponential backoff isn't supported for batch workers
2017-06-02T15:59:50Z 31168 TID-oswdenmrc ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages WARN: Auto extend visibility isn't supported for batch workers
2017-06-02T15:59:50Z 31168 TID-oswdenmrc ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages INFO: failed in: 35.834625 ms
2017-06-02T15:59:50Z 31168 TID-oswdenmrc ERROR: There should be at least one DeleteMessageBatchRequestEntry in the request.
2017-06-02T15:59:50Z 31168 TID-oswdenmrc ERROR: /home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/plugins/raise_response_errors.rb:15:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/aws-sdk-core/plugins/idempotency_token.rb:18:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/aws-sdk-core/plugins/param_converter.rb:20:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/plugins/response_target.rb:21:in `call'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/request.rb:70:in `send_request'
/home/application/.gem/ruby/2.4.0/gems/aws-sdk-core-2.8.14/lib/seahorse/client/base.rb:207:in `block (2 levels) in define_operation_methods'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/queue.rb:22:in `delete_messages'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/auto_delete.rb:15:in `call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:96:in `block in invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/exponential_backoff_retry.rb:10:in `call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:96:in `block in invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/timing.rb:14:in `block in call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/logging.rb:21:in `with_context'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/server/timing.rb:8:in `call'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:96:in `block in invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/middleware/chain.rb:99:in `invoke'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/processor.rb:13:in `process'
/home/application/.gem/ruby/2.4.0/gems/shoryuken-3.0.7/lib/shoryuken/manager.rb:97:in `block in assign'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/home/application/.gem/ruby/2.4.0/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'

@dotpyfe
Copy link
Author

dotpyfe commented Jun 2, 2017

when i switched to manually deleting the sqs messages, it still has those extra prints:

2017-06-02T16:24:39Z 2604 TID-otskw8fb8 INFO: Starting
2017-06-02T16:24:59Z 2604 TID-otsmosyq0 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages INFO: started at 2017-06-02 16:24:59 +0000
2017-06-02T16:24:59Z 2604 TID-otsmosyq0 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages WARN: Exponential backoff isn't supported for batch workers
2017-06-02T16:24:59Z 2604 TID-otsmosyq0 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages WARN: Auto extend visibility isn't supported for batch workers
2017-06-02T16:24:59Z 2604 TID-otsmosyq0 ProcessTurkSqs/squatch_mechanical_turk/batch-with-0-messages INFO: completed in: 0.343295 ms

phstc pushed a commit that referenced this issue Jun 2, 2017
Fix #375
0419cd1
@phstc phstc mentioned this issue Jun 2, 2017
Merged
@phstc
Copy link
Collaborator

phstc commented Jun 2, 2017 •
edited
Loading

@dotpyfe found the bug. I'm working in the fix #376.

@dotpyfe
Copy link
Author

dotpyfe commented Jun 2, 2017

awesome, thanks for the quick work! are the auto expire and exponential backoff messages safe to ignore? or is that indicative of a different issue?

@phstc
Copy link
Collaborator

phstc commented Jun 2, 2017

@dotpyfe thanks for checking that. They are safe to ignore, since it is ignoring only if exponential backoff and auto expire are off. Like, it does not need to show a warning for something that isn't on.

@dotpyfe
Copy link
Author

dotpyfe commented Jun 2, 2017

gotcha - i tested your hotfix locally and it seems to solve the issue

@phstc phstc closed this as completed in #376 Jun 2, 2017
phstc added a commit that referenced this issue Jun 2, 2017
@phstc
Merge pull request #376 from phstc/hotfix/fix-batch-delete-375
d7fa44c 
Fix miss handling empty batch fetches 

Fix #375
@phstc
Copy link
Collaborator

phstc commented Jun 2, 2017

@dotpyfe awesome, thanks for testing it 🍻

v3.0.8 is out with your fix 🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@phstc @dotpyfe