Problem¶
There is an inconsistent and relatively new regression on Pulp 2 Nightly CI:
Failures can be seen in the second-sync Task Details. Historically, only a value of `0` are expected for the second-sync details for the verified fields:
- 'added_count'
- 'removed_count'
- 'updated_count'
The output of the test failure (including a negative value in this case for `removed_count` and non-zero for `added_count` as well as `task_id`) can be correlated with the CLI Task Output for the `task_id` showing non-zero values for the verified fields.
Test Failure¶
============================================================== FAILURES ===============================================================
________________________________________ SyncRpmRepoTestCase.test_02_no_change_in_second_sync _________________________________________
self = <pulp_2_tests.tests.rpm.api_v2.test_sync_publish.SyncRpmRepoTestCase testMethod=test_02_no_change_in_second_sync>
def test_02_no_change_in_second_sync(self):
"""Verify that syncing a second time has no changes.
If the repository have not changed then Pulp must state that anything
was changed when doing a second sync.
"""
report = sync_repo(self.cfg, self.repo)
tasks = tuple(api.poll_spawned_tasks(self.cfg, report.json()))
with self.subTest(comment='spawned tasks'):
self.assertEqual(len(tasks), 1)
for count_type in ('added_count', 'removed_count', 'updated_count'):
with self.subTest(comment=count_type):
> self.assertEqual(tasks[0]['result'][count_type], 0, tasks)
E AssertionError: 8 != 0 : ({'exception': None, 'task_type': 'pulp.server.managers.repo.sync.sync', '_href': '/pulp/api/v2/tasks/ab78afea-178b-4081-99a3-2e63d47915de/', 'task_id': 'ab78afea-178b-4081-99a3-2e63d47915de', 'tags': ['pulp:repository:9601ef5d-f90c-433f-b2e5-9e879ed0c199', 'pulp:action:sync'], 'finish_time': '2019-05-08T11:28:39Z', '_ns': 'task_status', 'start_time': '2019-05-08T11:28:32Z', 'traceback': None, 'spawned_tasks': [], 'progress_report': {'yum_importer': {'content': {'items_total': 0, 'state': 'FINISHED', 'error_details': [], 'details': {'rpm_total': 0, 'rpm_done': 0, 'drpm_total': 0, 'drpm_done': 0}, 'size_total': 0, 'size_left': 0, 'items_left': 0}, 'comps': {'state': 'FINISHED'}, 'purge_duplicates': {'state': 'FINISHED'}, 'distribution': {'items_total': 0, 'state': 'FINISHED', 'error_details': [], 'items_left': 0}, 'modules': {'state': 'FINISHED'}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}}, 'queue': 'reserved_resource_worker-0@rhel76-218.dq2', 'state': 'finished', 'worker_name': 'reserved_resource_worker-0@rhel76-218', 'result': {'result': 'success', 'importer_id': 'yum_importer', 'exception': None, 'repo_id': '9601ef5d-f90c-433f-b2e5-9e879ed0c199', 'traceback': None, 'started': '2019-05-08T11:28:32Z', '_ns': 'repo_sync_results', 'completed': '2019-05-08T11:28:39Z', 'importer_type_id': 'yum_importer', 'error_message': None, 'summary': {'modules': {'state': 'FINISHED'}, 'content': {'state': 'FINISHED'}, 'comps': {'state': 'FINISHED'}, 'purge_duplicates': {'state': 'FINISHED'}, 'distribution': {'state': 'FINISHED'}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'added_count': 8, 'removed_count': -8, 'updated_count': 0, 'id': '5cd2bd676f8f3411133bf898', 'details': {'modules': {'state': 'FINISHED'}, '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'}, 'purge_duplicates': {'state': 'FINISHED'}, 'distribution': {'items_total': 0, 'state': 'FINISHED', 'error_details': [], 'items_left': 0}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}}, 'error': None, '_id': {'$oid': '5cd2bd60cfa8faeb309e9677'}, 'id': '5cd2bd60cfa8faeb309e9677'},)
test_sync_publish.py:156: AssertionError
CLI Task Failure Output from Second Sync¶
[root@rhel76 ~]# pulp-admin tasks details --task-id d0140034-e1ca-4d1e-a34f-7fdf1d17a697
+----------------------------------------------------------------------+
Task Details
+----------------------------------------------------------------------+
Operations: sync
Resources: 2cbd8fc6-4c37-445d-bfc3-d38a93cc98d1 (repository)
State: Successful
Start Time: 2019-05-07T19:15:43Z
Finish Time: 2019-05-07T19:15:49Z
Result:
Added Count: 8
Completed: 2019-05-07T19:15:49Z
Details:
Comps:
State: FINISHED
Content:
Details:
Drpm Done: 0
Drpm Total: 0
Rpm Done: 0
Rpm Total: 0
Error Details:
Items Left: 0
Items Total: 0
Size Left: 0
Size Total: 0
State: FINISHED
Distribution:
Error Details:
Items Left: 0
Items Total: 0
State: FINISHED
Errata:
State: FINISHED
Metadata:
State: FINISHED
Modules:
State: FINISHED
Purge Duplicates:
State: FINISHED
Error Message: None
Exception: None
Id: 5cd1d965719c8d17a0474cc4
Importer Id: yum_importer
Importer Type Id: yum_importer
Removed Count: -8
Repo Id: 2cbd8fc6-4c37-445d-bfc3-d38a93cc98d1
Result: success
Started: 2019-05-07T19:15:43Z
Summary:
Comps:
State: FINISHED
Content:
State: FINISHED
Distribution:
State: FINISHED
Errata:
State: FINISHED
Metadata:
State: FINISHED
Modules:
State: FINISHED
Purge Duplicates:
State: FINISHED
Traceback: None
Updated Count: 0
Task Id: d0140034-e1ca-4d1e-a34f-7fdf1d17a697
Worker Name: reserved_resource_worker-0@rhel76
Progress Report:
Yum Importer:
Comps:
State: FINISHED
Content:
Details:
Drpm Done: 0
Drpm Total: 0
Rpm Done: 0
Rpm Total: 0
Error Details:
Items Left: 0
Items Total: 0
Size Left: 0
Size Total: 0
State: FINISHED
Distribution:
Error Details:
Items Left: 0
Items Total: 0
State: FINISHED
Errata:
State: FINISHED
Metadata:
State: FINISHED
Modules:
State: FINISHED
Purge Duplicates:
State: FINISHED
Background¶
Test Design¶
The test is simply designed to:
- Sync a repo (immediate/no flags)
- Synch a repo again
- Verify there are no additional changes on the second sync (all artifacts should have been copied the first time) when checking the Task Details of the sync task.
Background¶
This logic was added in 2016 to ensure sync was fully syncing:
The failures are relatively recent.
Recreation¶
The easiest way to recreate is to run the following test against a pulp2 server. The test run-time is 16 seconds.
If the test needs to be abstracted to a set of manual steps, it can be. However, with the inconsistent behavior of this test, it is best to use this short python test for recreation in this instance.
The definition of `inconsistent behavior` is that the test will sometimes pass as expected and sometimes fail on any of these fields.
Possible Behavioral Change Commit¶
It was noted the following Commit has recently been introduced.
It may be part of the reason for the behavioral change for the test.
More investigation or a clear RCA is required still to verify the source.
.