Zammad-scheduler can't get connection from the pool

[iimrudy]

Infos:

• Used Zammad version: 6.3.1
• Used Zammad installation type: docker compose
• Operating system: Ubuntu 22.04.4 LTS x86_64
• Browser + version: Microsoft Edge Version 124.0.2478.105 (Official build) (64-bit)

Expected behavior:

• zammad-scheduler container should run all background jobs fine

Actual behavior:

• zammad-scheduler is skipping some tasks
  
  

The logs of the scheduler keep spamming

I, [2024-05-17T06:59:15.782098#25-6140]  INFO -- : ProcessScheduledJobs running...
I, [2024-05-17T06:59:15.785503#25-6140]  INFO -- : Running job thread for 'Check channels.' (Channel.fetch) status is: sleep
I, [2024-05-17T06:59:15.785582#25-6140]  INFO -- : Running job thread for 'Process ticket escalations.' (Ticket.process_escalation) status is: sleep
I, [2024-05-17T06:59:15.785682#25-6140]  INFO -- : Running job thread for 'Process pending tickets.' (Ticket.process_pending) status is: sleep
I, [2024-05-17T06:59:15.785843#25-6140]  INFO -- : Running job thread for 'Process automatic ticket unassignments.' (Ticket.process_auto_unassign) status is: sleep
I, [2024-05-17T06:59:15.785977#25-6140]  INFO -- : Running job thread for 'Generate 'Session' data.' (Sessions.jobs) status is: sleep
I, [2024-05-17T06:59:15.786108#25-6140]  INFO -- : Running job thread for 'Check 'Channel' streams.' (Channel.stream) status is: sleep
I, [2024-05-17T06:59:15.786231#25-6140]  INFO -- : Running job thread for 'Update exchange oauth 2 token.' (ExternalCredential::Exchange.refresh_token) status is: sleep
I, [2024-05-17T06:59:15.786364#25-6140]  INFO -- : Running job thread for 'Execute import jobs.' (ImportJob.start_registered) status is: sleep
I, [2024-05-17T06:59:15.786706#25-6140]  INFO -- : Running job thread for 'Close chat sessions where participants are offline.' (Chat.cleanup_close) status is: sleep
I, [2024-05-17T06:59:15.786762#25-6140]  INFO -- : Running job thread for 'Clean up dead sessions.' (SessionTimeoutJob.perform_now) status is: sleep
I, [2024-05-17T06:59:15.787540#25-6140]  INFO -- : Running job thread for 'Execute planned jobs.' (Job.run) status is: sleep
I, [2024-05-17T06:59:15.787605#25-6140]  INFO -- : Running job thread for 'Generate user-based stats.' (Stats.generate) status is: sleep
I, [2024-05-17T06:59:15.787792#25-6140]  INFO -- : Running job thread for 'Delete old online notification entries.' (OnlineNotification.cleanup) status is: sleep
I, [2024-05-17T06:59:15.788544#25-6140]  INFO -- : Running job thread for 'Handle data privacy tasks.' (DataPrivacyTaskJob.perform_now) status is: sleep
E, [2024-05-17T06:59:16.651694#25-5237580] ERROR -- : execute Stats.generate (try_count 6) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use> in: 5.000768342 seconds.
E, [2024-05-17T06:59:16.732770#25-5239620] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use>
I, [2024-05-17T06:59:16.813592#25-3839260]  INFO -- : execute Channel.fetch (try_count 3)...
I, [2024-05-17T06:59:16.826129#25-3839260]  INFO -- : fetching imap (imap.gmail.com/support@securcube.net port=993,ssl=true,starttls=false,folder=Inbox,keep_on_server=true,auth_type=XOAUTH2)
E, [2024-05-17T06:59:17.651864#25-5237600] ERROR -- : execute DataPrivacyTaskJob.perform_now (try_count 6) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use> in: 5.000585384 seconds.
I, [2024-05-17T06:59:17.783445#25-3839260]  INFO -- :  - no message
I, [2024-05-17T06:59:17.802721#25-3839260]  INFO -- : ended Channel.fetch took: 0.996170182 seconds.
E, [2024-05-17T06:59:20.534226#25-5231460] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use>
E, [2024-05-17T06:59:20.534667#25-5231460] ERROR -- : Failed to run ExternalCredential::Exchange.refresh_token after 11 tries.
E, [2024-05-17T06:59:20.649142#25-5237540] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use>
E, [2024-05-17T06:59:21.633290#25-5235520] ERROR -- : execute Ticket.process_escalation (try_count 7) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use> in: 5.001821519 seconds.
E, [2024-05-17T06:59:21.652469#25-5237580] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use>
E, [2024-05-17T06:59:22.652610#25-5237600] ERROR -- : Can't reconnect to database #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use>
E, [2024-05-17T06:59:22.686346#25-5237620] ERROR -- : execute OnlineNotification.cleanup (try_count 5) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use> in: 5.000724933 seconds.
E, [2024-05-17T06:59:22.754463#25-5241640] ERROR -- : execute Ticket.process_pending (try_count 2) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use> in: 5.000718398 seconds.
E, [2024-05-17T06:59:24.734441#25-5239620] ERROR -- : execute Chat.cleanup_close (try_count 3) exited with error #<ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use> in: 5.000779462 seconds.
E, [2024-05-17T06:59:25.535652#25-5231460] ERROR -- : could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use (ActiveRecord::ConnectionTimeoutError)
lib/background_services/service/process_scheduled_jobs/job_executor.rb:95:in `retry_limit_reached'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:82:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:88:in `retry_execution'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:34:in `rescue in execute'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:24:in `execute'
lib/background_services/service/process_scheduled_jobs/job_executor/one_time.rb:6:in `run'
lib/background_services/service/process_scheduled_jobs/job_executor.rb:10:in `run'
lib/background_services/service/process_scheduled_jobs/manager.rb:84:in `block in start_in_thread'
lib/application_handle_info.rb:19:in `use'
lib/background_services/service/process_scheduled_jobs/manager.rb:82:in `start_in_thread'
lib/background_services/service/process_scheduled_jobs/manager.rb:73:in `block (2 levels) in start'
lib/background_services/service/process_scheduled_jobs/manager.rb:72:in `block in start'
I, [2024-05-17T06:59:25.799013#25-6140]  INFO -- : ProcessScheduledJobs running...

This is my env for optimizations

WEB_CONCURRENCY=5
ZAMMAD_WEB_CONCURRENCY=5
ZAMMAD_SESSION_JOBS_CONCURRENT=1
ZAMMAD_PROCESS_SCHEDULED_JOBS_WORKERS=1
ZAMMAD_PROCESS_DELAYED_JOBS_WORKERS=1

how can i address this issue?

Thanks

[MrGeneration]

Closing as a duplicate in favor of

Scheduler fails with "ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use>"

Thanks, I’m not exactly familiar with how all max thread limits affect each other. So I reverted all environment settings back to default, increased the postgresql limit, and the issue still shows. What could be the next debugging step, or what should I try now? PS. From what I’ve read (link below), this issue has likely not to do with postgresql but with rails configuration. That’s why I tried upping/changing the rails thread limit environment variables. https :// judoscale .com/blog/active…