Issues since upgrade to 2.1.1

Problem:
Since upgrading to 2.1.1 we are seeing various issues.

  1. Web UI not loading properly - it displays the following:
    Proxy Error
    The proxy server received an invalid response from upstream server.
    The proxy server could not handle the request GET /widgets/217
    Reason: Error reading from remote server.

  2. Hammer commands fail with error:
    Error: 502 Bad Gateway

  3. I can’t bulk delete hosts - it fails straight away. But if i delete one at a time it will work but will return to a screen with the same proxy error as in issue 1.

  4. YUM/subscription manager on managed hosts displays the following error.
    HTTP error (500 - Internal Server Error): could not obtain a connection from the pool within 5.000 seconds (waited 10.620 seconds); all pooled connections were in use

  5. Ansible foreman inventory plugin fails with:
    Failed to parse inventory.foreman.yaml with auto plugin: 502 Server Error: Proxy Error

Expected outcome:
None of the above errors.

Foreman and Proxy versions:
2.1.1
Foreman and Proxy plugin versions:
foreman-tasks: 2.0.2
foreman_ansible: 5.1.1
foreman_remote_execution: 3.3.5
katello: 3.16.0

Distribution and version:
CentOS Linux release 7.8.2003

Other relevant data:

Where did you upgrade from? Was it 2.1.0 or 2.0.x? What’s in the Apache and Foreman logs?

Hi - thanks for the quick reply.
It was from 2.0.x

There is so much in the foreman/production.log i’m not sure what relates to the issues.
I do see a lot of entries like:

2020-08-26T12:39:16 [E|app|e506f7de] RestClient::BadRequest: 400 Bad Request
Body: {"displayMessage":"Content access mode does not allow this request.","requestUuid":"deccab5d-f15e-4861-a70a-876eb4a2e05c"}
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:223:in `exception_with_response'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/abstract_response.rb:103:in `return!'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:809:in `process_result'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:725:in `block in transmit'
/opt/rh/rh-ruby25/root/usr/share/ruby/net/http.rb:910:in `start'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:715:in `transmit'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:145:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/request.rb:52:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/rest-client-2.0.2/lib/restclient/resource.rb:51:in `get'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/katello/resources/candlepin/proxy.rb:26:in `get'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/controllers/katello/api/rhsm/candlepin_proxies_controller.rb:75:in `get'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/base.rb:195:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:112:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/controllers/katello/api/rhsm/candlepin_proxies_controller.rb:35:in `repackage_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in `disable_json_root'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:139:in `run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications.rb:180:in `block in instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications.rb:180:in `instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/controllers/katello/concerns/api/api_controller.rb:40:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/base.rb:136:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionview-6.0.3.1/lib/action_view/rendering.rb:39:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal.rb:190:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal.rb:254:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:834:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/engine.rb:527:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:834:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/lib/katello/middleware/event_daemon.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-dsl-2.2.2/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/static_dispatcher.rb:66:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/extractor/recorder.rb:137:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/etag.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/conditional_get.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/head.rb:12:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:266:in `context'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:260:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/cookies.rb:648:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:101:in `run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/rack/logger.rb:37:in `call_app'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/rack/logger.rb:28:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/lib/katello/prevent_json_parsing.rb:12:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/method_override.rb:24:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/runtime.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/sendfile.rb:110:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.3.0/lib/secure_headers/middleware.rb:11:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/engine.rb:527:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:74:in `block in call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:58:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:58:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/configuration.rb:228:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:682:in `handle_request'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:472:in `process_client'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:328:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/thread_pool.rb:134:in `block in spawn_thread'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2020-08-26T12:39:16 [I|app|e506f7de]   Rendering text template
2020-08-26T12:39:16 [I|app|e506f7de]   Rendered text template (Duration: 0.0ms | Allocations: 2)
2020-08-26T12:39:16 [I|app|e506f7de] Completed 400 Bad Request in 68ms (Views: 1.1ms | ActiveRecord: 5.9ms | Allocations: 5938)


And in the httpd foreman-ssl_error_ssl.log i see various messages like:

[Wed Aug 26 09:59:21.536334 2020] [proxy_http:error] [pid 1613] (104)Connection reset by peer: [client 10.203.3.201:48749] AH01102: error reading status line from remote server 127.0.0.1:3000
[Wed Aug 26 09:59:21.536706 2020] [proxy:error] [pid 1613] [client 10.203.3.201:48749] AH00898: Error reading from remote server returned by /rhsm/
[Wed Aug 26 09:59:21.634701 2020] [proxy_http:error] [pid 4662] (104)Connection reset by peer: [client 192.168.118.84:61060] AH01102: error reading status line from remote server 127.0.0.1:3000
[Wed Aug 26 09:59:21.634790 2020] [proxy:error] [pid 4662] [client 192.168.118.84:61060] AH00898: Error reading from remote server returned by /rhsm/consumers/f4e9a26d-6e50-4726-a4b2-3bd7dfc8014a/certificates/serials
[Wed Aug 26 09:59:30.132793 2020] [proxy_http:error] [pid 29144] (70007)The timeout specified has expired: [client 10.136.1.22:48544] AH01102: error reading status line from remote server 127.0.0.1:3000
[Wed Aug 26 09:59:30.132862 2020] [proxy:error] [pid 29144] [client 10.136.1.22:48544] AH00898: Error reading from remote server returned by /rhsm/consumers/c6d9b14c-21a7-41f8-a4bb-8bb38a748bf2

