manyfold icon indicating copy to clipboard operation
manyfold copied to clipboard
verified publisher icon manyfold3d

Database Connection Pooling Issues

Open aneurinprice opened this issue 1 year ago • 5 comments

Describe the bug Whilst merging some models, The application crashes and the logs fill with the following error messages.

18:21:44 default_worker.1     | 2024-09-23T18:21:44.128Z pid=131 tid=18bf class=ModelScanJob jid=9963d78a2ddf9b1db0c5080a elapsed=0.005 INFO: fail
18:21:44 default_worker.1     | 2024-09-23T18:21:44.128Z pid=131 tid=18bf WARN: {"context":"Job raised exception","job":{"retry":10,"queue":"scan","wrapped":"ModelScanJob","args":[{"job_class":"ModelScanJob","job_id":"114a199e-44c3-48b5-bc13-3da5425078b6","provider_job_id":null,"queue_name":"scan","priority":null,"arguments":[46,{"include_all_subfolders":false,"_aj_ruby2_keywords":["include_all_subfolders"]}],"executions":0,"exception_executions":{},"locale":"en","timezone":"UTC","enqueued_at":"2024-09-23T18:18:33.907184846Z","scheduled_at":null}],"class":"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper","jid":"9963d78a2ddf9b1db0c5080a","created_at":1727115513.9072263,"enqueued_at":1727115704.1229796,"error_message":"Couldn't find Model with 'id'=46","error_class":"ActiveRecord::RecordNotFound","failed_at":1727115704.1280274,"retry_count":3,"retried_at":1727115601.4023163,"processor":"manyfold-0:131"}}
18:21:44 default_worker.1     | 2024-09-23T18:21:44.128Z pid=131 tid=18bf WARN: ActiveRecord::RecordNotFound: Couldn't find Model with 'id'=46
18:21:44 default_worker.1     | 2024-09-23T18:21:44.129Z pid=131 tid=18bf WARN: app/jobs/model_scan_job.rb:21:in `perform'
18:21:53 rails.1              | I, [2024-09-23T18:21:53.767935 #202]  INFO -- : [75904b7f22c549c8101eb472c4fe0dd0] {"method":"GET","path":"/models","format":"html","controller":"ModelsController","action":"index","status":500,"allocations":264,"duration":5000.71,"view":0.0,"db":0.0,"@timestamp":"2024-09-23T18:21:53.767Z","@version":"1","message":"[500] GET /models (ModelsController#index)"}
18:21:53 rails.1              | F, [2024-09-23T18:21:53.768937 #202] FATAL -- : [75904b7f22c549c8101eb472c4fe0dd0]   
18:21:53 rails.1              | [75904b7f22c549c8101eb472c4fe0dd0] ActiveRecord::ConnectionTimeoutError (could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use):
18:21:53 rails.1              | [75904b7f22c549c8101eb472c4fe0dd0]   
18:21:53 rails.1              | [75904b7f22c549c8101eb472c4fe0dd0] app/models/library.rb:28:in `block in <class:Library>'
18:21:53 rails.1              | [75904b7f22c549c8101eb472c4fe0dd0] app/controllers/application_controller.rb:61:in `configure_content_security_policy'
18:22:12 default_worker.1     | 2024-09-23T18:22:12.681Z pid=131 tid=m86f class=ModelScanJob jid=e36bf9cfcb19468f71c70b19 INFO: start
18:22:12 default_worker.1     | I, [2024-09-23T18:22:12.682068 #131]  INFO -- : [ActiveJob] [ModelScanJob] [30caeab1-bf94-4791-b982-9790e22576c2] Performing ModelScanJob (Job ID: 30caeab1-bf94-4791-b982-9790e22576c2) from Sidekiq(scan) enqueued at 2024-09-23T18:18:34.748236023Z with arguments: 64, {:include_all_subfolders=>false}
18:22:12 default_worker.1     | W, [2024-09-23T18:22:12.683270 #131]  WARN -- : [ActiveJob] [ModelScanJob] [30caeab1-bf94-4791-b982-9790e22576c2] Scoped order is ignored, it's forced to be batch order.
18:22:12 default_worker.1     | E, [2024-09-23T18:22:12.686168 #131] ERROR -- : [ActiveJob] [ModelScanJob] [30caeab1-bf94-4791-b982-9790e22576c2] Error performing ModelScanJob (Job ID: 30caeab1-bf94-4791-b982-9790e22576c2) from Sidekiq(scan) in 4.16ms: ActiveRecord::RecordNotFound (Couldn't find Model with 'id'=64):
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.4/lib/active_record/core.rb:253:in `find'
18:22:12 default_worker.1     | /usr/src/app/app/jobs/model_scan_job.rb:21:in `perform'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/execution.rb:68:in `block in _perform_job'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/i18n-1.14.6/lib/i18n.rb:353:in `with_locale'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `instance_exec'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/core_ext/time/zones.rb:65:in `use_zone'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `instance_exec'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/execution.rb:67:in `_perform_job'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/instrumentation.rb:32:in `_perform_job'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/execution.rb:51:in `perform_now'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/instrumentation.rb:26:in `block in perform_now'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.4/lib/active_record/railties/job_runtime.rb:13:in `block in instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/instrumentation.rb:40:in `block in instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/notifications.rb:206:in `block in instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/notifications.rb:206:in `instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/instrumentation.rb:39:in `instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activerecord-7.1.4/lib/active_record/railties/job_runtime.rb:11:in `instrument'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/instrumentation.rb:26:in `perform_now'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/logging.rb:18:in `block in perform_now'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/tagged_logging.rb:139:in `block in tagged'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/tagged_logging.rb:39:in `tagged'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/tagged_logging.rb:139:in `tagged'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/broadcast_logger.rb:241:in `method_missing'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/logging.rb:25:in `tag_logger'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/logging.rb:18:in `perform_now'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/execution.rb:29:in `block in execute'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/railtie.rb:67:in `block (4 levels) in <class:Railtie>'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/reloader.rb:77:in `block in wrap'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/execution_wrapper.rb:88:in `wrap'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/reloader.rb:74:in `wrap'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/railtie.rb:66:in `block (3 levels) in <class:Railtie>'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `instance_exec'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:130:in `block in run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/callbacks.rb:141:in `run_callbacks'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/execution.rb:27:in `execute'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activejob-7.1.4/lib/active_job/queue_adapters/sidekiq_adapter.rb:70:in `perform'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:220:in `execute_job'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:185:in `block (4 levels) in process'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:180:in `traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/job/interrupt_handler.rb:9:in `call'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:182:in `traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/metrics/tracking.rb:26:in `track'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/metrics/tracking.rb:134:in `call'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:182:in `traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:183:in `block in traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-failures-1.0.4/lib/sidekiq/failures/middleware.rb:9:in `call'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:182:in `traverse'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/middleware/chain.rb:173:in `invoke'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:184:in `block (3 levels) in process'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:145:in `block (6 levels) in dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/job_retry.rb:118:in `local'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:144:in `block (5 levels) in dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/rails.rb:16:in `block in call'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/reloader.rb:77:in `block in wrap'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/execution_wrapper.rb:92:in `wrap'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/activesupport-7.1.4/lib/active_support/reloader.rb:74:in `wrap'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/rails.rb:15:in `call'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:139:in `block (4 levels) in dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:281:in `stats'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:134:in `block (3 levels) in dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/job_logger.rb:23:in `call'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:133:in `block (2 levels) in dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/job_retry.rb:85:in `global'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:132:in `block in dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/job_logger.rb:50:in `prepare'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:131:in `dispatch'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:183:in `block (2 levels) in process'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:182:in `handle_interrupt'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:182:in `block in process'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:181:in `handle_interrupt'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:181:in `process'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:86:in `process_one'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/processor.rb:76:in `run'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/component.rb:10:in `watchdog'
18:22:12 default_worker.1     | /usr/src/app/vendor/bundle/ruby/3.3.0/gems/sidekiq-7.3.2/lib/sidekiq/component.rb:19:in `block in safe_thread'
18:22:12 default_worker.1     | 2024-09-23T18:22:12.686Z pid=131 tid=m86f class=ModelScanJob jid=e36bf9cfcb19468f71c70b19 elapsed=0.005 INFO: fail
18:22:12 default_worker.1     | 2024-09-23T18:22:12.686Z pid=131 tid=m86f WARN: {"context":"Job raised exception","job":{"retry":10,"queue":"scan","wrapped":"ModelScanJob","args":[{"job_class":"ModelScanJob","job_id":"30caeab1-bf94-4791-b982-9790e22576c2","provider_job_id":null,"queue_name":"scan","priority":null,"arguments":[64,{"include_all_subfolders":false,"_aj_ruby2_keywords":["include_all_subfolders"]}],"executions":0,"exception_executions":{},"locale":"en","timezone":"UTC","enqueued_at":"2024-09-23T18:18:34.748236023Z","scheduled_at":null}],"class":"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper","jid":"e36bf9cfcb19468f71c70b19","created_at":1727115514.7482872,"enqueued_at":1727115732.6811464,"error_message":"Couldn't find Model with 'id'=64","error_class":"ActiveRecord::RecordNotFound","failed_at":1727115732.6862345,"retry_count":3,"retried_at":1727115607.935616,"processor":"manyfold-0:131"}}
18:22:12 default_worker.1     | 2024-09-23T18:22:12.686Z pid=131 tid=m86f WARN: ActiveRecord::RecordNotFound: Couldn't find Model with 'id'=64
18:22:12 default_worker.1     | 2024-09-23T18:22:12.687Z pid=131 tid=m86f WARN: app/jobs/model_scan_job.rb:21:in `perform'
18:22:27 rails.1              | I, [2024-09-23T18:22:27.260864 #194]  INFO -- : [6c74e4573d0ff122b1c17161e3f3cb23] {"method":"GET","path":"/models","format":"html","controller":"ModelsController","action":"index","status":500,"allocations":267,"duration":5000.65,"view":0.0,"db":0.0,"@timestamp":"2024-09-23T18:22:27.260Z","@version":"1","message":"[500] GET /models (ModelsController#index)"}
18:22:27 rails.1              | F, [2024-09-23T18:22:27.261809 #194] FATAL -- : [6c74e4573d0ff122b1c17161e3f3cb23]   
18:22:27 rails.1              | [6c74e4573d0ff122b1c17161e3f3cb23] ActiveRecord::ConnectionTimeoutError (could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use):
18:22:27 rails.1              | [6c74e4573d0ff122b1c17161e3f3cb23]   
18:22:27 rails.1              | [6c74e4573d0ff122b1c17161e3f3cb23] app/models/library.rb:28:in `block in <class:Library>'
18:22:27 rails.1              | [6c74e4573d0ff122b1c17161e3f3cb23] app/controllers/application_controller.rb:61:in `configure_content_security_policy'

config, tried many combinations to try get this connection pool working properly.

      containers:
        - name: manyfold
          image: ghcr.io/manyfold3d/manyfold:0.79.0
          env:
            - name: PUID
              value: '1000'
            - name: PGID
              value: '1000'
            - name: MAX_FILE_UPLOAD_SIZE
              value: '10737418240000'
            - name: SECRET_KEY_BASE
              valueFrom:
                secretKeyRef:
                  name: manyfold-secret-key
                  key: secret_key
            - name: DATABASE_ADAPTER
              value: sqlite3
            - name: DATABASE_NAME
              value: /database/manyfold.sqlite3
            - name: DATABASE_POOL
              value: '16'
            - name: RAILS_MAX_THREADS
              value: '32'
            - name: DEFAULT_WORKER_CONCURRENCY
              value: '16'
            - name: PERFORMANCE_WORKER_CONCURRENCY
              value: '4'
            - name: REDIS_URL
              value: redis://redis-master.apps-manyfold.svc.cluster.local:6379/1
          resources:
            limits:
              memory: "16Gi"
              cpu: "12"
            requests:
              memory: "4Gi"
              cpu: "0.5"

To Reproduce Steps to reproduce the behavior: Normal operation, more so during large write operations. Perhaps connections not being properly recycled?

Expected behavior Not to crash

Screenshots image

aneurinprice avatar Sep 23 '24 18:09 aneurinprice

As you're using SQLite, I'm not surprised; it has issues currently. There should be some big improvements in 0.80.0 though, releasing very very soon.

Floppy avatar Sep 23 '24 19:09 Floppy

Migrated to postgresql for a (theoretically) smoother experience to be greeted by:

18:24:42 rails.1              | ):
18:24:42 rails.1              | [e7d598da11ec8b8f3efc1f1769545a98]   
18:24:42 rails.1              | [e7d598da11ec8b8f3efc1f1769545a98] app/controllers/application_controller.rb:61:in `filter_map'
18:24:42 rails.1              | [e7d598da11ec8b8f3efc1f1769545a98] app/controllers/application_controller.rb:61:in `configure_content_security_policy'
18:24:45 rails.1              | I, [2024-09-24T18:24:45.172737 #258]  INFO -- : [19741440c09858c11e02c388622f6091] {"method":"GET","path":"/problems","format":"html","controller":"ProblemsController","action":"index","status":500,"allocations":2152,"duration":118.02,"view":0.0,"db":117.49,"@timestamp":"2024-09-24T18:24:45.172Z","@version":"1","message":"[500] GET /problems (ProblemsController#index)"}
18:24:45 rails.1              | F, [2024-09-24T18:24:45.173657 #258] FATAL -- : [19741440c09858c11e02c388622f6091]   
18:24:45 rails.1              | [19741440c09858c11e02c388622f6091] ActiveRecord::ConnectionNotEstablished (connection to server at "10.43.77.17", port 5432 failed: FATAL:  remaining connection slots are reserved for roles with the SUPERUSER attribute
18:24:45 rails.1              | ):
18:24:45 rails.1              | [19741440c09858c11e02c388622f6091]   
18:24:45 rails.1              | [19741440c09858c11e02c388622f6091] app/controllers/application_controller.rb:61:in `filter_map'
18:24:45 rails.1              | [19741440c09858c11e02c388622f6091] app/controllers/application_controller.rb:61:in `configure_content_security_policy'
18:24:51 rails.1              | I, [2024-09-24T18:24:51.667008 #258]  INFO -- : [ded5bbf3fac00f32476429b95fb3e508] {"method":"GET","path":"/problems","format":"html","controller":"ProblemsController","action":"index","status":500,"allocations":2152,"duration":120.29,"view":0.0,"db":119.73,"@timestamp":"2024-09-24T18:24:51.666Z","@version":"1","message":"[500] GET /problems (ProblemsController#index)"}
18:24:51 rails.1              | F, [2024-09-24T18:24:51.667933 #258] FATAL -- : [ded5bbf3fac00f32476429b95fb3e508]   
18:24:51 rails.1              | [ded5bbf3fac00f32476429b95fb3e508] ActiveRecord::ConnectionNotEstablished (connection to server at "10.43.77.17", port 5432 failed: FATAL:  remaining connection slots are reserved for roles with the SUPERUSER attribute
18:24:51 rails.1              | ):
18:24:51 rails.1              | [ded5bbf3fac00f32476429b95fb3e508]   
18:24:51 rails.1              | [ded5bbf3fac00f32476429b95fb3e508] app/controllers/application_controller.rb:61:in `filter_map'
18:24:51 rails.1              | [ded5bbf3fac00f32476429b95fb3e508] app/controllers/application_controller.rb:61:in `configure_content_security_policy'
18:24:53 rails.1              | I, [2024-09-24T18:24:53.176272 #258]  INFO -- : [0740ab15829779b25d7010da9b351de0] {"method":"GET","path":"/problems","format":"html","controller":"ProblemsController","action":"index","status":500,"allocations":2152,"duration":122.32,"view":0.0,"db":121.79,"@timestamp":"2024-09-24T18:24:53.176Z","@version":"1","message":"[500] GET /problems (ProblemsController#index)"}
18:24:53 rails.1              | F, [2024-09-24T18:24:53.177230 #258] FATAL -- : [0740ab15829779b25d7010da9b351de0]   
18:24:53 rails.1              | [0740ab15829779b25d7010da9b351de0] ActiveRecord::ConnectionNotEstablished (connection to server at "10.43.77.17", port 5432 failed: FATAL:  remaining connection slots are reserved for roles with the SUPERUSER attribute
18:24:53 rails.1              | ):
18:24:53 rails.1              | [0740ab15829779b25d7010da9b351de0]   
18:24:53 rails.1              | [0740ab15829779b25d7010da9b351de0] app/controllers/application_controller.rb:61:in `filter_map'
18:24:53 rails.1              | [0740ab15829779b25d7010da9b351de0] app/controllers/application_controller.rb:61:in `configure_content_security_policy'
18:24:59 rails.1              | I, [2024-09-24T18:24:59.717672 #258]  INFO -- : [b859e518df57d74c93cf73a76a2fb2b4] {"method":"GET","path":"/problems","format":"html","controller":"ProblemsController","action":"index","status":500,"allocations":2142,"duration":119.11,"view":0.0,"db":118.56,"@timestamp":"2024-09-24T18:24:59.717Z","@version":"1","message":"[500] GET /problems (ProblemsController#index)"}
18:24:59 rails.1              | F, [2024-09-24T18:24:59.718677 #258] FATAL -- : [b859e518df57d74c93cf73a76a2fb2b4]   
18:24:59 rails.1              | [b859e518df57d74c93cf73a76a2fb2b4] ActiveRecord::ConnectionNotEstablished (connection to server at "10.43.77.17", port 5432 failed: FATAL:  remaining connection slots are reserved for roles with the SUPERUSER attribute
18:24:59 rails.1              | ):
18:24:59 rails.1              | [b859e518df57d74c93cf73a76a2fb2b4]   
18:24:59 rails.1              | [b859e518df57d74c93cf73a76a2fb2b4] app/controllers/application_controller.rb:61:in `filter_map'
18:24:59 rails.1              | [b859e518df57d74c93cf73a76a2fb2b4] app/controllers/application_controller.rb:61:in `configure_content_security_policy'
18:25:08 rails.1              | I, [2024-09-24T18:25:08.377606 #258]  INFO -- : [438d07e153d81fb2758699eb2e0ba971] {"method":"GET","path":"/problems","format":"html","controller":"ProblemsController","action":"index","status":500,"allocations":2142,"duration":119.27,"view":0.0,"db":118.64,"@timestamp":"2024-09-24T18:25:08.377Z","@version":"1","message":"[500] GET /problems (ProblemsController#index)"}
18:25:08 rails.1              | F, [2024-09-24T18:25:08.378701 #258] FATAL -- : [438d07e153d81fb2758699eb2e0ba971]   
18:25:08 rails.1              | [438d07e153d81fb2758699eb2e0ba971] ActiveRecord::ConnectionNotEstablished (connection to server at "10.43.77.17", port 5432 failed: FATAL:  remaining connection slots are reserved for roles with the SUPERUSER attribute
18:25:08 rails.1              | ):
18:25:08 rails.1              | [438d07e153d81fb2758699eb2e0ba971]   
18:25:08 rails.1              | [438d07e153d81fb2758699eb2e0ba971] app/controllers/application_controller.rb:61:in `filter_map'
18:25:08 rails.1              | [438d07e153d81fb2758699eb2e0ba971] app/controllers/application_controller.rb:61:in `configure_content_security_policy'

As per our conversation on Matrix, I believe this is a bug with ActiveRecord. I have taken a look at implementing ActiveRecord::ConnectionAdapters::ConnectionManagement but unfortunately I have no idea what I am doing.

I'm running Manyfold on some pretty serious hardware, so I am running into these issues at breakneck speed.

Running with the following settings, Ive tried many combinations but there is very little difference.

          env:
            - name: PUID
              value: '1000'
            - name: PGID
              value: '1000'
            - name: MAX_FILE_UPLOAD_SIZE
              value: '10737418240000'
            - name: SECRET_KEY_BASE
              valueFrom:
                secretKeyRef:
                  name: manyfold-secret-key
                  key: secret_key
            - name: DATABASE_USER
              value: manyfold
            - name: DATABASE_PASSWORD
              valueFrom:
                secretKeyRef:
                  name: postgres-postgresql
                  key: password
            - name: DATABASE_HOST
              value: postgres-postgresql.apps-manyfold.svc.cluster.local
            - name: DATABASE_NAME
              value: manyfold
            - name: RAILS_MAX_THREADS
              value: '32'
            - name: REDIS_URL
              value: redis://redis-master.apps-manyfold.svc.cluster.local:6379/1

aneurinprice avatar Sep 24 '24 18:09 aneurinprice

Ok let me take a look at ConnectionManagement, see what that's all about 👍

Floppy avatar Sep 24 '24 18:09 Floppy

Ah, that error mentioning superuser connections is coming from Postgres side, not Rails, indicating that it's maybe the server running out of connections rather than the pool. What's your Postgres server max connections set to?

Floppy avatar Sep 24 '24 19:09 Floppy

Default web concurrency is 4 workers, each of which will have a pool of RAILS_MAX_THREADS connections. So the main app will go up to 128 possible connections.

Then you've got the background workers, of which you've got 20. They shouldn't use more than one connection at a time, so you're looking at potentially 148 connections.

Apparently the default in Postgres is normally 100, so you could certainly end up hammering the server harder than it can cope with unless that's increased.

If it's set higher than 150, and you're still getting errors, then it could be that connections aren't being released.

Floppy avatar Sep 24 '24 19:09 Floppy

@aneurinprice in the next release, coming hopefully this afternoon, I've added PgHero via a link in the settings page. Using that you should be able to see exactly how many connections are coming from which processes, assuming this is still causing problems for you?

Floppy avatar Nov 05 '24 14:11 Floppy

Hi dude, Yes still causing me problems. Hopefully this fix will help narrow it down. Got a HUGE backlog of things to upload so lots of test data!

aneurinprice avatar Nov 05 '24 14:11 aneurinprice

👋🏻 Howdy! I'm experiencing similar behavior where after using the app heavily for a few minutes I start seeing connection pool errors in the logs. Same message as the first post.

After some googling I set DATABASE_CONNECTION_POOL=100 in my config mostly to see how things would change. This made the system reliable for more operations, until I started seeing a different message in the log:

ActiveRecord::ConnectionNotEstablished (connection to server at "192.168.1.220", port 5432 failed: FATAL: remaining connection slots are reserved for non-replication superuser connections

This error message seems to come from my Postgres server itself, which has a higher-than-default connection count. It sure sounds like connections are not being released for re-use.

edit

A related observation, after I restart the server and start working on things memory consumption only goes up. It'll sit there at the cap until I restart it.

image

edit 2

Turns out I had updated to the newer version that includes pghero, I poked around. On initial app start manyfold will make 3 connections. I open a link to a model that has 29 files in it, then scroll to the bottom. This added 30 connections and 260MB of memory consumption.

Is there anything I can do to help narrow down what's going on here? I'm not a ruby dev so I'm entirely unfamiliar with analyzing an app :)

image

Cellivar avatar Nov 15 '24 09:11 Cellivar

Oh, that's brilliant, thank you! I've been meaning to dig into this since shipping the PgHero addition. That's great data, it's obviously opening up lots of threads to respond to all the requests - which is expected. Have you set any of the other performance settings (threads, concurrency etc), or are you using the defaults?

I guess "remaining connection slots are reserved for non-replication superuser connections" is because your app is trying to use up to 100 connections, but the postgres server doesn't have that many available, because it keeps a few for important things. I think the postgres-side default is 100 as well, so perhaps turn the Rails pool size down to 90, then you shouldn't see that error.

Of course, you may see a different error once the Rails pool runs out, which is where our bug is here, I think.

Floppy avatar Nov 15 '24 14:11 Floppy