Page MenuHomePhabricator

Flow: Off-by-one timestamp failures in tests
Closed, ResolvedPublic

Description

There are two timestamp-related off-by-one errors, both intermittent. It's not clear yet if they're related:

https://gerrit.wikimedia.org/r/#/c/172925/ had a failure on patch set 9.

03:08:27 1) Flow\Tests\Api\ApiFlowViewTopicListTest::testTocOnly
03:08:27 TOC-only output for "updated" order
03:08:27 Failed asserting that two arrays are equal.
03:08:27 --- Expected
03:08:27 +++ Actual
03:08:27 @@ @@
03:08:27                              'fwd' => Array (
03:08:27 -                                'url' => '/wiki/index.php?title=Talk:Flow_QA&topiclist_offset-dir=fwd&topiclist_limit=2&topiclist_offset=20141123030821&topiclist_sortby=updated'
03:08:27 +                                'url' => '/wiki/index.php?title=Talk:Flow_QA&topiclist_offset-dir=fwd&topiclist_limit=2&topiclist_offset=20141123030822&topiclist_sortby=updated'
03:08:27                                  'title' => 'fwd'
03:08:27                              )
03:08:27                          )
03:08:27                      )
03:08:27                      'errors' => Array ()
03:08:27                      'type' => 'topiclist'
03:08:27                  )
03:08:27              )
03:08:27              'status' => 'ok'
03:08:27          )
03:08:27      )
03:08:27  )

I then did a recheck and patch set 9 then worked.

Patch set 7 of https://gerrit.wikimedia.org/r/#/c/170997/ had another failure, also a timestamp off-by-one:

03:52:54 1) Flow\Tests\Model\UUIDTest::testConversionToTimestamp
03:52:54 Failed asserting that '20141125035244' matches expected '20141125035243'.
03:52:54 
03:52:54 /srv/ssd/jenkins-slave/workspace/mwext-Flow-testextension/src/extensions/Flow/tests/phpunit/Model/UUIDTest.php:160
03:52:54 /srv/ssd/jenkins-slave/workspace/mwext-Flow-testextension/src/tests/phpunit/MediaWikiTestCase.php:141

Again, it went away on recheck.

Event Timeline

Mattflaschen-WMF raised the priority of this task from to Medium.
Mattflaschen-WMF updated the task description. (Show Details)
Mattflaschen-WMF changed Security from none to None.
Mattflaschen-WMF added a subscriber: EBernhardson.

I think these are both caused by the timestamp ticking over from one second to the next.

In the ViewTopicList case we are sourcing the timestamp from the latest revision id, but the timestamp in the url comes from the workflow. The workflow timestamp is assigned in TopicBlock::commit() just before writing things out, there is the potential for a few ms between creating the revision and commiting it. It makes sense for the workflow to use the exact same timestamp, so https://gerrit.wikimedia.org/r/175664 makes that happen. As long as we are making timestamps match I also submitted https://gerrit.wikimedia.org/r/175665 to match a revisions moderation timestamp to the revision id. In both these cases though, i almost wonder if we should be storing id's instead of timestamps.

In the UUIDTest its directly comparing wfTimestampNow() to a uuid, another opportunity for the timestamps to be created on either side of the second tick. I don't have much of a solution for this atm, we could move uid generation behind a mockable interface and use consistent timestamps on the unit test side through HistoricalUIDGenerator

In the ViewTopicList case we are sourcing the timestamp from the latest revision id, but the timestamp in the url comes from the workflow.

From the topic workflow?

Yes the topic workflow. When you have a numerical offset like in this test that means we are sorting by the workflow_last_updated_timestamp of the related topic workflows.

Mattflaschen-WMF raised the priority of this task from Medium to High.Mar 3 2015, 10:32 PM

This really needs to be fixed.

This is currently causing mediawiki-core integration tests to fail and block commits in other repositories being merged from time to time. This should be fixed within a day. Alternatively, I'll disable the relevant test for the time being. No worries :)

Per our IRC conversation: For the testConverionToTimestamp, I think we can just do:

UUID::create( 'somehex' )->getTimestamp()

which will have a deterministic output, and still test our code (we're not trying to test core's use of the time).

Change 194226 had a related patch set uploaded (by EBernhardson):
Fix intermittent off by one issues

https://gerrit.wikimedia.org/r/194226

Change 194226 merged by jenkins-bot:
Fix intermittent off by one issues

https://gerrit.wikimedia.org/r/194226