Does any of that helkp?

Thanks
Rob

I’m currently seeing the ‘502 Server Error: Proxy Error’ messages in an Ansibnel run, and I thin i have pinned it down to some messages in the logs.

Apache ssl error log.

[Wed Aug 26 12:53:16.849289 2020] [proxy_http:error] [pid 16190] (104)Connection reset by peer: [client 10.136.1.22:45308] AH01102: error reading status line from remote server 127.0.0.1:3000
[Wed Aug 26 12:53:16.849447 2020] [proxy:error] [pid 16190] [client 10.136.1.22:45308] AH00898: Error reading from remote server returned by /rhsm/consumers/5692b454-cb5b-4a52-ad68-33b572b77175/certificates/serials

foreman production.log

2020-08-26T12:53:16 [E|kat|39e39b59] ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 7.921 seconds); all pooled connections were in use
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:221:in `block in wait_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:210:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:210:in `wait_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:171:in `internal_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:297:in `internal_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:166:in `block in poll'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:175:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:166:in `poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `acquire_connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:593:in `checkout'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:437:in `connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:1119:in `retrieve_connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_handling.rb:221:in `retrieve_connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_handling.rb:189:in `connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/delegation.rb:92:in `connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/query_methods.rb:1298:in `preprocess_order_args'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/query_methods.rb:364:in `order!'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/query_methods.rb:359:in `order'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:554:in `ordered_relation'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:519:in `find_nth_with_limit'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:512:in `find_nth'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:120:in `first'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/active_record/session_store/session.rb:58:in `find_by_session_id'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/action_dispatch/session/active_record_store.rb:124:in `block in get_session_model'
/usr/share/foreman/lib/foreman/silenced_logger.rb:37:in `silence'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/action_dispatch/session/active_record_store.rb:123:in `get_session_model'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/action_dispatch/session/active_record_store.rb:140:in `find_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:314:in `load_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/session/abstract_store.rb:45:in `block in load_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/session/abstract_store.rb:53:in `stale_session_check!'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/session/abstract_store.rb:45:in `load_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/request/session.rb:234:in `load!'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/request/session.rb:230:in `load_for_write!'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/request/session.rb:132:in `[]='
/opt/theforeman/tfm/root/usr/share/gems/gems/gettext_i18n_rails-1.8.0/lib/gettext_i18n_rails/action_controller.rb:5:in `set_gettext_locale'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:428:in `block in make_lambda'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:200:in `block (2 levels) in halting'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:201:in `block in halting'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:513:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:513:in `invoke_before'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:110:in `block in run_callbacks'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in `disable_json_root'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in `around'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:139:in `run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications.rb:180:in `block in instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications.rb:180:in `instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/controllers/katello/concerns/api/api_controller.rb:40:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/base.rb:136:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionview-6.0.3.1/lib/action_view/rendering.rb:39:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal.rb:190:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal.rb:254:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:834:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/engine.rb:527:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:834:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/lib/katello/middleware/event_daemon.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-dsl-2.2.2/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/static_dispatcher.rb:66:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/extractor/recorder.rb:137:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/etag.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/conditional_get.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/head.rb:12:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:266:in `context'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:260:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/cookies.rb:648:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:101:in `run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/rack/logger.rb:37:in `call_app'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/rack/logger.rb:28:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/lib/katello/prevent_json_parsing.rb:12:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/method_override.rb:24:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/runtime.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/sendfile.rb:110:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.3.0/lib/secure_headers/middleware.rb:11:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/engine.rb:527:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:74:in `block in call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:58:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:58:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/configuration.rb:228:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:682:in `handle_request'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:472:in `process_client'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:328:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/thread_pool.rb:134:in `block in spawn_thread'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'

I hope this helps.

Thanks
Rob

Some background: in 2.1 the default was switched from Passenger to Puma. Passenger runs as part of the Apache process while Puma runs standalone. That turns it into a reverse proxy setup. For some reason the service fails to respond.

A common reason is that a request takes too long, but then we’d see timeouts. This looks like the DB pool size is too small for some reason. You can run the installer with --foreman-db-pool 10. The default is 5, so perhaps that helps.

1 Like

Thanks for the info - i’ll give that a try and let you know how it goes.

That didn’t seem to work.
Is there a way to see what is using the DB pool? Perhaps i need to increase further…?

Hi - is the main issue that i’m not getting a meaningful (or any) response back from the server?
For example, the following:

$ hammer host delete --name server_name
Could not delete the host:
Error: 502 Bad Gateway

In this case the host was successfully deleted.

I get the same error when using hammer to publish and promote content views - should I assume that what i expected to happen (eg. publish content view) did happen correctly? Even though I can now see a new version of the content view, it would be nice to know its a clean and working version.

Thanks
Rob

Hello,

I’m experiencing the same 502 errors when, for instance, creating an activation key with hammer while repos sync tasks are running:

$ hammer activation-key create --organization-id $orgid --name development
Could not create the activation key:
  Error: 502 Bad Gateway

error in logs:

2020-09-01T10:46:40 [E|app|] Timeout::Error: The time waiting for task 51f4d7f5-7e4e-47b0-bbe5-2c65ece532d4 to finish exceeded the 'foreman_tasks_sync_task_timeout' (120s)
2020-09-01T10:46:40 [I|app|] Completed 500 Internal Server Error in 120341ms (Views: 0.2ms | ActiveRecord: 32.3ms | Allocations: 383155)

The object is actually created:

$ hammer --csv activation-key list --organization-id 3 --search name=development
ID,Name,Host Limit,Lifecycle Environment,Content View
1,development,0 of Unlimited,,

When I try to view it from the UI I get:

Katello::Resources::Candlepin::CandlepinResource: 404 Not Found {"displayMessage":"Runtime Error RESTEASY003210: Could not find resource for full path: https://localhost:8443/candlepin/activation_keys//content_overrides at org.jboss.resteasy.core.registry.SegmentNode.match:153","requestUuid":"a9766704-a1e6-4b51-a2b2-22c13eac79d7"} (GET /candlepin/activation_keys//content_overrides)

And the creation task seems stuck (still running for 12 minutes):

$ hammer --csv task list --search state=running
6af1e29d-704a-4ae0-abd1-36218de54cdf,"Create activation_key {""text""=>""activation key 'development'"", ""link""=>""/activation_keys/1/info""} organization {""text""=>""organization 'orgXX'"", ""link""=>""/organizations/3/edit""}",running,pending,2020/09/01 10:43:37,"",admin,""

When 4 tasks of this kind are running, I get then:

Could not create the activation key:
Task 60172c78-b86c-4903-a388-4451d2ed706d: 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 will try to increase foreman_tasks timeout and db pool size but I would like to have some feedback as this behavior looks quite insane to me.

The ActiveRecord::ConnectionTimeoutErrors should be fixed in dynflow-1.4.7.

It seems that the management of activation keys is broken, and it looks to be a different issue than the 502 error with hammer.
I’ve increased db pool size to 15, foreman_tasks timeout to 240, rebooted the server and cleaned the paused tasks (skip/resume from dynflow console).
Now I have no running/paused task and I try to create the activation key from the UI (no hammer here). When I click on Save, I can see in the logs:

2020-09-01T13:14:30 [I|bac|] Task {label: Actions::Katello::ActivationKey::Create, id: 2dec9c47-9c7e-4f69-bad4-9362a6c44be6, execution_plan_id: 8f6010d7-b1b5-4d75-9844-100a4defdaa5} state changed: planned 
2020-09-01T13:14:30 [I|bac|] Task {label: Actions::Katello::ActivationKey::Create, id: 2dec9c47-9c7e-4f69-bad4-9362a6c44be6, execution_plan_id: 8f6010d7-b1b5-4d75-9844-100a4defdaa5} state changed: running 

and 240s later:

2020-09-01T13:18:30 [E|app|] Timeout::Error: The time waiting for task 2dec9c47-9c7e-4f69-bad4-9362a6c44be6 to finish exceeded the 'foreman_tasks_sync_task_timeout' (240s)

The creation task is stuck and I observe the same behavior as described before with hammer.

can you go to the task that created that activation key and click the dynflow console button and post a screenshot of what you see? I’m curious which step is taking so long

I tried the same on another foreman instance and activation keys are correctly created so I suspect an issue specific to this instance, I will redeploy it and retry with fresh install.

However, the 502 Bad Gateway errors with hammer are real (seen at host/smart-proxy creation/deletion).

Here is what I see:

But I think I’ve broken that instance by myself… I will retry on fresh install and let you know.

I think its a symptom of the same issue. Can you try to upgrade to the dynflow version adam mentioned?

yum update http://koji.katello.org/kojifiles/packages/tfm-rubygem-dynflow/1.4.7/1.fm2_1.el7/noarch/tfm-rubygem-dynflow-1.4.7-1.fm2_1.el7.noarch.rpm

I did already :slight_smile:
but doesn’t help.

would you be able to send a foreman-debug?

Sorry I’ve trashed it already, I’m now redeploying a fresh one…

NVM - activation keys are working fine on fresh install. I’m sorry for that noise…

To workaround this issue I’ve added Timeout 1800 in /etc/httpd/conf.d/05-foreman-ssl.conf. Hammer looks to work as expected after this change.