| Title | Automatic test expects a bug to replicate on first poll |
| Status | closed |
| Priority | essential |
| Assigned user | Francis Irving |
| Organization | Ravenbrook |
| Description | The automated tests fail on swan.ravenbrook.com (RedHat 7.3 and Bugzilla) with the message ====================================================================== FAIL: Frequent edits cause no conflicts (test_p4dti.frequent_edits) ---------------------------------------------------------------------- Traceback (innermost last): File "test_p4dti.py", line 3037, in runTest self.expectation([803, 804, 812, 911, 912]) File "test_p4dti.py", line 1134, in expectation self.expected(expected) File "test_p4dti.py", line 1128, in expected assert found.has_key(id) and found[id] > 0, \ AssertionError: Expected message 803 not found in log [911, 100, 101, 100, 101, 102, 100, 101, 100, 101, 102, 100, 101, 103, 100, 101, 103, 100, 101, 103, 701, 703, 100, 101, 100, 101, 100, 101, 912] ---------------------------------------------------------------------- You can run just this test with "python test_p4dti.py frequent_edits.runTest". The tests lifecycle and and perforce_section also fail in a similar way. The failures are intermittent, but occur most times that the test is run. |
| Analysis | The problem appears to be with timing. The test calls self.poll() on test_p4dti.py line 3036, expecting the bug it just submitted to replicate immediately. However the replicator does not replicate the bug until the next clock second has ticked. Here are two extracts from a log where I made the test suite poll repeatedly. The first is an SQL query which fails to find the bug, and the second is the query which finds it after the second counter has ticked over on the clock. 2002-10-04 15:39:46 UTC (P4DTI-1003) Executing SQL command 'select bugs.* from bugs left join p4dti_bugs using (bug_id) where bugs.creation_ts >= '2002-10-04 16:39:45' and bugs.creation_ts < '2002-10-04 16:39:45' and (p4dti_bugs.rid is null or (p4dti_bugs.rid = 'replicator0' and p4dti_bugs.sid = 'perforce0' and p4dti_bugs.migrated is null))'. 2002-10-04 15:39:46 UTC (P4DTI-1014) MySQL returned '0L'. ... 2002-10-04 15:39:46 UTC (P4DTI-1003) Executing SQL command 'select bugs.* from bugs left join p4dti_bugs using (bug_id) where bugs.creation_ts >= '2002-10-04 16:39:45' and bugs.creation_ts < '2002-10-04 16:39:46' and (p4dti_bugs.rid is null or (p4dti_bugs.rid = 'replicator0' and p4dti_bugs.sid = 'perforce0' and p4dti_bugs.migrated is null))'. 2002-10-04 15:39:46 UTC (P4DTI-1014) MySQL returned '1L'. Note in particular the clause bugs.creation_ts >= '2002-10-04 16:39:45' and bugs.creation_ts < '2002-10-04 16:39:45' which will never find bugs in the current second. This may be a fault in the replicator. Otherwise the tests need altering to perform multiple polls, or perhaps wait just over one second before polling. |
| How found | automated_test |
| Evidence | Run the test_p4dti.py test on swan. |
| Test procedure | <http://www.ravenbrook.com/project/p4dti/master/test/test_p4dti.py>, sections 22, 10, and 23 |
| Created by | Francis Irving |
| Created on | 2002-10-08 13:11:14 |
| Last modified by | Gareth Rees |
| Last modified on | 2010-10-06 21:41:10 |
| History | 2002-10-08 FAI Created. 2002-11-04 RB Downgraded to "essential". |
| Change | Effect | Date | User | Description |
|---|---|---|---|---|
| 30127 | closed | 2002-06-14 15:05:24 | Nick Barnes | Sleep on test submission. |