Problem:
Publishing a CVV fails in Actions::Katello::Repository::IndexContent step
Expected outcome:
CVV publication works
Foreman and Proxy versions:
foreman-2.4.0-1.el8.noarch
Foreman and Proxy plugin versions:
katello-4.0.0-1.el8.noarch
Distribution and version:
Oracle Linux 8.3
Other relevant data:
So, I was running Katello 4.0rc2, quite successfully, and noticed the 4.0 release completed. So I updated and re-ran the installer, which left me with a seemingly working Katello 4.0. However, CVV publication appears to be broken.
Action: Actions::Katello::Repository::IndexContent
Input:
{"id"=>960,
"matching_content"=>false,
"current_request_id"=>"492ddf02-1c76-4e11-92e8-1fb9300bb760",
"current_timezone"=>"Europe/London",
"current_organization_id"=>1,
"current_location_id"=>2,
"current_user_id"=>6}
Exception:
PulpRpmClient::ApiError: Error message: the server returns an error
Backtrace:
/usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api_client.rb:88:in `rescue in call_api'
/usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api_client.rb:66:in `call_api'
/usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api/content_modulemds_api.rb:228:in `list_with_http_info'
/usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api/content_modulemds_api.rb:158:in `list'
/usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:93:in `content_unit_list'
/usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:106:in `fetch_content_list'
/usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:75:in `block (2 levels) in pulp_units_batch_for_repo'
/usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:69:in `loop'
/usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:69:in `block in pulp_units_batch_for_repo'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/concerns/pulp_database_unit.rb:120:in `each'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/concerns/pulp_database_unit.rb:120:in `each'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/concerns/pulp_database_unit.rb:120:in `import_for_repository'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:902:in `block (2 levels) in index_content'
/usr/share/gems/gems/katello-4.0.0/app/lib/katello/logging.rb:6:in `time'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:901:in `block in index_content'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:900:in `each'
/usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:900:in `index_content'
/usr/share/gems/gems/katello-4.0.0/app/lib/actions/katello/repository/index_content.rb:18:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:571:in `block (3 levels) in execute_run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/katello-4.0.0/app/lib/actions/middleware/execute_if_contents_changed.rb:5:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
/usr/share/gems/gems/activesupport-6.0.3.4/lib/active_support/execution_wrapper.rb:88:in `wrap'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/progress.rb:17:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_request_id.rb:52:in `restore_current_request_id'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:32:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_user.rb:54:in `restore_curent_user'
/usr/share/gems/gems/foreman-tasks-4.0.1/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:23:in `call'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/world.rb:31:in `execute'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:570:in `block (2 levels) in execute_run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:569:in `catch'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:569:in `block in execute_run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:472:in `block in with_error_handling'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:472:in `catch'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:472:in `with_error_handling'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:564:in `execute_run'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:285:in `execute'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/director.rb:68:in `execute'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors.rb:18:in `run_user_code'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
/usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:192:in `execute_job'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:165:in `block (2 levels) in process'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:164:in `block in process'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:109:in `local'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq.rb:37:in `block in <module:Sidekiq>'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/job_logger.rb:8:in `call'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'
/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_thread'
/usr/share/gems/gems/logging-2.3.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
Hi @John_Beranek
Was it just this Content View or all Content Views in general? Did the upgrade go ok when the installer ran?
All Content Views I tried. The upgrade seemed to go completely fine.
@John_Beranek
Are you seeing any errors in /var/log/messages from Pulp when trying to publish?
It def is isolated to Pulp from your traceback you posted.
So, at the time of the publish I see:
2021-04-27T15:24:50.441803+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 5fa9b010065145f69fc6531010eb8624
2021-04-27T15:24:50.446964+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:50 +0000] "GET /pulp/api/v3/status HTTP/1.1" 301 0 "-" "rest-client/2.0.2 (linux-gnu x86_64) ruby/2.5.5p157"
2021-04-27T15:24:50.474891+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 10875e2f9c3c4a8dafbad05f744ef837
2021-04-27T15:24:50.516800+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:50 +0000] "GET /pulp/api/v3/status/ HTTP/1.1" 200 3968 "-" "rest-client/2.0.2 (linux-gnu x86_64) ruby/2.5.5p157"
2021-04-27T15:24:54.487255+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 2d82ab1983ca466f9325f466056c7613
2021-04-27T15:24:54.679610+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:54 +0000] "GET /pulp/api/v3/repositories/rpm/rpm/094d6cc9-8a0b-49dc-8ed0-644a72a2bf86/ HTTP/1.1" 200 456 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:24:54.681021+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: efd9655f60214e65aaed9b4b8a61a85a
2021-04-27T15:24:54.710177+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:54 +0000] "GET /pulp/api/v3/repositories/rpm/rpm/9018a94b-bf64-4c50-8898-7d096d5f2406/ HTTP/1.1" 200 471 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:24:54.712339+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: c4e1fafe4a114b6498095d0837e5f020
2021-04-27T15:24:54.734140+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:54 +0000] "GET /pulp/api/v3/repositories/rpm/rpm/ed32a3e2-ddc6-4480-ad29-9bd426960259/ HTTP/1.1" 200 462 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:24:54.737804+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: b1e3d3bee46040f3afce976e92e33203
2021-04-27T15:24:54.754195+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:54 +0000] "GET /pulp/api/v3/repositories/rpm/rpm/da33f193-4268-4a99-bcd7-e7c53cbff922/ HTTP/1.1" 200 458 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:24:54.755398+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 9de20ba0d5ae4d118161cadb9c22f680
2021-04-27T15:24:54.775636+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:54 +0000] "GET /pulp/api/v3/repositories/rpm/rpm/876365bd-af1a-4c17-8419-6189f657341c/ HTTP/1.1" 200 455 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:24:54.860922+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 5bb3c2e689c04ad397f0e838411ebfe6
2021-04-27T15:24:54.883097+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:24:54 +0000] "GET /pulp/api/v3/repositories/rpm/rpm/1a6da521-56a3-43cb-bfc7-652349ec3407/ HTTP/1.1" 200 469 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:24:55.517672+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 98afb712d6c84be28942be2d36abcfd7
2021-04-27T15:25:26.154408+00:00 paaitskatell01 pulpcore-api[1105]: - - [27/Apr/2021:15:25:26 +0000] "GET /pulp/api/v3/content/rpm/packages/?arch__ne=src&fields=pulp_href&limit=2000&offset=0&repository_version=%2Fpulp%2Fapi%2Fv3%2Frepositories%2Frpm%2Frpm%2Ff1a07704-c637
-4801-bf40-99423a1dfef9%2Fversions%2F7%2F HTTP/1.1" 200 20645 "-" "OpenAPI-Generator/3.10.0/ruby"
2021-04-27T15:25:26.155230+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 72e240bf8492426d91f37ff75358eb67
2021-04-27T15:25:56.508802+00:00 paaitskatell01 pulpcore-api[1105]: [2021-04-27 15:25:56 +0000] [1105] [CRITICAL] WORKER TIMEOUT (pid:1519)
2021-04-27T15:25:57.568358+00:00 paaitskatell01 pulpcore-api[1105]: [2021-04-27 15:25:57 +0000] [8106] [INFO] Booting worker with pid: 8106
2021-04-27T15:25:59.692603+00:00 paaitskatell01 pulpcore-api[1105]: /usr/lib/python3.6/site-packages/pulpcore/app/apps.py:72: FutureWarning: The plugin `deb` is missing a version attribute. Starting with pulpcore==3.10, plugins are required to define their version on the PulpPluginAppConfig subclass.
2021-04-27T15:25:59.692603+00:00 paaitskatell01 pulpcore-api[1105]: warnings.warn(msg, FutureWarning)
2021-04-27T15:25:59.692603+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 0d8f60ab642044eb9f9b2d39ad355022
2021-04-27T15:26:30.627966+00:00 paaitskatell01 pulpcore-api[1105]: [2021-04-27 15:26:30 +0000] [1105] [CRITICAL] WORKER TIMEOUT (pid:8106)
2021-04-27T15:26:31.387844+00:00 paaitskatell01 pulpcore-api[1105]: [2021-04-27 15:26:31 +0000] [8106] [INFO] Worker exiting (pid: 8106)
2021-04-27T15:26:31.656753+00:00 paaitskatell01 pulpcore-api[1105]: [2021-04-27 15:26:31 +0000] [8117] [INFO] Booting worker with pid: 8117
2021-04-27T15:26:34.006820+00:00 paaitskatell01 pulpcore-api[1105]: /usr/lib/python3.6/site-packages/pulpcore/app/apps.py:72: FutureWarning: The plugin `deb` is missing a version attribute. Starting with pulpcore==3.10, plugins are required to define their version on the PulpPluginAppConfig subclass.
2021-04-27T15:26:34.006820+00:00 paaitskatell01 pulpcore-api[1105]: warnings.warn(msg, FutureWarning)
2021-04-27T15:26:34.006820+00:00 paaitskatell01 pulpcore-api[1105]: pulp [None]: django_guid:INFO: Header `Correlation-ID` was not found in the incoming request. Generated new GUID: 6f23cbf174004ac9ad2ba1c59894af5b
This is not good, can you adjust the worker timeout here:
/etc/systemd/system/pulpcore-api.service you want to add two options to the ExecStart line
ExecStart=/usr/libexec/pulpcore/gunicorn pulpcore.app.wsgi:application \
--timeout 90 \
-w 8 \
--access-logfile -
Then lets do
sudo systemctl daemon-reload
systemctl restart pulpcore-api
OK, after these changes I was indeed able to publish a few CVVs. One of the publishes I resumed from the error did error again, but did then complete on the second attempt.
1 Like
I spoke too soon - I just ran our script for auto publication again, and it has failed in the same/similar way for at least one Content View…
No CRITICAL in /var/log/messages this time.
[Edit: Make that 2 Content Views, both Oracle Linux - which might mean another issue I reported around Pulp RAM usage could be part of the problem. No OOM this time though]
1 Like
@John_Beranek
Can you run journalctl -u pulpcore-worker@* and see if there are any tracebacks or if there any worker messages related messages?
Oddly, no. The only thing I have is from the Foreman production.log:
2021-04-29T13:13:29 [I|app|d8b00f82] CONTENT_INDEX type=Katello::Rpm duration=11500.25
2021-04-29T13:13:30 [I|app|d8b00f82] CONTENT_INDEX type=Katello::ModuleStream duration=159.63
2021-04-29T13:13:33 [I|app|d8b00f82] CONTENT_INDEX type=Katello::Erratum duration=3363.3
2021-04-29T13:13:33 [I|app|d8b00f82] CONTENT_INDEX type=Katello::PackageGroup duration=107.72
2021-04-29T13:13:34 [I|app|d8b00f82] CONTENT_INDEX type=Katello::Srpm duration=763.58
2021-04-29T13:13:34 [I|app|d8b00f82] CONTENT_INDEX type=Katello::Rpm duration=322.45
2021-04-29T13:13:34 [I|app|d8b00f82] CONTENT_INDEX type=Katello::ModuleStream duration=73.98
2021-04-29T13:13:34 [I|app|d8b00f82] CONTENT_INDEX type=Katello::Erratum duration=80.8
2021-04-29T13:13:34 [I|app|d8b00f82] CONTENT_INDEX type=Katello::PackageGroup duration=82.85
2021-04-29T13:13:35 [I|app|d8b00f82] CONTENT_INDEX type=Katello::Srpm duration=96.71
2021-04-29T13:13:36 [E|bac|d8b00f82] Error message: the server returns an error (PulpRpmClient::ApiError)
d8b00f82 | /usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api_client.rb:88:in `rescue in call_api'
d8b00f82 | /usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api_client.rb:66:in `call_api'
d8b00f82 | /usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api/content_packages_api.rb:244:in `list_with_http_info'
d8b00f82 | /usr/share/gems/gems/pulp_rpm_client-3.10.0/lib/pulp_rpm_client/api/content_packages_api.rb:130:in `list'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:93:in `content_unit_list'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:106:in `fetch_content_list'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:75:in `block (2 levels) in pulp_units_batch_for_repo'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:69:in `loop'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/services/katello/pulp3/pulp_content_unit.rb:69:in `block in pulp_units_batch_for_repo'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/models/katello/concerns/pulp_database_unit.rb:120:in `each'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/models/katello/concerns/pulp_database_unit.rb:120:in `import_for_repository'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:902:in `block (2 levels) in index_content'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/lib/katello/logging.rb:6:in `time'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:901:in `block in index_content'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:900:in `each'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/models/katello/repository.rb:900:in `index_content'
d8b00f82 | /usr/share/gems/gems/katello-4.0.0/app/lib/actions/katello/repository/index_content.rb:18:in `run'
d8b00f82 | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:571:in `block (3 levels) in execute_run'
d8b00f82 | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
d8b00f82 | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
@Justin_Sherrill
Do you have any insights to this one, the worker timeout sadly didn’t fix the issue with the cv publishing. It did get rid of the critical error in /var/log/messages
I would try reducing the ‘bulk load size’ in katello, essentially katello is fetching a lot of items and pulp is not responding within the timeout time. We can adjust both sides of this to try to improve it.
in /etc/foreman/plugins/katello.yaml
add under :katello_applicability: true
:katello_applicability: true
:pulp:
:bulk_load_size: 500
and restart the services:
foreman-maintain service restart
then give it a try. Note that this will be wiped out anytime you re-run the installer, but we’ve made it easier in 4.1 to adjust this setting from the Administer > settings page in 4.1
Unfortunately not quite doing it…watching journalctl I see things like:
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: Worker '1285@katello.example.com' has gone missing, removing from list of workers
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: The worker named 1285@katello.example.com is missing. Canceling the tasks in its queue.
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: Worker '1270@katello.example.com' has gone missing, removing from list of workers
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: The worker named 1270@katello.example.com is missing. Canceling the tasks in its queue.
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: Worker '1299@katello.example.com' has gone missing, removing from list of workers
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: The worker named 1299@katello.example.com is missing. Canceling the tasks in its queue.
Apr 29 14:24:11 katello.example.com pulpcore-worker-2[66046]: pulp [None]: pulpcore.tasking.util:INFO: Canceling task: c2e7a351-9926-4ca5-8b72-3ee3956bbf46
Apr 29 14:24:12 katello.example.com pulpcore-worker-6[66052]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: Worker '1299@katello.example.com' has gone missing, removing from list of workers
Apr 29 14:24:12 katello.example.com pulpcore-worker-6[66052]: pulp [None]: pulpcore.tasking.services.worker_watcher:ERROR: The worker named 1299@katello.example.com is missing. Canceling the tasks in its queue.
Are you sure those messages weren’t from the service restart? What was the behavior of the CV publish?
Are you running on HDDs? or SSDs?
Can you confirm that /usr/lib/python3.6/site-packages/pulpcore/tasking/constants.py has WORKER_TTL=300 ?
Definitely not during the service restart, they correspond with production.log sections like:
2021-04-29T14:24:18 [E|bac|ad38adab] Task canceled (Katello::Errors::Pulp3Error)
ad38adab | /usr/share/gems/gems/katello-4.0.0/app/lib/actions/pulp3/abstract_async_task.rb:102:in `block in check_for_errors'
ad38adab | /usr/share/gems/gems/katello-4.0.0/app/lib/actions/pulp3/abstract_async_task.rb:100:in `each'
ad38adab | /usr/share/gems/gems/katello-4.0.0/app/lib/actions/pulp3/abstract_async_task.rb:100:in `check_for_errors'
ad38adab | /usr/share/gems/gems/katello-4.0.0/app/lib/actions/pulp3/abstract_async_task.rb:133:in `poll_external_task'
ad38adab | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/polling.rb:100:in `poll_external_task_with_rescue'
ad38adab | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/polling.rb:22:in `run'
ad38adab | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action/cancellable.rb:14:in `run'
ad38adab | /usr/share/gems/gems/katello-4.0.0/app/lib/actions/pulp3/abstract_async_task.rb:10:in `run'
ad38adab | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/action.rb:571:in `block (3 levels) in execute_run'
ad38adab | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware/stack.rb:27:in `pass'
ad38adab | /usr/share/gems/gems/dynflow-1.4.7/lib/dynflow/middleware.rb:19:in `pass'
Katello is running on a VM using a software-defined storage system, with SSDs for all writes, HDDs for cold data.
# cat /usr/lib/python3.6/site-packages/pulpcore/tasking/constants.py
from types import SimpleNamespace
TASKING_CONSTANTS = SimpleNamespace(
# The name of resource manager entries in the workers table
RESOURCE_MANAGER_WORKER_NAME="resource-manager",
# The amount of time (in seconds) after which a worker process is considered missing.
WORKER_TTL=300,
# The amount of time (in seconds) between checks
JOB_MONITORING_INTERVAL=5,
)
The job is left in the Paused/Error state in the step Actions::Pulp3::Repository::RefreshDistribution, which admittedly is different to the original behaviour.
anything in dmesg or /var/log/message during this time? The fact that a worker has gone missing multiple times within a couple seconds makes me think that an OOM or something else is killing it?
Nothing else I can see in dmesg/messages at that time, no OOM.
I resumed 2 CVVs publish tasks, one went to paused/error and another is still at running/error but apparently the VM is idle.
is postgresql on the same box or external? Can you check journalctl for it and look for any errors?
PostgreSQL is on the same server, there is nothing in the journal for it.
