Verify Checksum task fails with 'md5' error

Support
#1

Problem:
After an upgrade to Katello 3.1x we had lots of issues with our repositories, which did not migrate correctly from pulp 2 to 3. After upgrading now to Katello 4.3 we tried again to repair our faulty repositories. The task starts fine and identifies missing content, and then it aborts with an ‘md5’ error.

Expected outcome:
The repair to finish, download the missing and invalid files. Oh, and to tell me which file is failing when it raises an error.

Foreman and Proxy versions:
3.1.2

Foreman and Proxy plugin versions:
Katello 4.3

Distribution and version:
CentOS 7.9

Other relevant data:
The task fails here:

2022-02-28T14:39:09 [E|bac|522fef72] 'md5' (Katello::Errors::Pulp3Error)
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/pulp3/abstract_async_task.rb:108:in `block in check_for_errors'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/pulp3/abstract_async_task.rb:106:in `each'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/pulp3/abstract_async_task.rb:106:in `check_for_errors'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/pulp3/abstract_async_task.rb:160:in `poll_external_task'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/polling.rb:100:in `poll_external_task_with_rescue'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/polling.rb:22:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/cancellable.rb:14:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/pulp3/abstract_async_task.rb:10:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:582:in `block (3 levels) in execute_run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:32:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/middleware/remote_action.rb:16:in `block in run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/middleware/remote_action.rb:40:in `block in as_remote_user'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/models/katello/concerns/user_extensions.rb:21:in `cp_config'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/middleware/remote_action.rb:27:in `as_cp_user'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/middleware/remote_action.rb:39:in `as_remote_user'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-4.3.0/app/lib/actions/middleware/remote_action.rb:16:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.7/lib/active_support/execution_wrapper.rb:88:in `wrap'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action/progress.rb:17:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/load_setting_values.rb:20:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:52:in `restore_current_request_id'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:32:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:27:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware.rb:19:in `pass'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:54:in `restore_curent_user'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-5.2.0/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/stack.rb:23:in `call'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/middleware/world.rb:31:in `execute'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:581:in `block (2 levels) in execute_run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:580:in `catch'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:580:in `block in execute_run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:483:in `block in with_error_handling'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:483:in `catch'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:483:in `with_error_handling'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:575:in `execute_run'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/action.rb:296:in `execute'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/director.rb:94:in `execute'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors.rb:18:in `run_user_code'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
 522fef72 | /opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.6.3/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
 522fef72 | [ sidekiq ]
 522fef72 | [ concurrent-ruby ]
2022-02-28T14:39:09 [I|bac|522fef72] Task {label: Actions::Katello::Repository::VerifyChecksum, id: 0f918c59-6ff8-4384-9291-f0c253f02b8b, execution_plan_id: 080b7542-9617-40c7-8a60-8b6117885643} state changed: stopped  result: warning```
#2

@rbremer Could you look around for any Pulp logs associated with this error? There has to be more context somewhere than “md5”

#3

@dralley I have checked the /v/l/messages file, this is all I can see:

Mar  2 11:42:21 foreman pulpcore-worker-4: pulp [037a4a8f-a289-41b0-b632-d0528e4c8954]: pulpcore.app.tasks.repository:WARNING: Missing file for <Artifact: pk=1d026c44-39b2-478a-b9a7-daa6980eefb9>
Mar  2 11:42:23 foreman pulpcore-worker-4: pulp [037a4a8f-a289-41b0-b632-d0528e4c8954]: pulpcore.app.tasks.repository:WARNING: Missing file for <Artifact: pk=a1fbd944-71af-4e00-8aba-1f6fd39f0771>
Mar  2 11:42:23 foreman pulpcore-worker-4: pulp [037a4a8f-a289-41b0-b632-d0528e4c8954]: pulpcore.tasking.pulpcore_worker:INFO: Task fa0e242b-040f-42e4-9a44-0a487806852d failed ('md5')
Mar  2 11:42:23 foreman pulpcore-worker-4: pulp [037a4a8f-a289-41b0-b632-d0528e4c8954]: pulpcore.tasking.pulpcore_worker:INFO:   File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/tasking/pulpcore_worker.py", line 377, in _perform_task
Mar  2 11:42:23 foreman pulpcore-worker-4: result = func(*args, **kwargs)
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/tasks/repository.py", line 176, in repair_version
Mar  2 11:42:23 foreman pulpcore-worker-4: loop.run_until_complete(
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/rh/rh-python38/root/usr/lib64/python3.8/asyncio/base_events.py", line 616, in run_until_complete
Mar  2 11:42:23 foreman pulpcore-worker-4: return future.result()
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/tasks/repository.py", line 150, in _repair_artifacts_for_content
Mar  2 11:42:23 foreman pulpcore-worker-4: await asyncio.gather(*done)  # Clean up tasks
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/app/tasks/repository.py", line 78, in _repair_ca
Mar  2 11:42:23 foreman pulpcore-worker-4: dl_result = await downloader.run()
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/download/http.py", line 259, in run
Mar  2 11:42:23 foreman pulpcore-worker-4: return await download_wrapper()
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/backoff/_async.py", line 133, in retry
Mar  2 11:42:23 foreman pulpcore-worker-4: ret = await target(*args, **kwargs)
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/download/http.py", line 255, in download_wrapper
Mar  2 11:42:23 foreman pulpcore-worker-4: return await self._run(extra_data=extra_data)
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulp_rpm/app/downloaders.py", line 118, in _run
Mar  2 11:42:23 foreman pulpcore-worker-4: to_return = await self._handle_response(response)
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/download/http.py", line 207, in _handle_response
Mar  2 11:42:23 foreman pulpcore-worker-4: await self.finalize()
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/download/base.py", line 166, in finalize
Mar  2 11:42:23 foreman pulpcore-worker-4: self.validate_digests()
Mar  2 11:42:23 foreman pulpcore-worker-4: File "/opt/theforeman/tfm-pulpcore/root/usr/lib/python3.8/site-packages/pulpcore/download/base.py", line 215, in validate_digests
Mar  2 11:42:23 foreman pulpcore-worker-4: if expected_digest != self._digests[algorithm].hexdigest():
Mar  2 11:42:23 foreman qpidd[71275]: 2022-03-02 11:42:23 [System] error Error reading socket: Encountered end of file [-5938]
Mar  2 11:42:23 foreman qpidd: 2022-03-02 11:42:23 [System] error Error reading socket: Encountered end of file [-5938]

Unfortunately, I cannot figure out which file it has issues with and I also don’t find an option to completely clean out a repository and re-download it.

Does that help?

#4

Cool, thanks. So this is interesting. It seems as if, either the file has changed in the remote repo and no longer has the same checksum, or all of that is correct but the downloading of the files that occurs during the repair operation is faulty.

#5

@rbremer Is this repeatable? If you run the repair operation multiple times does it fail like this every time?

#6

@dralley yes, every single time. I tried many things now, first run a normal sync - after changing the sync mode to “Content Only” - to get rid of older packages and then ran a validate checksum sync, always fails with md5. Unfortunately, I don’t know which package, otherwise I could re-download it manually and replace it inside of the repo…