Timeout when I enabled simple content access

Support
1

On Foreman 3.6.1/Katello 4.8.3.

So thought it was time to enable Simple Content Access so went Administer → Organizations → Edit → Primary → Ticked “Simple Content Access” and hit Submit. After Foreman was thinking about it for a while I get this error:

[root@sebr-foreman foreman]# foreman-rake errors:fetch_log request_id=766a8067
Foreman version: 3.6.1
Plugins:
 - foreman-tasks 7.2.1
 - foreman_ansible 11.2.0
 - foreman_openscap 6.0.0
 - foreman_remote_execution 9.1.0
 - katello 4.8.3

2023-08-08T12:54:55 [I|app|766a8067] Started PATCH "/organizations/1-xxx" for 10.10.10.10 at 2023-08-08 12:54:55 +0000
2023-08-08T12:54:55 [I|app|766a8067] Processing by OrganizationsController#update as HTML
2023-08-08T12:54:55 [I|app|766a8067]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX==", "organization"=>{"name"=>"xxx", "service_level"=>"", "description"=>"", "ignore_types"=>["0", "0", "0", "0", "0", "0", "0", "0", "0", "0"], "user_ids"=>["4", "1", "3", "2", "17", "14", "15", "5", "13", "", "7", "18", "6"], "smart_proxy_ids"=>["", "7", "5", "4", "8", "3", "1", "2", "9", "11", "10", "6"], "subnet_ids"=>[""], "compute_resource_ids"=>[""], "medium_ids"=>["", "1", "2", "3", "15", "11", "4", "6", "13", "5", "12", "7", "8", "10", "14", "16", "9"], "provisioning_template_ids"=>["53", "", "45", "10", "29", "46", "48", "47", "202", "203", "11", "38", "110", "28", "12", "49", "13", "30", "50", "59", "60", "51", "2", "31", "52", "27", "32", "3", "6", "14", "33", "42", "111", "54", "15", "37", "1", "4", "5", "8", "9", "18", "19", "20", "21", "22", "112", "55", "7", "209", "16", "17", "34", "43", "113", "23", "56", "114", "115", "24", "25", "35", "44", "210", "57", "108", "61", "26", "58", "36", "62", "64", "65", "66", "67", "68", "69", "70", "71", "72", "73", "74", "75", "76", "77", "78", "79", "80", "39", "40", "41", "81", "82", "83", "85", "87", "88", "89", "207", "90", "91", "204", "211", "93", "94", "95", "96", "97", "98", "99", "100", "101", "102", "103", "104", "105", "106", "84", "206", "86", "92", "63", "107", "109"], "ptable_ids"=>["", "118", "116", "117", "119", "120", "121", "122", "123", "124", "125", "126", "127", "128", "129", "130", "132", "131", "134", "133", "135"], "domain_ids"=>["2", "4", "1", "7", "3", "6", "", "8"], "realm_ids"=>[""], "hostgroup_ids"=>["7", "28", "1", "39", "5", "2", "13", "4", "12", "43", "40", "33", "3", "6", "48", "47", "45", "44", "11", "14", "41", "8", "27", "29", "", "30", "31", "32", "9", "49", "50", "10", "51", "52", "42", "34", "35", "36", "46", "37", "38"], "location_ids"=>["5", "3", "12", "2", "9", "4", "10", "11", "6", "7", "8", "", "13", "14"]}, "simple_content_access"=>"1", "commit"=>"Submit", "id"=>"1-xxx"}
2023-08-08T12:54:55 [I|bac|766a8067] Task {label: , execution_plan_id: a48c4dd0-7091-4ab5-a3ae-160bd76ac017} state changed: pending
2023-08-08T12:54:55 [I|bac|766a8067] Task {label: Actions::Katello::Organization::SimpleContentAccess::Enable, id: 35538273-1d63-421c-bd86-a9d1d7e4e95d, execution_plan_id: a48c4dd0-7091-4ab5-a3ae-160bd76ac017} state changed: planning
2023-08-08T12:54:56 [I|app|766a8067] PrepareContentOverrides plan: "1-xxx"
2023-08-08T12:54:56 [I|bac|766a8067] Task {label: Actions::Katello::Organization::SimpleContentAccess::Enable, id: 35538273-1d63-421c-bd86-a9d1d7e4e95d, execution_plan_id: a48c4dd0-7091-4ab5-a3ae-160bd76ac017} state changed: planned
2023-08-08T12:54:56 [I|bac|766a8067] Task {label: Actions::Katello::Organization::SimpleContentAccess::Enable, id: 35538273-1d63-421c-bd86-a9d1d7e4e95d, execution_plan_id: a48c4dd0-7091-4ab5-a3ae-160bd76ac017} state changed: running
2023-08-08T12:54:56 [I|app|766a8067] Hosts - Creating disabled overrides for unsubscribed content in organization xxx
2023-08-08T12:56:52 [I|app|766a8067] Activation keys - Creating disabled overrides for unsubscribed content in organization xxx
2023-08-08T12:56:56 [W|app|766a8067] The time waiting for task 35538273-1d63-421c-bd86-a9d1d7e4e95d to finish exceeded the 'foreman_tasks_sync_task_timeout' (120s)
2023-08-08T12:56:56 [I|app|766a8067] Backtrace for 'The time waiting for task 35538273-1d63-421c-bd86-a9d1d7e4e95d to finish exceeded the 'foreman_tasks_sync_task_timeout' (120s)' error (Timeout::Error): The time waiting for task 35538273-1d63-421c-bd86-a9d1d7e4e95d to finish exceeded the 'foreman_tasks_sync_task_timeout' (120s)
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks.rb:36:in `block (2 levels) in trigger_task'
 766a8067 | /usr/share/gems/gems/algebrick-0.7.5/lib/algebrick/matchers/abstract.rb:74:in `assigns'
 766a8067 | /usr/share/gems/gems/algebrick-0.7.5/lib/algebrick/matching.rb:56:in `match_value'
 766a8067 | /usr/share/gems/gems/algebrick-0.7.5/lib/algebrick/matching.rb:36:in `block in match?'
 766a8067 | /usr/share/gems/gems/algebrick-0.7.5/lib/algebrick/matching.rb:35:in `each'
 766a8067 | /usr/share/gems/gems/algebrick-0.7.5/lib/algebrick/matching.rb:35:in `match?'
 766a8067 | /usr/share/gems/gems/algebrick-0.7.5/lib/algebrick/matching.rb:23:in `match'
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks.rb:26:in `block in trigger_task'
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks.rb:46:in `block in rails_safe_trigger_task'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks.rb:45:in `rails_safe_trigger_task'
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks.rb:24:in `trigger_task'
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks.rb:55:in `sync_task'
 766a8067 | /usr/share/gems/gems/foreman-tasks-7.2.1/lib/foreman_tasks/triggers.rb:22:in `sync_task'
 766a8067 | /usr/share/gems/gems/katello-4.8.3/app/controllers/katello/concerns/organizations_controller_extensions.rb:52:in `update'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/base.rb:228:in `process_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rendering.rb:30:in `process_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:117:in `block in run_callbacks'
 766a8067 | /usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in `set_timezone'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 766a8067 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 766a8067 | /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 766a8067 | /usr/share/gems/gems/audited-5.3.1/lib/audited/sweeper.rb:16:in `around'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 766a8067 | /usr/share/gems/gems/audited-5.3.1/lib/audited/sweeper.rb:16:in `around'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:126:in `block in run_callbacks'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:137:in `run_callbacks'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/callbacks.rb:41:in `process_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/rescue.rb:22:in `process_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `block in instrument'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/notifications.rb:203:in `instrument'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/instrumentation.rb:33:in `process_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal/params_wrapper.rb:249:in `process_action'
 766a8067 | /usr/share/gems/gems/activerecord-6.1.7.3/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/abstract_controller/base.rb:165:in `process'
 766a8067 | /usr/share/gems/gems/actionview-6.1.7.3/lib/action_view/rendering.rb:39:in `process'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal.rb:190:in `dispatch'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_controller/metal.rb:254:in `dispatch'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:33:in `serve'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:50:in `block in serve'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:32:in `each'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/journey/router.rb:32:in `serve'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/routing/route_set.rb:842:in `call'
 766a8067 | /usr/share/gems/gems/katello-4.8.3/lib/katello/middleware/organization_created_enforcer.rb:18:in `call'
 766a8067 | /usr/share/gems/gems/katello-4.8.3/lib/katello/middleware/event_daemon.rb:10:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/apipie-dsl-2.5.0/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
 766a8067 | /usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/static_dispatcher.rb:68:in `call'
 766a8067 | /usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/extractor/recorder.rb:137:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/static.rb:24:in `call'
 766a8067 | /usr/share/foreman/lib/foreman/middleware/libvirt_connection_cleaner.rb:9:in `call'
 766a8067 | /usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
 766a8067 | /usr/share/gems/gems/apipie-rails-0.8.2/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/tempfile_reaper.rb:15:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/etag.rb:27:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/conditional_get.rb:40:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/head.rb:12:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/http/permissions_policy.rb:22:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/http/content_security_policy.rb:19:in `call'
 766a8067 | /usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/session/abstract/id.rb:266:in `context'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/session/abstract/id.rb:260:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/cookies.rb:697:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/callbacks.rb:98:in `run_callbacks'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/actionable_exceptions.rb:18:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/debug_exceptions.rb:29:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 766a8067 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:37:in `call_app'
 766a8067 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/rack/logger.rb:28:in `call'
 766a8067 | /usr/share/gems/gems/sprockets-rails-3.4.2/lib/sprockets/rails/quiet_assets.rb:13:in `call'
 766a8067 | /usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/request_id.rb:26:in `call'
 766a8067 | /usr/share/gems/gems/katello-4.8.3/lib/katello/prevent_json_parsing.rb:12:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/method_override.rb:24:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/runtime.rb:22:in `call'
 766a8067 | /usr/share/gems/gems/activesupport-6.1.7.3/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/executor.rb:14:in `call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/sendfile.rb:110:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/ssl.rb:77:in `call'
 766a8067 | /usr/share/gems/gems/actionpack-6.1.7.3/lib/action_dispatch/middleware/host_authorization.rb:142:in `call'
 766a8067 | /usr/share/gems/gems/secure_headers-6.5.0/lib/secure_headers/middleware.rb:11:in `call'
 766a8067 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/engine.rb:539:in `call'
 766a8067 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/railtie.rb:207:in `public_send'
 766a8067 | /usr/share/gems/gems/railties-6.1.7.3/lib/rails/railtie.rb:207:in `method_missing'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/urlmap.rb:74:in `block in call'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/urlmap.rb:58:in `each'
 766a8067 | /usr/share/gems/gems/rack-2.2.6.2/lib/rack/urlmap.rb:58:in `call'
 766a8067 | /usr/share/gems/gems/puma-5.6.5/lib/puma/configuration.rb:252:in `call'
 766a8067 | /usr/share/gems/gems/puma-5.6.5/lib/puma/request.rb:77:in `block in handle_request'
 766a8067 | /usr/share/gems/gems/puma-5.6.5/lib/puma/thread_pool.rb:340:in `with_force_shutdown'
 766a8067 | /usr/share/gems/gems/puma-5.6.5/lib/puma/request.rb:76:in `handle_request'
 766a8067 | /usr/share/gems/gems/puma-5.6.5/lib/puma/server.rb:443:in `process_client'
 766a8067 | /usr/share/gems/gems/puma-5.6.5/lib/puma/thread_pool.rb:147:in `block in spawn_thread'
 766a8067 | /usr/share/gems/gems/logging-2.3.1/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2023-08-08T12:56:56 [I|app|766a8067]   Rendered common/500.html.erb within layouts/application (Duration: 2.5ms | Allocations: 1258)
