search

Freika / dawarich

Self-hosted alternative to Google Location History (Google Maps Timeline)
https://dawarich.app
GNU Affero General Public License v3.0
616 stars 12 forks source link

Sidekiq `ActiveRecord::ConnectionTimeoutError` error during reverse geocoding phase of import #96

Open tigattack opened 4 days ago

tigattack commented 4 days ago

Describe the bug

During the reverse geocoding phase of the import process, I'm seeing a lot of ActiveRecord::ConnectionTimeoutError errors from Sidekiq. The large majority of the reverse geocoding jobs appear to succeed without encountering this error, but it still occurs roughly once every few minutes.

I'm importing a 1.6GB Records.json file from my Google Takeout with approximately 3.6 million geopoints.

Version

0.8.0

To Reproduce

I can't guarantee this will reproduce it as I'm not sure exactly what the cause is, but it appears to be consistent for me:

  1. Run import
  2. Wait for geopoints import to finish and reverse geocoding to begin
  3. After a while the errors mentioned above begin to appear.

Expected behavior

I would expect this error to not occur.

Screenshots N/A.

Logs

Logs from dawarich_app are not relevant but here is a snippet of an occurence of the error from dawarich_sidekiq:

2024-07-01T09:17:39.127Z pid=38 tid=17mrxu class=ReverseGeocodingJob jid=d8d9373f94d8df6a9d906d37 ERROR: Error performing ReverseGeocodingJob (Job ID: 42690df5-61bc-44db-ac8e-40dd3e14fd68) from Sidekiq(reverse_geocoding) in 5500.11ms: ActiveRecord::ConnectionTimeoutError (could not obtain a connection from the pool within 5.000 seconds (waited 5.496 seconds); all pooled connections were in use):
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:128:in `block in wait_poll'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `loop'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:117:in `wait_poll'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:78:in `internal_poll'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:204:in `internal_poll'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `block in poll'
/usr/local/lib/ruby/3.2.0/monitor.rb:202:in `synchronize'
/usr/local/lib/ruby/3.2.0/monitor.rb:202:in `mon_synchronize'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:82:in `synchronize'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool/queue.rb:73:in `poll'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:663:in `acquire_connection'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:353:in `checkout'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:182:in `connection'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/connection_handler.rb:246:in `retrieve_connection'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_handling.rb:287:in `retrieve_connection'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/connection_handling.rb:254:in `connection'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/core.rb:377:in `cached_find_by_statement'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/core.rb:419:in `cached_find_by'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/core.rb:252:in `find'
/var/app/app/jobs/reverse_geocoding_job.rb:9:in `perform'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:69:in `block in _perform_job'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/i18n-1.14.5/lib/i18n.rb:351:in `with_locale'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/core_ext/time/zones.rb:65:in `use_zone'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:68:in `_perform_job'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:32:in `_perform_job'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:52:in `perform_now'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:26:in `block in perform_now'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/railties/job_runtime.rb:13:in `block in instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:40:in `block in instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `block in instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:39:in `instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activerecord-7.1.3.4/lib/active_record/railties/job_runtime.rb:11:in `instrument'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/instrumentation.rb:26:in `perform_now'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/logging.rb:18:in `block in perform_now'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:135:in `block in tagged'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:39:in `tagged'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/tagged_logging.rb:135:in `tagged'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/broadcast_logger.rb:240:in `method_missing'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/logging.rb:25:in `tag_logger'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/logging.rb:18:in `perform_now'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:30:in `block in execute'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/railtie.rb:67:in `block (4 levels) in <class:Railtie>'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:77:in `block in wrap'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:88:in `wrap'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:74:in `wrap'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/railtie.rb:66:in `block (3 levels) in <class:Railtie>'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `instance_exec'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/execution.rb:28:in `execute'
/var/app/vendor/bundle/ruby/3.2.0/gems/activejob-7.1.3.4/lib/active_job/queue_adapters/sidekiq_adapter.rb:70:in `perform'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:210:in `execute_job'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:180:in `block (4 levels) in process'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/middleware/chain.rb:180:in `traverse'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/metrics/tracking.rb:26:in `track'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/metrics/tracking.rb:126:in `call'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/middleware/chain.rb:182:in `traverse'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/middleware/chain.rb:173:in `invoke'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:179:in `block (3 levels) in process'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:140:in `block (6 levels) in dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/job_retry.rb:113:in `local'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:139:in `block (5 levels) in dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/rails.rb:16:in `block in call'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:77:in `block in wrap'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
/var/app/vendor/bundle/ruby/3.2.0/gems/activesupport-7.1.3.4/lib/active_support/reloader.rb:74:in `wrap'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/rails.rb:15:in `call'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:135:in `block (4 levels) in dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:271:in `stats'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:130:in `block (3 levels) in dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/job_logger.rb:13:in `call'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:129:in `block (2 levels) in dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/job_retry.rb:80:in `global'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:128:in `block in dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/job_logger.rb:39:in `prepare'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:127:in `dispatch'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:178:in `block (2 levels) in process'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:177:in `handle_interrupt'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:177:in `block in process'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:176:in `handle_interrupt'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:176:in `process'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:82:in `process_one'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/processor.rb:72:in `run'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/component.rb:10:in `watchdog'
/var/app/vendor/bundle/ruby/3.2.0/gems/sidekiq-7.2.4/lib/sidekiq/component.rb:19:in `block in safe_thread'
2024-07-01T09:17:39.421Z pid=38 tid=17mrxu class=ReverseGeocodingJob jid=d8d9373f94d8df6a9d906d37 elapsed=6.608 INFO: fail
2024-07-01T09:17:39.520Z pid=38 tid=17mrxu WARN: {"context":"Job raised exception","job":{"retry":true,"queue":"reverse_geocoding","wrapped":"ReverseGeocodingJob","args":[{"job_class":"ReverseGeocodingJob","job_id":"42690df5-61bc-44db-ac8e-40dd3e14fd68","provider_job_id":null,"queue_name":"reverse_geocoding","priority":null,"arguments":[44988],"executions":0,"exception_executions":{},"locale":"en","timezone":"Europe/London","enqueued_at":"2024-06-28T14:44:27.550872135Z","scheduled_at":null}],"class":"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper","jid":"d8d9373f94d8df6a9d906d37","created_at":1719585867.5510216,"enqueued_at":1719585867.5511196}}
2024-07-01T09:17:39.521Z pid=38 tid=17mrxu WARN: ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.496 seconds); all pooled connections were in use
2024-07-01T09:17:39.522Z pid=38 tid=17mrxu WARN: app/jobs/reverse_geocoding_job.rb:9:in `perform'
2024-07-01T09:17:40.027Z pid=38 tid=17mrzq class=ReverseGeocodingJob jid=e28053348c47940095e632c0 INFO: start
Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).

Additional context

While the following error does not appear to cause the error above, I thought it worth mentioning as it occurs for almost all reverse geocoding jobs:

Geocoding API not responding fast enough (use Geocoder.configure(:timeout => ...) to set limit).
Freika commented 3 days ago

@tigattack I'd suggest to lower the value of BACKGROUND_PROCESSING_CONCURRENCY env var to something between 10-30. Sidekiq creates an excessive amount of requests to PostgreSQL database + Nominatim can't handle your reverse geocoding request as fast as your instance sends them to it

tigattack commented 3 days ago

Thanks for the tip @Freika, though I have the processing concurrency set to 10 already. I actually had intended to increase it from the default but hadn't got round to it yet.

Parzival0x commented 22 hours ago

I am experiencing the same issue as tigaatack while importing a large Records.json file. I have just lowered the processing concurrency to 10 (from 30) and this has seemed to resolve the issue for me, but I have almost 500,000 failed jobs in Sidekiq. I'm assuming this number is related to the failed reverse geocodings, but I may be wrong, is there anyway to retry these failed jobs?