Project

Profile

Help

Issue #4795

Updated by bherring over 5 years ago

h2. Problem 

 There is an inconsistent and relatively new regression on Pulp 2 Nightly CI: 
 * rpm.api_v2.test_sync_publish.SyncRpmRepoTestCase.test_no_change_in_second_sync 
 * https://github.com/PulpQE/Pulp-2-Tests/blob/e4699997370c734e94c43b956b44b088888b5d9e/pulp_2_tests/tests/rpm/api_v2/test_sync_publish.py#L144 
 * https://pulp-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/Pulp%202%20-%20Master/job/pulp-2-master-dev-rhel7/441/testReport/ 

 Failures can be seen in the second-sync Task Details. Historically, only a value of `0` are two discrete issues here: expected for the second-sync details for the verified fields: 
 * 'added_count' 
 * 'removed_count' 
 * 'updated_count' 

 * `pulp-smash` is now/recently updated polling at a 0.3s rate that. For a The output of the test including failure (including a second repo sync, negative value in this will occasionally returning a task "COMPLETE" but 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 task verified fields. 


 h3. Test Failure 

 <pre> 
 ============================================================== 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 
 </pre> 

 h3. CLI Task Failure Output from Second Sync 
 <pre> 
 [root@rhel76 ~]# pulp-admin tasks details had yet to be reset. --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 

 </pre> 

 h2. Background 

 h3. Test Design 

 The resulting return of non-zero values causes test failures. It appears that the ACTUAL change is none, however the task_details simply designed to: 

 * Sync a repo (immediate/no flags) 
 * Synch a repo again 
 * Verify there are reporting incorrectly. This was supposedly discovered long ago, but no additional changes on the legacy issue could not be found. 
 
 * Due to second sync (all artifacts should have been copied the above, first time) when checking the values Task Details of 'added_count', 'removed_count', 'updated_count' are being permanently updated to values in the db that are incorrect. Meaning, running `pulp-admin tasks details --task-id` of the automated task will result sync task. 

 h3. Background 

 This logic was added in the invalid values still being populated in the historic record. This appears 2016 to be related to legacy issue #4428 ensure sync was fully syncing: 

 * https://github.com/PulpQE/pulp-smash/commit/0a51ef749faaa87afa311d665056de4270f9ec3c 
 * https://github.com/PulpQE/pulp-smash/issues/161 

 The failures are relatively recent. 

 h2. Recreation  

 

 The RCA seems easiest way to be from updating pulp-smash polling recreate is to run the following test against a much quicker rate: 
 https://github.com/PulpQE/pulp-smash/blob/e385e6685a82709fd167b5374d19c4dfcfdb78c5/pulp_smash/api.py#L687 pulp2 server. The test run-time is 16 seconds. 

 To * https://github.com/PulpQE/Pulp-2-Tests/blob/e4699997370c734e94c43b956b44b088888b5d9e/pulp_2_tests/tests/rpm/api_v2/test_sync_publish.py#L144 

 If the test this, locally have pulp-smash installed and set needs to be abstracted to a VERY low polling rate. At set of manual steps, it can be. However, with the time inconsistent behavior of this writing, anything around `0.3` would fail 50-80% of the time. Adjusting test, it is best to an even smaller value should increase the probabiltiy of failure on a non-patched system. 

 Run use this short python test through pytest with the following syntax for recreation in an appropriately prepared virtenv: this instance. 

 <pre> 
 (pulp2) [herring@redherring api_v2]$ pwd 
 /home/herring/git/Pulp-2-Tests/pulp_2_tests/tests/rpm/api_v2 
 (pulp2) [herring@redherring api_v2]$ count=1; while [ $count -le 10 ]; do echo -e "Iteration: $count\n"; pytest -svv test_sync_publish.py::SyncRpmRepoTestCase::test_no_change_in_second_sync --disable-warnings; ((count++)); done 
 </pre> 

 A loop value The definition of 10 was chosen to ensure math was easy. 

 It `inconsistent behavior` is expected there that the test will be a 100% sometimes pass rate. At this time, even with larger values around 2 seconds, there is still ~10% chance as expected and sometimes fail on any of failure. these fields. 

 Also, running h2. Possible Behavioral Change Commit 

 It was noted the following on a passing Task ID should NOT result in incorrect values for the task: Commit has recently been introduced. 

 <pre> 
 [root@rhel76 ~]# pulp-admin tasks details --task-id d0140034-e1ca-4d1e-a34f-7fdf1d17a697 
 </pre> 

 Where It may be part of the `--task-id` is appropriate reason for the jobs being ran. behavioral change for the test.  

 h2. QE Workaround in place 

 For the time being, the values for pulp-smash when used on Pulp2 polling can be increase More investigation or a clear RCA is required still to keep these failures from happening. 

 Once this task issues are resolved, pulp-smash can have verify the values restored to lower polling values. source. 

 h2. References 

 * Additional Reference needed here from @dkliban about how the values are calculated https://github.com/pulp/pulp_rpm/pull/1335/files 
 https://pulp.plan.io/issues/4428#note-17 
 * Original investigation information moved down in other Notes to retain investigation history. https://pulp.plan.io/issues/4627

Back