2023-08-08T12:56:56 [I|app|766a8067]   Rendered layouts/base.html.erb (Duration: 4.3ms | Allocations: 7892)
2023-08-08T12:56:56 [I|app|766a8067]   Rendered layout layouts/application.html.erb (Duration: 13.6ms | Allocations: 20675)
2023-08-08T12:56:56 [I|app|766a8067] Completed 500 Internal Server Error in 120186ms (Views: 15.8ms | ActiveRecord: 38.9ms | Allocations: 175512)
2023-08-08T12:56:56 [I|app|766a8067] Finished creating overrides in non-SCA org; no errors
2023-08-08T12:56:56 [I|app|766a8067] Organization may now be switched to Simple Content Access mode without any change in access to content.
2023-08-08T12:56:56 [I|bac|766a8067] Task {label: Actions::Katello::Organization::SimpleContentAccess::Enable, id: 35538273-1d63-421c-bd86-a9d1d7e4e95d, execution_plan_id: a48c4dd0-7091-4ab5-a3ae-160bd76ac017} state changed: stopped  result: success

Have a snapshot from before this. Should I be worried and rollback?
Going to Subscriptions tells me “This organization has Simple Content Access enabled.”
Have a couple of remote proxies on networks that are currently down, can this be why the timeout comes?

