search

contribsys / faktory

Language-agnostic persistent background job server
https://contribsys.com/faktory/
Other
5.66k stars 226 forks source link

Faktory ENT staging env doesnt seem to be set correctly by FAKTORY_ENV environment variable. #455

Closed Deekor closed 7 months ago

Deekor commented 7 months ago

When FAKTORY_ENV is set to staging faktory doesn't print any logs stating it is actually in staging mode, we had assumed it was working fine until we received the same error in Production and Staging at the same time:

ConnectionPool::TimeoutError: Waited 1 sec, 0/5 available.

In the backtrace, the error occured when trying to push a job to faktory which makes me think both our Prod and Staging faktory instances share the same connection limit.

mperham commented 7 months ago

Logging about staging is on main but has not been released.

It sounds like that error is with faktory_worker_ruby, not Faktory itself.

mperham commented 7 months ago

Can you please include the full backtrace and any initializer code for faktory_worker_ruby?

Deekor commented 7 months ago

We have no initializer code.

Backtrace:

[GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool/timed_stack.rb:77 :in `block (2 levels) in pop`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool/timed_stack.rb:69 :in `loop`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool/timed_stack.rb:69 :in `block in pop`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool/timed_stack.rb:68 :in `synchronize`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool/timed_stack.rb:68 :in `pop`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool.rb:125 :in `checkout`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool.rb:107 :in `block in with`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool.rb:106 :in `handle_interrupt`
  [GEM_ROOT]/gems/connection_pool-2.4.1/lib/connection_pool.rb:106 :in `with`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/job.rb:117 :in `block in client_push`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/middleware/chain.rb:129 :in `block in invoke`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/middleware/batch.rb:14 :in `call`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/middleware/chain.rb:131 :in `block in invoke`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/middleware/chain.rb:134 :in `invoke`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/job.rb:116 :in `client_push`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/job.rb:80 :in `perform_async`
  [GEM_ROOT]/gems/faktory_worker_ruby-1.3.0/lib/faktory/job.rb:132 :in `perform_async`
 [PROJECT_ROOT]/app/services/sendgrid/webhooks/handler.rb:24 :in `block in process_webhook`
 [PROJECT_ROOT]/app/services/sendgrid/webhooks/handler.rb:12 :in `each`
 [PROJECT_ROOT]/app/services/sendgrid/webhooks/handler.rb:12 :in `process_webhook`
 [PROJECT_ROOT]/app/controllers/webhooks_controller.rb:8 :in `sendgrid`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal/basic_implicit_render.rb:6 :in `send_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/abstract_controller/base.rb:215 :in `process_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal/rendering.rb:165 :in `process_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/abstract_controller/callbacks.rb:234 :in `block in process_action`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/callbacks.rb:99 :in `run_callbacks`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/abstract_controller/callbacks.rb:233 :in `process_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal/rescue.rb:23 :in `process_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal/instrumentation.rb:67 :in `block in process_action`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/notifications.rb:206 :in `block in instrument`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/notifications/instrumenter.rb:24 :in `instrument`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/notifications.rb:206 :in `instrument`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal/instrumentation.rb:66 :in `process_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal/params_wrapper.rb:259 :in `process_action`
  [GEM_ROOT]/gems/activerecord-7.0.8/lib/active_record/railties/controller_runtime.rb:27 :in `process_action`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/abstract_controller/base.rb:151 :in `process`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal.rb:188 :in `dispatch`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_controller/metal.rb:251 :in `dispatch`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/routing/route_set.rb:49 :in `dispatch`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/routing/route_set.rb:32 :in `serve`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/journey/router.rb:50 :in `block in serve`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/journey/router.rb:32 :in `each`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/journey/router.rb:32 :in `serve`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/routing/route_set.rb:852 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/rack/browser_monitoring.rb:38 :in `traced_call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/session/abstract/id.rb:266 :in `context`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/session/abstract/id.rb:260 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/cookies.rb:704 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/etag.rb:27 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/conditional_get.rb:40 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/head.rb:12 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/callbacks.rb:27 :in `block in call`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/callbacks.rb:99 :in `run_callbacks`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/callbacks.rb:26 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/debug_exceptions.rb:28 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/show_exceptions.rb:29 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/railties-7.0.8/lib/rails/rack/logger.rb:40 :in `call_app`
  [GEM_ROOT]/gems/railties-7.0.8/lib/rails/rack/logger.rb:25 :in `block in call`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/tagged_logging.rb:99 :in `block in tagged`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/tagged_logging.rb:37 :in `tagged`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/tagged_logging.rb:99 :in `tagged`
  [GEM_ROOT]/gems/railties-7.0.8/lib/rails/rack/logger.rb:25 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/remote_ip.rb:93 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/request_id.rb:26 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/runtime.rb:22 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/activesupport-7.0.8/lib/active_support/cache/strategy/local_cache_middleware.rb:29 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/executor.rb:14 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-2.2.8/lib/rack/sendfile.rb:110 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/actionpack-7.0.8/lib/action_dispatch/middleware/host_authorization.rb:131 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/rack-cors-2.0.1/lib/rack/cors.rb:102 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/railties-7.0.8/lib/rails/engine.rb:530 :in `call`
  [GEM_ROOT]/gems/newrelic_rpm-9.6.0/lib/new_relic/agent/instrumentation/middleware_tracing.rb:99 :in `call`
  [GEM_ROOT]/gems/puma-5.6.7/lib/puma/configuration.rb:252 :in `call`
  [GEM_ROOT]/gems/puma-5.6.7/lib/puma/request.rb:77 :in `block in handle_request`
  [GEM_ROOT]/gems/puma-5.6.7/lib/puma/thread_pool.rb:340 :in `with_force_shutdown`
  [GEM_ROOT]/gems/puma-5.6.7/lib/puma/request.rb:76 :in `handle_request`
  [GEM_ROOT]/gems/puma-5.6.7/lib/puma/server.rb:443 :in `process_client`
  [GEM_ROOT]/gems/puma-5.6.7/lib/puma/thread_pool.rb:147 :in `block in spawn_thread`
mperham commented 7 months ago

You're running in puma so the Faktory client defaults to a pool of 5 connections. I'm assuming you were doing some load testing and had many puma threads pushing a lot of jobs to Faktory at the same time. It has nothing to do with staging.

I've increased the default pool size from 5 to 20. Pools are lazy so it will only create 20 if you actually need that many. You can run FWR's main branch to pick up that change and verify it fixes your issue.

Deekor commented 7 months ago

It was a normal traffic event for us, but we do process a ton of traffic and a lot of that traffic pushes jobs to faktory. The weird things is the staging ENV throwing the exact same error at the exact same time.. it shouldnt have had anywhere close to the same traffic as prod.