Some requests fail with UIDGenerator error "Process clock is outdated or drifted"
Closed, ResolvedPublicPRODUCTION ERROR
Actions

Description

See for example https://integration.wikimedia.org/ci/job/mediawiki-extensions-zend/9816/consoleFull .

00:12:02.398 There were 2 failures:
00:12:02.398 
00:12:02.399 1) Warning
00:12:02.422 The data provider specified for Flow\Tests\UrlGeneratorTest::testWatchTopicLink is invalid.
00:12:02.422 Process clock is outdated or drifted.
00:12:02.422 
00:12:02.422 
00:12:02.423 2) Warning
00:12:02.423 The data provider specified for Flow\Tests\UrlGeneratorTest::testUnwatchTopicLink is invalid.
00:12:02.423 Process clock is outdated or drifted.

This error is from https://git.wikimedia.org/blob/mediawiki%2Fcore.git/7cf070f9cbb71b2bb3fcba5b7c632970ab6bf933/includes%2Futils%2FUIDGenerator.php and happens when two clocks drift apart by 2 seconds.

Details

Subject	Repo	Branch	Lines +/-
UIDGenerator: Remove the clock skew problem	mediawiki/core	wmf/1.32.0-wmf.24	+71 -56
UIDGenerator: Misc clean up	mediawiki/core	wmf/1.32.0-wmf.24	+77 -37
UIDGenerator: Remove the clock skew problem	mediawiki/core	master	+71 -56
UIDGenerator: Misc clean up	mediawiki/core	master	+77 -37
Make UID clock drift error have more details.	mediawiki/core	wmf/1.32.0-wmf.24	+3 -2

Customize query in gerrit

Related Objects

Mentioned In: T245464: Use php-hrtime monotonic clock instead of microtime for perf measure in MW
T244275: Write blog post about UIDGenerator
Mentioned Here: T94963: Jenkins: "Warning: Some projects have builds whose timestamps are inconsistent."

Event Timeline

• Mattflaschen-WMF created this task.Mar 31 2015, 12:36 AM

• Mattflaschen-WMF raised the priority of this task from to Needs Triage.

• Mattflaschen-WMF updated the task description. (Show Details)

• Mattflaschen-WMF added projects: MediaWiki-General, Continuous-Integration-Infrastructure.

• Mattflaschen-WMF subscribed.

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMar 31 2015, 12:36 AM

Apparently not a CI issue, seems something is flappy in either Flow test or the UIDGenerator.

hashar updated the task description. (Show Details)Mar 31 2015, 12:34 PM

The UUID generator was originally implemented by @aaron (cced) and introduced by https://gerrit.wikimedia.org/r/#/q/I989626dfb7976d17f5931a34fe040f41cf14dfe3,n,z

The drift detection has been added by Patchset 12 https://gerrit.wikimedia.org/r/#/c/37052/11..12/includes/UIDGenerator.php which Aaron commented as being "Robustness rewrite (partly as a result of testing)".

@Mattflaschen can you reach out to @aaron ?

In T94522#1166646, @hashar wrote:

Apparently not a CI issue

Based on what? How do we know there isn't clock drift on the CI machines (that's what it's checking for).

• Mattflaschen-WMF added projects: Collaboration-Team-Triage, Continuous-Integration-Infrastructure.Apr 1 2015, 4:03 AM

Read the code? A PHP bug causes the microtime() function to drift and @aaron made the uuidgenerator to abort the process. There is nothing CI can do about that code.

Unless this happens again we wont be looking into it further.

Krinkle renamed this task from "Process clock is outdated or drifted" is causing continuous integration failures to Some requests fail with UIDGenerator error "Process clock is outdated or drifted".Sep 20 2018, 1:38 AM

Krinkle raised the priority of this task from Lowest to High.

Krinkle edited projects, added Wikimedia-production-error; removed Collaboration-Team-Triage.

This has started to affect not just CI, but also random page views, API requests, and JobQueue jobs.

I don't know for how long, but quite likely related to the introduction of EventBus for the JobQueue, given that prior to that, UID was not used for the job queue.

Impact: Jobs may be lost before insertion.

Error

Sample Request ID: W6L0GwrAEDUAAJYVR4IAAAAB

message

[{exception_id}] {exception_url}   RuntimeException from line 482 of /srv/mediawiki/php-1.32.0-wmf.22/includes/utils/UIDGenerator.php: Process clock is outdated or drifted.

trace

#0 /srv/mediawiki/php-1.32.0-wmf.22/includes/utils/UIDGenerator.php(222): UIDGenerator->getTimeAndDelay(string, integer, integer, integer)
#1 /srv/mediawiki/php-1.32.0-wmf.22/extensions/EventBus/includes/EventBus.php(445): UIDGenerator::newUUIDv1()
#2 /srv/mediawiki/php-1.32.0-wmf.22/extensions/EventBus/includes/EventBus.php(382): EventBus::newId()
#3 /srv/mediawiki/php-1.32.0-wmf.22/extensions/EventBus/includes/JobQueueEventBus.php(43): EventBus::createEvent(string, string, array, string)
#4 /srv/mediawiki/php-1.32.0-wmf.22/extensions/EventBus/includes/JobQueueEventBus.php(133): JobQueueEventBus->createJobEvent(JobSpecification)
#5 /srv/mediawiki/php-1.32.0-wmf.22/includes/jobqueue/JobQueue.php(332): JobQueueEventBus->doBatchPush(array, integer)
#6 /srv/mediawiki/php-1.32.0-wmf.22/includes/jobqueue/JobQueue.php(302): JobQueue->batchPush(array, integer)
#7 /srv/mediawiki/php-1.32.0-wmf.22/includes/jobqueue/JobQueueGroup.php(154): JobQueue->push(array)
#8 /srv/mediawiki/php-1.32.0-wmf.22/includes/jobqueue/JobQueueGroup.php(218): JobQueueGroup->push(array)
#9 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/MWCallableUpdate.php(34): JobQueueGroup::pushLazyJobs()
#10 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/DeferredUpdates.php(268): MWCallableUpdate->doUpdate()
#11 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate(MWCallableUpdate, Wikimedia\Rdbms\LBFactoryMulti, string, integer)
#12 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/DeferredUpdates.php(134): DeferredUpdates::execute(array, string, integer)
#13 /srv/mediawiki/php-1.32.0-wmf.22/includes/MediaWiki.php(914): DeferredUpdates::doUpdates(string)
#14 /srv/mediawiki/php-1.32.0-wmf.22/includes/MediaWiki.php(734): MediaWiki->restInPeace(string, boolean)
#15 [internal function]: Closure$MediaWiki::doPostOutputShutdown()