2

If you go to the Dynflow console from the task detail page in the UI, what does that output look like?

It looks like it timed out during

Activation keys - Creating disabled overrides for unsubscribed content in organization xxx

How many activation keys do you have? How many custom products do you have?

Should I be worried and rollback?

There should be nothing to worry about, except that you may not have content overrides for some of your non-subscribed activation key custom products.

If in the future you want to enable Simple Content Access without creating the overrides, you can do so with

hammer simple-content-access enable --org xxx --auto-create-overrides false

(The auto-create-overrides option is only present on Katello 4.8 and will not be in 4.9.)

3

image
image952×522 74.8 KB

13 activation keys and 61 custom products (140 repos).

4

I just noticed this:

Looks like the creation of overrides actually completed just fine; it was just Foreman Tasks that errored. I’ll look into if this is a bug…

This should not have taken over 2 minutes. hmm :thinking:

5

Also, I just noticed this:

The task id that it errored on is not the same as the task id in the SimpleContentAccess::Enable screenshot. Therefore, this error is probably just a coincidence, and nothing actually went wrong with enabling SCA.

6

So seems the “Hosts - Creating disabled overrides for unsubscribed content in organization xxx” took almost 2 minutes and that gave only the next step 4 seconds to complete and since it took longer then 4 seconds it hit the 120 timeout…so makes me sorta wonder what steps it never had time to start after that…

Have 400 hosts.

7

Checked all enabled/disabled “Repository Sets” for my activation keys and all looks good.
Are there any steps that should have been executed after the “Activation keys - Creating disabled overrides for unsubscribed content in organization xxx” step that perhaps was missed due to the timeout?

8

No, the fact that we got Finished creating overrides in non-SCA org; no errors means everything completed successfully.

9

I tested this in my development environment. Seems it’s because this code calls SimpleContentAccess::Enable as a synchronous task rather than async. This was fine before we were doing content overrides at the same time, but now it seems it may take too long if you have enough custom repositories.

Besides the scary error message, it shouldn’t really hurt anything. I’ve opened Bug #36657: On Katello 4.8, SimpleContentAccess::Enable causes "The time waiting for task xxxx to finish exceeded the 'foreman_tasks_sync_task_timeout' (120s)' - Katello - Foreman.

1 Like