Syncing repo returns : PLP0000: Importer indicated a failed response

Support
1

Hi,

Problem:
Since upgrade TFM to 3.18 and Katello 3.7 i’m having trouble syncing some repositories:
For ex:

  • Red Hat Enterprise Linux 7 Server - Optional RPMs x86_64 7.4 returns error: PLP0000: invalid length or type code
  • EPEL 7 - x86_64 returns error: PLP0000: Importer indicated a failed response

The upgrade from TFM 1.17.1 & Katello 3.6 did run without problems.
Expected outcome:
Syncing repos without errors as before when using Katello 3.6
Foreman and Proxy versions:
foreman-1.18.0-2.el7.noarch
foreman-proxy-1.18.0-1.el7.noarch
Foreman and Proxy plugin versions:
katello-3.7.0-4.el7.noarch
Other relevant data:
[e.g. logs from Foreman and/or the Proxy, modified templates, commands issued, etc]
Log extract

Response: 200: {"exception": null, "task_type": "pulp.server.managers.repo.sync.sync", "_href": "/pulp/api/v2/tasks/8fd59285-b8d8-48f3-a519-427ca656ac1d/", "task_id": "8fd59285-b8d8-48f3-a519-427ca656ac1d", "tags": ["pulp:repository:e5ea2d9a-2661-4adb-85b1-cfdee667169f", "pulp:action:sync"], "finish_time": "2018-07-31T09:09:27Z", "_ns": "task_status", "start_time": "2018-07-31T09:05:02Z", "traceback": "Traceback (most recent call last):\n  File \"/usr/lib/python2.7/site-packages/celery/app/trace.py\", line 367, in trace_task\n    R = retval = fun(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py\", line 529, in __call__\n    return super(Task, self).__call__(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py\", line 107, in __call__\n    return super(PulpTask, self).__call__(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/celery/app/trace.py\", line 622, in __protected_call__\n    return self.run(*args, **kwargs)\n  File \"/usr/lib/python2.7/site-packages/pulp/server/controllers/repository.py\", line 827, in sync\n    raise pulp_exceptions.PulpExecutionException(_('Importer indicated a failed response'))\nPulpExecutionException: Importer indicated a failed response\n", "spawned_tasks": [], "progress_report": {"yum_importer": {"content": {"size_total": 0, "items_left": 0, "items_total": 0, "state": "FAILED", "size_left": 0, "details": {"rpm_total": 0, "rpm_done": 0, "drpm_total": 0, "drpm_done": 0}, "error": "BSONElement: bad type 99", "error_details": []}, "comps": {"state": "NOT_STARTED"}, "purge_duplicates": {"state": "NOT_STARTED"}, "distribution": {"items_total": 0, "state": "NOT_STARTED", "error_details": [], "items_left": 0}, "errata": {"state": "NOT_STARTED"}, "metadata": {"state": "FINISHED"}}}, "queue": "reserved_resource_worker-0@spfy-tfm.xxxx.xxxx.xxx.dq2", "state": "error", "worker_name": "reserved_resource_worker-0@spfy-tfm.xxxx.xxxx.xxxx", "result": null, "error": {"code": "PLP0000", "data": {}, "description": "Importer indicated a failed response", "sub_errors": []}, "_id": {"$oid": "5b60263e7267bcf978e31731"}, "id": "5b60263e7267bcf978e31731"}
2018-07-31T11:09:41  [app] [D] Setting current user thread-local variable to nil
2018-07-31T11:09:41  [background] [E] PLP0000: Importer indicated a failed response (Katello::Errors::PulpError)
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/pulp/abstract_async_task.rb:121:in `block in external_task='
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/pulp/abstract_async_task.rb:119:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/pulp/abstract_async_task.rb:119:in `external_task='
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/pulp/repository/sync.rb:48:in `external_task='
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action/polling.rb:98:in `poll_external_task_with_rescue'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action/polling.rb:21:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action/cancellable.rb:13:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/pulp/abstract_async_task.rb:45:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:538:in `block (3 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:31:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/remote_action.rb:16:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/remote_action.rb:40:in `block in as_remote_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/models/katello/concerns/user_extensions.rb:21:in `cp_config'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/remote_action.rb:27:in `as_cp_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/remote_action.rb:39:in `as_remote_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/remote_action.rb:16:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.13.2/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/activesupport-5.1.6/lib/active_support/execution_wrapper.rb:85:in `wrap'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.13.2/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action/progress.rb:30:in `with_progress_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action/progress.rb:16:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/keep_locale.rb:11:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/keep_locale.rb:22:in `with_locale'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.7.0/app/lib/actions/middleware/keep_locale.rb:11:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.13.2/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.13.2/app/lib/actions/middleware/keep_current_user.rb:43:in `restore_curent_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.13.2/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:18:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware.rb:31:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/middleware/world.rb:30:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:537:in `block (2 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:536:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:536:in `block in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:451:in `block in with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:451:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:451:in `with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:531:in `execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/action.rb:278:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block (2 levels) in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/execution_plan/steps/abstract.rb:162:in `with_meta_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `block in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:30:in `open_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:15:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/director.rb:56:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/executors/parallel/worker.rb:12:in `block in on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/executors.rb:12:in `run_user_code'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/executors/parallel/worker.rb:11:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.0.5/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/core.rb:161:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/core.rb:95:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/core.rb:118:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `block in synchronize'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.4/lib/concurrent/actor/core.rb:115:in `block in schedule_execution'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:348:in `run_task'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:337:in `block (3 levels) in create_worker'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `loop'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:320:in `block (2 levels) in create_worker'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `catch'
/opt/theforeman/tfm-ror51/root/usr/share/gems/gems/concurrent-ruby-1.0.5/lib/concurrent/executor/ruby_thread_pool_executor.rb:319:in `block in create_worker'
/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'

It seems this is a pulp issue, i’ve already tried Bug #24443: 3.6 -> 3.7 upgrade on proxy does not always migrate pulp db - Katello - Foreman but it didn’t help.

Any idea or help how to debug that problem?

Thanks,
Arsene

2

it looks my mongo DB is corrupt, when trying to dump the DB i do get an error:

mongodump --host localhost --out /tmp/mongo_dump
2018-08-02T10:24:53.844+0200 writing pulp_database.repo_content_units to
2018-08-02T10:24:53.844+0200 writing pulp_database.lazy_content_catalog to
2018-08-02T10:24:53.844+0200 writing pulp_database.units_rpm to
2018-08-02T10:24:53.844+0200 writing pulp_database.erratum_pkglists to
2018-08-02T10:24:54.144+0200 done dumping pulp_database.erratum_pkglists (22945 documents)
2018-08-02T10:24:54.145+0200 writing pulp_database.units_erratum to
2018-08-02T10:24:54.299+0200 Failed: error writing data for collection pulp_database.units_erratum to disk: error reading collection: Document is corrupted

using db.repairDatabase() to repair the mongo DB didn’t resolve the problem, ist there another way to repair that corrupted document?

Thank for any help.
rgds, arsene

4

Hey @Arsene, apologies no one got back to you. Are you still having this issue or similar issues?

5

Hi John,

I couldn’t find a solution for that problem, I’ve tried several time the upgrade using previous snapshots but everytime i ran into the same problem after several days. So finally i did a fresh install based on TFM 1.19 and Katello 3.8 and since then it looks fine.
I suppose it’s due to the mongo update between 3.17 and 3.18 but i couldn’t locate exactly the problem. The error points to a storage failure but my installation is on a VM running on oVirt with several other VMs running without problem.
I still have this VM with the problem if you would investigate further .

Thanks,
Arsene

6

Glad to hear a fresh install is working fine. If the mongo db was corrupt and ‘repairDatabase()’ didn’t work, there isn’t much to be done except try to hunt down the corrupt data (which looked like errata in your case)

Let us know if you hit any more issues!