2 repos never sync - stuck on "waiting for Pulp to start the task"

Problem:
I have 2 repos exhibiting this behavior. All of my other repos are syncing successfully

Expected outcome:
Repo syncs successfully

Foreman and Proxy versions:
2.1.2

Foreman and Proxy plugin versions:
Katello 3.16.0

Distribution and version:
CentOS 7

Other relevant data:
From the Dynflow console:
Actions::Pulp3::Repository::Sync (waiting for Pulp to start the task) [ 28231.80s / 100.86s ]

Input:

repo_id: 59
smart_proxy_id: 1
options:
smart_proxy_id: 1
repo_id: 59
source_url:
options: {}
remote_user: admin
remote_cp_user: admin
current_request_id:
current_timezone: America/New_York
current_user_id: 5
current_organization_id: 1
current_location_id:

Output:

pulp_tasks:

  • !ruby/object:Katello::Pulp3::Task
    smart_proxy: !ruby/object:SmartProxy
    concise_attributes:
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: id
      value_before_type_cast: 1
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: name
      value_before_type_cast: lxcfg015.phibred.com
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: url
      value_before_type_cast: https://lxcfg015.phibred.com:9090
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: created_at
      value_before_type_cast: 2020-09-08 15:08:29.012550000 Z
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: updated_at
      value_before_type_cast: 2020-09-08 15:08:31.922669000 Z
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: expired_logs
      value_before_type_cast: ‘0’
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: puppet_path
      value_before_type_cast: “/etc/puppetlabs/code/environments”
    • !ruby/object:ActiveModel::Attribute::FromDatabase
      name: download_policy
      value_before_type_cast: on_demand
      new_record: false
      active_record_yaml_version: 2
      pulp_data: !ruby/hash:ActiveSupport::HashWithIndifferentAccess
      pulp_href: “/pulp/api/v3/tasks/8e98103f-58ab-4201-a886-af85b60b42c7/”
      pulp_created: ‘2020-10-23T19:17:28.590+00:00’
      state: waiting
      name: pulp_rpm.app.tasks.synchronizing.synchronize
      worker: “/pulp/api/v3/workers/9849307c-21cc-4f2b-92a7-82282aaa7050/”
      child_tasks:
      progress_reports:
      created_resources:
      reserved_resources_record:
    • “/pulp/api/v3/repositories/rpm/rpm/db3e6681-45d7-402a-bd4c-d1afbfd7c716/”
    • “/pulp/api/v3/remotes/rpm/rpm/6116a632-d5cd-4a31-941a-966299fe8c79/”
      href: “/pulp/api/v3/tasks/8e98103f-58ab-4201-a886-af85b60b42c7/”
      create_version: true
      task_groups:
      poll_attempts:
      total: 1778
      failed: 0

The task gets stuck here at 4% complete and stays that way indefinitely. It’s been sitting here like this for over 8 hours, and the poll_attempts just keeps climbing.

Following up to add some additional information. It appears that eventually the sync does indeed fail. Here are the relevant errors:

