Bug 1264330 - Pulp repo sync taks never completing
Pulp repo sync taks never completing
Status: CLOSED CURRENTRELEASE
Product: Red Hat Satellite 6
Classification: Red Hat
Component: Pulp (Show other bugs)
6.1.2
Unspecified Unspecified
urgent Severity high (vote)
: Unspecified
: --
Assigned To: satellite6-bugs
Katello QA List
:
Depends On:
Blocks: 1122832
  Show dependency treegraph
 
Reported: 2015-09-18 04:30 EDT by Peter Vreman
Modified: 2017-02-23 14:46 EST (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2015-12-30 03:40:31 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
sosreport (8.75 MB, application/x-xz)
2015-09-18 10:36 EDT, Peter Vreman
no flags Details

  None (edit)
Description Peter Vreman 2015-09-18 04:30:55 EDT
Description of problem:
We have pulp repo sync tasks that are staying on incomplete state for 6+ hours. Therefor the Katello repository sync tasks will also not complete. From the logging it looks like the yum_import finished quickly, but the overall task state is not updated.

It happends with both standard RedHat repositories as well as with Custom product repositories.
It happend both with only a single repo sync task running (Custom product case) as well as many (50+) concurrent tasks during a daily RedHat repo sync.


----- Incomplete task 1 of RedHat Repository:
[crash] root@li-lc-1578:~# date
Fri Sep 18 08:07:04 GMT 2015

[crash] root@li-lc-1578:~# pulp-admin tasks list | grep -B6 38c30954-c2bd-4a85-b6c6-951a0b23bee2
Operations:  sync
Resources:   Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_6_Serv
             er_-_Oracle_Java_RPMs_x86_64_6Server (repository)
State:       Running
Start Time:  2015-09-18T02:00:23Z
Finish Time: Incomplete
Task Id:     38c30954-c2bd-4a85-b6c6-951a0b23bee2

[crash] root@li-lc-1578:~# grep 38c30954-c2bd-4a85-b6c6-951a0b23bee2 /var/log/messages
Sep 18 02:00:23 li-lc-1578 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.sync.sync[38c30954-c2bd-4a85-b6c6-951a0b23bee2]
Sep 18 02:00:47 li-lc-1578 pulp: pulp.server.event.http:INFO: (29212-74560) {'call_report': {u'exception': None, u'task_type': u'pulp.server.managers.repo.sync.sync', u'task_id': u'38c30954-c2bd-4a85-b6c6-951a0b23bee2', u'tags': [u'pulp:repository:Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_6_Server_-_Oracle_Java_RPMs_x86_64_6Server', u'pulp:action:sync'], u'finish_time': None, u'_ns': u'task_status', u'start_time': u'2015-09-18T02:00:23Z', u'traceback': None, u'spawned_tasks': [], u'progress_report': {u'yum_importer': {u'content': {u'size_total': 0, u'items_left': 0, u'items_total': 0, u'state': u'FINISHED', u'size_left': 0, u'details': {u'rpm_total': 0, u'rpm_done': 0, u'drpm_total': 0, u'drpm_done': 0}, u'error_details': []}, u'comps': {u'state': u'FINISHED'}, u'distribution': {u'items_total': 0, u'state': u'FINISHED', u'error_details': [], u'items_left': 0}, u'errata': {u'state': u'FINISHED'}, u'metadata': {u'state': u'FINISHED'}}}, u'state': u'running', u'worker_name': u'reserved_resource_worker-5@li-lc-1578', u'result': None, u'error': None, u'_id': ObjectId('55fb7037874b58303c5d7e5b'), u'id': u'55fb70370586fe0ea2c21ceb'}, 'event_type': 'repo.sync.finish', 'payload': {'importer_id': u'yum_importer', 'exception': None, 'repo_id': u'Hilti-Oracle_Java__for_RHEL_Server_-Red_Hat_Enterprise_Linux_6_Server_-_Oracle_Java_RPMs_x86_64_6Server', 'traceback': None, 'started': '2015-09-18T02:00:23Z', '_ns': u'repo_sync_results', 'completed': '2015-09-18T02:00:47Z', 'importer_type_id': u'yum_importer', 'error_message': None, 'summary': {'content': {'state': 'FINISHED'}, 'comps': {'state': 'FINISHED'}, 'distribution': {'state': 'FINISHED'}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'added_count': 0, 'result': 'success', 'updated_count': 17, 'details': {'content': {'size_total': 0, 'items_left': 0, 'items_total': 0, 'state': 'FINISHED', 'size_left': 0, 'details': {'rpm_total': 0, 'rpm_done': 0, 'drpm_total': 0, 'drpm_done': 0}, 'error_details': []}, 'comps': {'state': 'FINISHED'}, 'distribution': {'


----- Incomplete task 2 with Custom Product:
[crash] root@li-lc-1578:~# pulp-admin tasks list | grep -B6 aa993623-b01b-49ec-ba7f-0ac6d892ac0b

Operations:  sync
Resources:   Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9 (repository)
State:       Running
Start Time:  2015-09-17T20:08:52Z
Finish Time: Incomplete
Task Id:     aa993623-b01b-49ec-ba7f-0ac6d892ac0b
[crash] root@li-lc-1578:~# date
Fri Sep 18 08:24:19 GMT 2015
[crash] root@li-lc-1578:~# grep aa993623-b01b-49ec-ba7f-0ac6d892ac0b /var/log/messages
Sep 17 20:08:52 li-lc-1578 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.sync.sync[aa993623-b01b-49ec-ba7f-0ac6d892ac0b]
Sep 17 20:08:58 li-lc-1578 pulp: pulp.server.event.http:INFO: (29249-25184) {'call_report': {u'exception': None, u'task_type': u'pulp.server.managers.repo.sync.sync', u'task_id': u'aa993623-b01b-49ec-ba7f-0ac6d892ac0b', u'tags': [u'pulp:repository:Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9', u'pulp:action:sync'], u'finish_time': None, u'_ns': u'task_status', u'start_time': u'2015-09-17T20:08:52Z', u'traceback': None, u'spawned_tasks': [], u'progress_report': {u'yum_importer': {u'content': {u'size_total': 80203, u'items_left': 0, u'items_total': 3, u'state': u'FINISHED', u'size_left': 0, u'details': {u'rpm_total': 3, u'rpm_done': 3, u'drpm_total': 0, u'drpm_done': 0}, u'error_details': []}, u'comps': {u'state': u'FINISHED'}, u'distribution': {u'items_total': 0, u'state': u'FINISHED', u'error_details': [], u'items_left': 0}, u'errata': {u'state': u'FINISHED'}, u'metadata': {u'state': u'FINISHED'}}}, u'state': u'running', u'worker_name': u'reserved_resource_worker-3@li-lc-1578', u'result': None, u'error': None, u'_id': ObjectId('55fb1dd4874b58303c5d7e55'), u'id': u'55fb1dd40586fe0ea2c21cb7'}, 'event_type': 'repo.sync.finish', 'payload': {'importer_id': u'yum_importer', 'exception': None, 'repo_id': u'Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9', 'traceback': None, 'started': '2015-09-17T20:08:52Z', '_ns': u'repo_sync_results', 'completed': '2015-09-17T20:08:58Z', 'importer_type_id': u'yum_importer', 'error_message': None, 'summary': {'content': {'state': 'FINISHED'}, 'comps': {'state': 'FINISHED'}, 'distribution': {'state': 'FINISHED'}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'added_count': 3, 'result': 'success', 'updated_count': 10, 'details': {'content': {'size_total': 80203, 'items_left': 0, 'items_total': 3, 'state': 'FINISHED', 'size_left': 0, 'details': {'rpm_total': 3, 'rpm_done': 3, 'drpm_total': 0, 'drpm_done': 0}, 'error_details': []}, 'comps': {'state': 'FINISHED'}, 'distribution': {'items_total': 0, 'state': 'FINISHED', 'error_details': [], 'items_left': 0}, 'errata': {'state': 'FINISHED'}, 'metadata'


Pulp versions from standard 6.1.2:
[crash] root@li-lc-1578:~# rpm -qa | grep pulp | sort
mod_wsgi-3.4-1.pulp.el6sat.x86_64
pulp-admin-client-2.6.0.15-1.el6_6sat.noarch
pulp-docker-plugins-0.2.5-1.el6_6sat.noarch
pulp-katello-0.5-1.el6_6sat.noarch
pulp-nodes-common-2.6.0.15-1.el6_6sat.noarch
pulp-nodes-parent-2.6.0.15-1.el6_6sat.noarch
pulp-puppet-admin-extensions-2.6.0.15-1.el6_6sat.noarch
pulp-puppet-plugins-2.6.0.15-1.el6_6sat.noarch
pulp-puppet-tools-2.6.0.15-1.el6_6sat.noarch
pulp-rpm-admin-extensions-2.6.0.15-1.el6_6sat.noarch
pulp-rpm-handlers-2.6.0.15-1.el6_6sat.noarch
pulp-rpm-plugins-2.6.0.15-1.el6_6sat.noarch
pulp-selinux-2.6.0.15-1.el6_6sat.noarch
pulp-server-2.6.0.15-1.el6_6sat.noarch
python-isodate-0.5.0-4.pulp.el6_6sat.noarch
python-kombu-3.0.24-10.pulp.el6_6sat.noarch
python-pulp-agent-lib-2.6.0.15-1.el6_6sat.noarch
python-pulp-bindings-2.6.0.15-1.el6_6sat.noarch
python-pulp-client-lib-2.6.0.15-1.el6_6sat.noarch
python-pulp-common-2.6.0.15-1.el6_6sat.noarch
python-pulp-docker-common-0.2.5-1.el6_6sat.noarch
python-pulp-puppet-common-2.6.0.15-1.el6_6sat.noarch
python-pulp-rpm-common-2.6.0.15-1.el6_6sat.noarch
rubygem-smart_proxy_pulp-1.0.1.2-1.el6_6sat.noarch



Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. Sync 50+ RedHat repositories concurrent
2.
3.

Actual results:
A couple of tasks will stay on incomplete in Pulp and on Running in Katello

Expected results:
All tasks finish


Additional info:
Comment 1 Peter Vreman 2015-09-18 05:12:09 EDT
After restarting Satellite 6 i have now the following tasks for the above mentiond Custom Product "Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9" that did not finish. The task_id changed to cancelled aa993623-b01b-49ec-ba7f-0ac6d892ac0b, but it now has a new unstarted task in Waiting:

[crash] root@li-lc-1578:~# pulp-admin tasks list | grep -B1 -A5 Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9
Operations:  publish
Resources:   Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9 (repository)
State:       Successful
Start Time:  2015-09-17T20:08:31Z
Finish Time: 2015-09-17T20:08:31Z
Task Id:     6da37080-7415-4fb0-8da2-6fed57bbd783

Operations:  sync
Resources:   Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9 (repository)
State:       Cancelled
Start Time:  2015-09-17T20:08:52Z
Finish Time: Incomplete
Task Id:     aa993623-b01b-49ec-ba7f-0ac6d892ac0b

Operations:  publish
Resources:   Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9 (repository)
State:       Waiting
Start Time:  Unstarted
Finish Time: Incomplete
Task Id:     f8c4984c-3b01-459b-b01b-8d174c55d850
Comment 2 Peter Vreman 2015-09-18 05:42:20 EDT
To try to recover i tried:
- Restarting Satellite katello-service stop & start
- Reboot Satellite server

Both did not help. The resuming of the task still gives:

{"pulp_tasks"=>
  [{"exception"=>nil,
    "task_type"=>"pulp.server.managers.repo.sync.sync",
    "_href"=>"/pulp/api/v2/tasks/269d201e-e868-4789-824b-4adefd0332bf/",
    "task_id"=>"269d201e-e868-4789-824b-4adefd0332bf",
    "tags"=>
     ["pulp:repository:Hilti-HOIPRODUCTS-HOIPRODUCTS-1_0_0-hf9",
      "pulp:action:sync"],
    "finish_time"=>nil,
    "_ns"=>"task_status",
    "start_time"=>"2015-09-18T09:30:21Z",
    "traceback"=>nil,
    "spawned_tasks"=>[],
    "progress_report"=>
     {"yum_importer"=>
       {"content"=>
         {"size_total"=>0,
          "items_left"=>0,
          "items_total"=>0,
          "state"=>"FINISHED",
          "size_left"=>0,
          "details"=>
           {"rpm_total"=>0, "rpm_done"=>0, "drpm_total"=>0, "drpm_done"=>0},
          "error_details"=>[]},
        "comps"=>{"state"=>"FINISHED"},
        "distribution"=>
         {"items_total"=>0,
          "state"=>"FINISHED",
          "error_details"=>[],
          "items_left"=>0},
        "errata"=>{"state"=>"FINISHED"},
        "metadata"=>{"state"=>"FINISHED"}}},
    "queue"=>"reserved_resource_worker-3@li-lc-1578.dq",
    "state"=>"running",
    "worker_name"=>"reserved_resource_worker-3@li-lc-1578",
    "result"=>nil,
    "error"=>nil,
    "_id"=>{"$oid"=>"55fbd9ac9696a0d0902b3a1a"},
    "id"=>"55fbd9ad0586fe0e30c37a9a"}],
 "poll_attempts"=>{"total"=>2619, "failed"=>0}}

The yum_importer finished again correctly, but the overall pulp task still is in running state.
Comment 3 Peter Vreman 2015-09-18 10:36:23 EDT
Created attachment 1074946 [details]
sosreport
Comment 7 Peter Vreman 2015-11-12 04:35:57 EST
Still seeing this problem with Sat6.1.3, see the number of poll_attemps in the task below.

Looks related to BZ1268756. Because from a timing perspective the never completing Sync is there since i tried to reproduce BZ1268756.

   97  2015-11-10 16:19:54: logrotate -f -v /etc/logrotate.d



Hanging task from dynflow console seen:

 Action:

Actions::Pulp::Repository::Sync

State: waiting for Pulp to finish the task
Input:

{"pulp_id"=>
  "Hilti-Red_Hat_Enterprise_Linux_Server_-_Extended_Update_Support-Red_Hat_Satellite_Tools_6_1_for_RHEL_6_Server_-_EUS_RPMs_x86_64_6_5",
 "task_id"=>nil,
 "remote_user"=>"hoici-4dbfe556",
 "remote_cp_user"=>"hoici",
 "locale"=>"en"}

Output:

{"pulp_tasks"=>
  [{"exception"=>nil,
    "task_type"=>"pulp.server.managers.repo.sync.sync",
    "_href"=>"/pulp/api/v2/tasks/aad03d1a-2279-41b5-b08d-25da14954f96/",
    "task_id"=>"aad03d1a-2279-41b5-b08d-25da14954f96",
    "tags"=>
     ["pulp:repository:Hilti-Red_Hat_Enterprise_Linux_Server_-_Extended_Update_Support-Red_Hat_Satellite_Tools_6_1_for_RHEL_6_Server_-_EUS_RPMs_x86_64_6_5",
      "pulp:action:sync"],
    "finish_time"=>nil,
    "_ns"=>"task_status",
    "start_time"=>"2015-11-10T16:19:12Z",
    "traceback"=>nil,
    "spawned_tasks"=>[],
    "progress_report"=>
     {"yum_importer"=>
       {"content"=>
         {"size_total"=>0,
          "items_left"=>0,
          "items_total"=>0,
          "state"=>"FINISHED",
          "size_left"=>0,
          "details"=>
           {"rpm_total"=>0, "rpm_done"=>0, "drpm_total"=>0, "drpm_done"=>0},
          "error_details"=>[]},
        "comps"=>{"state"=>"FINISHED"},
        "distribution"=>
         {"items_total"=>0,
          "state"=>"FINISHED",
          "error_details"=>[],
          "items_left"=>0},
        "errata"=>{"state"=>"FINISHED"},
        "metadata"=>{"state"=>"FINISHED"}}},
    "queue"=>"reserved_resource_worker-3@li-lc-1578.dq",
    "state"=>"running",
    "worker_name"=>"reserved_resource_worker-3@li-lc-1578",
    "result"=>nil,
    "error"=>nil,
    "_id"=>{"$oid"=>"56421900d746ee9805a8f469"},
    "id"=>"564219000586fe0e43e9feaa"}],
 "poll_attempts"=>{"total"=>8936, "failed"=>0}}


/var/log/messages:

Nov 10 16:19:56 li-lc-1578 pulp: pulp.server.db.connection:INFO: Mongo database for connection is version 2.4.6
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin yum_clone_distributor for types: rpm,srpm,drpm,erratum,distribution,package_catego
ry,package_group
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin yum_distributor for types: rpm,srpm,drpm,erratum,package_group,package_category,di
stribution,yum_repo_metadata_file
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin export_distributor for types: rpm,srpm,drpm,erratum,distribution,package_category,
package_group
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin iso_distributor for types: iso
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin docker_distributor_web for types: docker_image
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin docker_distributor_export for types: docker_image
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin nodes_http_distributor for types: node
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin puppet_distributor for types: puppet_module
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin puppet_file_distributor for types: puppet_module
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin puppet_install_distributor for types: puppet_module
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin group_export_distributor for types: rpm,srpm,drpm,erratum,distribution,package_cat
egory,package_group
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin yum_importer for types: distribution,drpm,erratum,package_group,package_category,r
pm,srpm,yum_repo_metadata_file,package_environment
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin iso_importer for types: iso
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin docker_importer for types: docker_image
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin puppet_importer for types: puppet_module
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin yum_profiler for types: rpm,erratum
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin node for types: node,repository
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin puppet_whole_repo_profiler for types: puppet_module
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin yum for types: rpm
Nov 10 16:19:57 li-lc-1578 pulp: pulp.plugins.loader.manager:INFO: Loaded plugin rhui for types: rpm
Nov 10 16:19:57 li-lc-1578 pulp: gofer.messaging.adapter.qpid.connection:INFO: connecting: URL: ssl://li-lc-1578.hag.hilti.com|SSL: ca: /etc/pki/katello/certs/kate
llo-default-ca.crt|key: None|certificate: /etc/pki/katello/qpid_client_striped.crt|host-validation: False
Nov 10 16:19:57 li-lc-1578 pulp: gofer.messaging.adapter.qpid.connection:INFO: connected: ssl://li-lc-1578.hag.hilti.com
Nov 10 16:19:57 li-lc-1578 pulp: pulp.server.agent.direct.services:INFO: Task reply handler, started.
Nov 10 16:19:57 li-lc-1578 pulp: pulp.server.agent.direct.services:INFO: AMQP reply handler started
Nov 10 16:19:57 li-lc-1578 pulp: pulp.server.webservices.application:INFO: *************************************************************
Nov 10 16:19:57 li-lc-1578 pulp: pulp.server.webservices.application:INFO: The Pulp server has been successfully initialized
Nov 10 16:19:57 li-lc-1578 pulp: pulp.server.webservices.application:INFO: *************************************************************
Nov 10 16:19:57 li-lc-1578 pulp: gofer.messaging.adapter.qpid.connection:INFO: connecting: URL: ssl://li-lc-1578.hag.hilti.com|SSL: ca: /etc/pki/katello/certs/kate
llo-default-ca.crt|key: None|certificate: /etc/pki/katello/qpid_client_striped.crt|host-validation: False
Nov 10 16:19:57 li-lc-1578 pulp: gofer.messaging.adapter.qpid.connection:INFO: connected: ssl://li-lc-1578.hag.hilti.com
Comment 10 Peter Vreman 2015-12-30 03:40:12 EST
Closing issue did not happen anymore since the upgrade to 6.1.5, the fix of https://bugzilla.redhat.com/show_bug.cgi?id=1279502 solved this issue.

Note You need to log in before you can comment on or make changes to this bug.