Source: https://github.com/wikimedia/mediawiki/blob/8477d4a6f5949fcb875fb0d21800866bc548fc05/includes/utils/UIDGenerator.php#L478-L483

Notes

Logstash has recorded that 31 request processes got aborted due to this error (in the last 30 days). Most are from the callsite in EventBus when inserting jobs.

Restricted Application added a project: Analytics. · View Herald TranscriptSep 20 2018, 1:41 AM

Krinkle moved this task from Untriaged to Older on the Wikimedia-production-error board.Sep 20 2018, 1:41 AM

• mobrovac added a project: Services (watching).Sep 20 2018, 6:10 AM

• mobrovac edited projects, added Services (doing); removed Services (watching).Sep 20 2018, 5:07 PM

Milimetric moved this task from Incoming to Radar on the Analytics board.Sep 24 2018, 4:04 PM

(Still seen on 1.32.0-wmf.23)

Time drifting is a known occurrence. From what I see, we have two options:

allow it to happen and risk duplicate v1 UUIDs: the collision rate would vary with the drift, but in practice that means that some request IDs might end up with the same UUID
use PECL's uuid library which is a wrapper around libuuid: the library does not suffer from the time drifting problem, but requires extra packages to be installed and PECL enabled.

I would vote for the latter.

Change 464454 had a related patch set uploaded (by Krinkle; owner: Aaron Schulz):
[mediawiki/core@wmf/1.32.0-wmf.24] Make UID clock drift error have more details.

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

gerritbot added a project: Patch-For-Review.Oct 3 2018, 10:53 PM

Change 464454 merged by jenkins-bot:
[mediawiki/core@wmf/1.32.0-wmf.24] Make UID clock drift error have more details.

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

Mentioned in SAL (#wikimedia-operations) [2018-10-03T23:23:27Z] <catrope@deploy1001> Synchronized php-1.32.0-wmf.24/includes/utils/UIDGenerator.php: Make UID clock drift error have more details (T94522) (duration: 00m 58s)

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)).Oct 4 2018, 12:01 AM

Change 464462 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] UIDGenerator: Make internal millitime() non-static

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

Change 464463 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@master] [WIP] UIDGenerator

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

Change 464462 merged by jenkins-bot:
[mediawiki/core@master] UIDGenerator: Misc clean up

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-10-16 (1.32.0-wmf.26)); removed MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)).Oct 4 2018, 12:01 PM

fgiunchedi subscribed.Oct 4 2018, 3:04 PM

Change 464463 merged by jenkins-bot:
[mediawiki/core@master] UIDGenerator: Remove the clock skew problem

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

Change 465533 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.32.0-wmf.24] UIDGenerator: Misc clean up

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

Change 465533 merged by Krinkle:
[mediawiki/core@wmf/1.32.0-wmf.24] UIDGenerator: Misc clean up

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

Change 465535 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/core@wmf/1.32.0-wmf.24] UIDGenerator: Remove the clock skew problem

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)); removed MW-1.32-notes (WMF-deploy-2018-10-16 (1.32.0-wmf.26)).Oct 10 2018, 12:00 AM

Change 465535 merged by Krinkle:
[mediawiki/core@wmf/1.32.0-wmf.24] UIDGenerator: Remove the clock skew problem

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

Krinkle closed this task as Resolved.Oct 10 2018, 12:14 AM

Krinkle claimed this task.

Krinkle edited projects, added Wikimedia-Performance-publish; removed MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)), Patch-For-Review, Event-Platform, Analytics.

Restricted Application added a project: Performance-Team. · View Herald TranscriptOct 10 2018, 12:14 AM

Mentioned in SAL (#wikimedia-operations) [2018-10-10T00:14:24Z] <krinkle@deploy1001> Synchronized php-1.32.0-wmf.24/tests/phpunit/includes/utils/: T94522 - I2a0c51bea58 (duration: 01m 02s)

Mentioned in SAL (#wikimedia-operations) [2018-10-10T00:19:44Z] <krinkle@deploy1001> Synchronized php-1.32.0-wmf.24/includes/utils/UIDGenerator.php: T94522 - I2a0c51bea58 (duration: 00m 56s)

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-10-02 (1.32.0-wmf.24)).Oct 10 2018, 1:00 AM

Krinkle moved this task from Untriaged to Ready for write-up on the Wikimedia-Performance-publish board.Oct 12 2018, 2:36 AM

• mmodell changed the subtype of this task from "Task" to "Production Error".Aug 28 2019, 11:11 PM

Krinkle mentioned this in T244275: Write blog post about UIDGenerator.Feb 4 2020, 7:04 PM

Krinkle mentioned this in T245464: Use php-hrtime monotonic clock instead of microtime for perf measure in MW.Feb 25 2020, 5:57 PM