Exception:
NameError: undefined local variable or method `pulp_task' for #<Katello::Pulp3::Task:0x0000000013a03fa8>
Did you mean?  @pulp_data

Backtrace:
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/services/katello/pulp3/task.rb:94:in `cancel'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/pulp3/abstract_async_task.rb:76:in `block in cancel'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/pulp3/abstract_async_task.rb:76:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/pulp3/abstract_async_task.rb:76:in `cancel'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/pulp3/abstract_async_task.rb:68:in `cancel!'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action/cancellable.rb:10:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/pulp3/abstract_async_task.rb:10:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:563:in `block (3 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:32:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/middleware/remote_action.rb:16:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.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.16.0/app/models/katello/concerns/user_extensions.rb:21:in `cp_config'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/middleware/remote_action.rb:27:in `as_cp_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/middleware/remote_action.rb:39:in `as_remote_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/lib/actions/middleware/remote_action.rb:16:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/rails_executor_wrap.rb:14:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/execution_wrapper.rb:88:in `wrap'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/rails_executor_wrap.rb:13:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action/progress.rb:31:in `with_progress_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action/progress.rb:17:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_request_id.rb:15:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_request_id.rb:49:in `restore_current_request_id'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_request_id.rb:15:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_timezone.rb:15:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_timezone.rb:44:in `restore_curent_timezone'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_timezone.rb:15:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_user.rb:15:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_user.rb:44:in `restore_curent_user'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_user.rb:15:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_taxonomies.rb:45:in `restore_current_taxonomies'
/opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-2.0.2/app/lib/actions/middleware/keep_current_taxonomies.rb:15:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:27:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:19:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware.rb:32:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/stack.rb:23:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/middleware/world.rb:31:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:562:in `block (2 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:561:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:561:in `block in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `block in with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:475:in `with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:556:in `execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/action.rb:285:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:18:in `block (2 levels) in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract.rb:167:in `with_meta_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:17:in `block in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:32:in `open_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:16:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/director.rb:93:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:11:in `block (2 levels) in perform'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/executors.rb:18:in `run_user_code'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:9:in `block in perform'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:25:in `with_telemetry'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/worker_jobs.rb:8:in `perform'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/executors/sidekiq/serialization.rb:27:in `perform'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:192:in `execute_job'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:165:in `block (2 levels) in process'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:164:in `block in process'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:137:in `block (6 levels) in dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:109:in `local'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:136:in `block (5 levels) in dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq.rb:37:in `block in <module:Sidekiq>'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:132:in `block (4 levels) in dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:250:in `stats'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:127:in `block (3 levels) in dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/job_logger.rb:8:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:126:in `block (2 levels) in dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/job_retry.rb:74:in `global'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:125:in `block in dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:48:in `with_context'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/logging.rb:42:in `with_job_hash_context'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:124:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:163:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:83:in `process_one'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/processor.rb:71:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:16:in `watchdog'
/opt/theforeman/tfm/root/usr/share/gems/gems/sidekiq-5.2.7/lib/sidekiq/util.rb:25:in `block in safe_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'

@mark.frank can you add a new issue for this at Issues - Katello - Foreman ?

Appending the details as per your second message would be great. If not, let me know here and I’ll create the issue. As soon as we can, we’ll triage the issue.

In the meantime, I’ll query folks on the team to see if they recognize the issue.

@mark.frank Can you try restarting pulpcore-worker@* and pulpcore-resource-manager and retrying?

I restarted all of those services and started a manual sync, but at first glance it appears the hang is still occurring. I’m seeing poll_attempts climb and the task is stuck at 4% again.

One other thing I noticed when checking the pulpcore-worker@* services is that they all are showing this message if I do a systemctl status command. Not sure if the “write concern for Mongo connection” is expected behavior or not.

[root@lxcfg015 ~]# systemctl status pulp_worker-1.service

  • pulp_worker-1.service - Pulp Worker #1
    Loaded: loaded (/run/systemd/system/pulp_worker-1.service; static; vendor preset: disabled)
    Active: active (running) since Mon 2020-10-26 13:17:51 CDT; 11min ago
    Main PID: 19472 (celery)
    Tasks: 9
    CGroup: /system.slice/pulp_worker-1.service
    |-19472 /usr/bin/python /usr/bin/celery worker -n reserved_resource_worker-1@%h -A pulp.server.async.app -c 1 --events --umask 18 --pidfile=/var/run/pulp/reserved_resource_worker-1.pid
    `-19493 /usr/bin/python /usr/bin/celery worker -n reserved_resource_worker-1@%h -A pulp.server.async.app -c 1 --events --umask 18 --pidfile=/var/run/pulp/reserved_resource_worker-1.pid

Oct 26 13:17:53 lxcfg015.phibred.com pulp[19472]: celery.worker.consumer.connection:INFO: Connected to qpid://localhost:5671//
Oct 26 13:17:53 lxcfg015.phibred.com pulp[19472]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Oct 26 13:17:53 lxcfg015.phibred.com pulp[19472]: pulp.server.async.worker_watcher:INFO: New worker ‘reserved_resource_worker-1@lxcfg015.phibred.com’ discovered
Oct 26 13:17:53 lxcfg015.phibred.com pulp[19472]: celery.apps.worker:INFO: reserved_resource_worker-1@lxcfg015.phibred.com ready.
Oct 26 13:17:53 lxcfg015.phibred.com pulp[19493]: pulp.server.db.connection:INFO: Write concern for Mongo connection: {}
Oct 26 13:27:44 lxcfg015.phibred.com pulp[19472]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[750019f3-4d2d-48fb-9841-baccdca7430b]
Oct 26 13:27:44 lxcfg015.phibred.com pulp[19493]: py.warnings:WARNING: [750019f3] (19493-58368) /usr/lib64/python2.7/site-packages/pymongo/topology.py:74: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forkin…
Oct 26 13:27:44 lxcfg015.phibred.com pulp[19493]: py.warnings:WARNING: [750019f3] (19493-58368) "MongoClient opened before fork. Create MongoClient "
Oct 26 13:27:44 lxcfg015.phibred.com pulp[19493]: py.warnings:WARNING: [750019f3] (19493-58368)
Oct 26 13:27:44 lxcfg015.phibred.com pulp[19493]: celery.app.trace:INFO: [750019f3] Task pulp.server.controllers.repository.download_deferred[750019f3-4d2d-48fb-9841-baccdca7430b] succeeded in 0.0187435508706s: None
Hint: Some lines were ellipsized, use -l to show in full.
[root@lxcfg015 ~]#

Bug #31176 created. Hopefully I did it right. :grinning:

1 Like

Yeah, that looks fine to me. That should be fine for going forward.

In general, this is related to Pulp3 (and hence the pulpcore processes). I don’t believe the Mongo related messages are relevant in this case.

I’ll add a link on the issue related to this discussion for completeness.

I met same problem for some of my repos.
Re-creation of those repos solved issue for me.