Page MenuHomePhabricator
Create Task
Maniphest T198280

Beta Cluster: Unable to obtain lock via objectcache (memcached add() fails)
Closed, ResolvedPublic
Actions

Description

Following https://gerrit.wikimedia.org/r/442198 (per T195314#4317397), I'm trying to see whether Navigation Timing reports have increased in Beta. But it seems they remain at zero. Given the sample rate of 1/10, I figured I'd just try locally a few times to click on the main page, and eventually got sampled, but noticed the following error in the console.

Console
[NavigationTiming] Missing or empty schema

Looking at the network fetch for the schemas from load.php, it got the following:

https://en.wikipedia.beta.wmflabs.org/w/load.php?debug=false&lang=en&modules=schema.NavigationTiming|schema.SaveTiming

load.php
mw.loader.implement("schema.NavigationTiming@02ba1tn", function($, jQuery, require, module) {
    mediaWiki.eventLog.declareSchema("NavigationTiming", {
        "schema": {},
        "revision": 18156125
    });
});
mw.loader.implement("schema.SaveTiming@10h98u7", function($, jQuery, require, module) {
    mediaWiki.eventLog.declareSchema("SaveTiming", {
        "schema": {
            "title": "SaveTiming",
            "properties": {
                "saveTiming": {
[..]

Given it only affects the NavigationTiming schema, and not the SaveTiming schema in the same request, I suspected a recent change (maybe https://gerrit.wikimedia.org/r/#/c/mediawiki/extensions/NavigationTiming/+/441934/, which changed the revision ID). However, I that didn't seem to be the cause because:

  1. NavigationTiming was working fine on my localhost MediaWiki.
  2. And, the underlying API request that EventLogging makes from load.php works fine (https://meta.wikimedia.org/w/api.php?action=jsonschema&revid=18156125&formatversion=2).

That request is triggered from EventLogging/RemoteSchema.php (source code). Which does the following:

  • get:1: Try memcGet() = false (key doesn't exist).
  • get:2: Try httpGet()
    • httpGet:1: Acquire cache->lock(), or return false.
    • httpGet:2: Fetch schema from meta.wikimedia.org over HTTP.
    • httpGet:3: Parse response as JSON.
    • httpGet:4: If fetch or parsing failed, log error and return false.
    • httpGet:5: Return parsed response.

There are no log messages about the request failing. And as mentioned, trying that request manually shows it works fine. Instead, what I find when trying to reproduce it via the REPL, is that it seems Memcached isn't allowing PHP to acquire a lock.

When manually calling $cache->get() with the lock key, it returns false suggesting the lock isn't taken. Yet, when calling $cache->add() with the lock key, it also returns false.

Terminal
beta-tin$ mwscript eval.php --wiki enwiki

> var_dump( $cache->get($key . ':lock') );
bool(false)

> var_dump( $cache->add($key . ':lock', 1, 20) );
bool(false)

> var_dump( $cache->add($key . ':lock', 1, 20) );
bool(false)

> var_dump( $cache->get($key . ':lock') );
bool(false)

If this is due an issue with MultiWrite/ReplicatedBagOStuff logic we added for mcrouter, then it might be the same root-cause as T198279.

See also:

Details

SubjectRepoBranchLines +/-
objectcache: make MultiWriteBagOStuff handle duplicate add() operationsmediawiki/corewmf/1.32.0-wmf.10+48 -22
objectcache: make MultiWriteBagOStuff handle duplicate add() operationsmediawiki/coremaster+48 -22
Add better logging in RemoteSchema.php for failed locking and httpmediawiki/extensions/EventLoggingmaster+12 -2
Customize query in gerrit

Related Objects
Search...

Event Timeline

Krinkle created this task.Jun 27 2018, 1:24 AM
Restricted Application added a project: Analytics. · View Herald TranscriptJun 27 2018, 1:24 AM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
Krinkle triaged this task as Unbreak Now! priority.Jun 27 2018, 1:25 AM
Krinkle updated the task description. (Show Details)
Restricted Application added subscribers: Liuxinyu970226, TerraCodes. · View Herald TranscriptJun 27 2018, 1:25 AM
Krinkle renamed this task from EventLogging/RemoteSchema unable to obtain memcached lock to Beta Cluster: EventLogging/RemoteSchema unable to obtain memcached lock.Jun 27 2018, 1:31 AM
Krinkle updated the task description. (Show Details)
aaron added a comment.Jun 27 2018, 6:12 PM

I can't reproduce this in eval.php (after https://gerrit.wikimedia.org/r/#/c/mediawiki/core/+/442245/).

aaron added a comment.Jun 27 2018, 6:12 PM
This comment was removed by aaron.
Krinkle added a comment.EditedJun 27 2018, 10:16 PM

Hm.. well, the load.php url is still experiencing the same issue. I also see the same happen on CLI still.

I confirmed via Special:Version that the commit was applied (at 8faba225fefd7).

Terminal
krinkle@deployment-tin:~$ mwscript eval.php --wiki enwiki
> $s = new RemoteSchema('NavigationTiming', 18156125);
> var_dump( $s->get() );
bool(false)

> var_dump( $s->key );
string(74) "global:eventlogging-schema:https%3A//meta.wikimedia.org/w/api.php:18156125"

> echo get_class($s->cache);
ReplicatedBagOStuff
> var_dump( $s->cache->get( $s->key ) );
bool(false)

> var_dump( $s->cache->get( $s->key . ':lock', 1, 20 ) );
bool(false)

> var_dump( $s->cache->add( $s->key . ':lock', 1, 20 ) );
bool(false)

Digging a bit further, it seems the added key does get shown by get() but add() is returning false regardless. Demonstrated below:

get and set seem fine
> var_dump( $s->cache->get( 'krinkle:test' ) );
bool(false)
> var_dump( $s->cache->set( 'krinkle:test', 'x', 5 ) );
bool(true)
> var_dump( $s->cache->get( 'krinkle:test' ) );
string(1) "x"

> var_dump( $s->cache->get( 'krinkle:test' ) );
bool(false)
add has issues
> var_dump( $s->cache->get('krinkle:test') );
bool(false)
> var_dump( $s->cache->add('krinkle:test', 'x', 20) );
bool(false)

// Above: add() returns false.
// Below: get() shows the key did actually get added..

> var_dump( $s->cache->get( 'krinkle:test' ) );
string(1) "x"
> var_dump( $s->cache->get( 'krinkle:test' ) );
string(1) "x"
> var_dump( $s->cache->set( 'krinkle:test', 'y', 5 ) );
bool(true)
> var_dump( $s->cache->get( 'krinkle:test' ) );
string(1) "y"

> var_dump( $s->cache->get('krinkle:test') );
bool(false)

// And again:

> var_dump( $s->cache->add('krinkle:test', 'z', 20) );
bool(false)

> var_dump( $s->cache->get('krinkle:test') );
string(1) "z"
aaron added a comment.Jun 27 2018, 10:33 PM

How is $cache defined?

aaron added a comment.Jun 27 2018, 10:41 PM

Maybe for certain keys, when the mc server used by nutcracker matches that of the mcrouter one, add() fails since it has to succeed on *all* backends for MultiWriteBagOStuff to return true and the second write would see the first one.

Krinkle added a comment.Jun 27 2018, 10:41 PM
$s = new RemoteSchema('NavigationTiming', 18156125);
$s->cache

From source code which does wfGetCache( CACHE_ANYTHING );.

Krinkle renamed this task from Beta Cluster: EventLogging/RemoteSchema unable to obtain memcached lock to Beta Cluster: Unable to obtain lock via objectcache (memcached).Jun 28 2018, 1:35 AM
Krinkle renamed this task from Beta Cluster: Unable to obtain lock via objectcache (memcached) to Beta Cluster: Unable to obtain lock via objectcache (memcached add() fails).
aaron added a comment.Jun 28 2018, 8:32 AM

I get:

> $s = new RemoteSchema('NavigationTiming', 18156125);

> var_dump( $s->cache->lock( $s->key, 1, 20 ) );
bool(true)

> var_dump( $s->cache->lock( $s->key, 1, 20 ) );
bool(false)

> var_dump( $s->cache->unlock( $s->key, 1, 20 ) );
bool(true)

> var_dump( $s->cache->add($key . ':lock', 1, 20) );
bool(true)

> var_dump( $s->cache->add($key . ':lock', 1, 20) );
bool(false)

> var_dump( $s->cache->get($key . ':lock') );
int(1)
gerritbot subscribed.Jun 28 2018, 9:44 AM

Change 442813 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] objectcache: make MultiWriteBagOStuff handle duplicate add() operations

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

gerritbot added a project: Patch-For-Review.Jun 28 2018, 9:44 AM
gerritbot added a comment.Jun 28 2018, 6:28 PM

Change 442902 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[mediawiki/extensions/EventLogging@master] Add better logging in RemoteSchema.php for failed locking and http

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

Krinkle added a parent task: T192370: Deploy mcrouter to production as a wancache backend.Jun 28 2018, 9:33 PM
Krinkle edited parent tasks, added: T198239: Rollout use of mcrouter for MediaWiki in production; removed: T192370: Deploy mcrouter to production as a wancache backend.
gerritbot added a comment.Jun 29 2018, 2:16 AM

Change 442813 merged by jenkins-bot:
[mediawiki/core@master] objectcache: make MultiWriteBagOStuff handle duplicate add() operations

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

gerritbot added a comment.Jun 29 2018, 1:58 PM

Change 442902 merged by jenkins-bot:
[mediawiki/extensions/EventLogging@master] Add better logging in RemoteSchema.php for failed locking and http

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

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-07-10 (1.32.0-wmf.12)).Jun 30 2018, 7:01 PM
aaron added a comment.Jul 2 2018, 10:41 AM

As of now, I get (as expected):

> $s = new RemoteSchema('NavigationTiming', 18156125);

> var_dump( $s->cache->get('krinkle:test' ) );
bool(false)

> var_dump( $s->cache->add('krinkle:test', 'x', 20) );
bool(true)

> var_dump( $s->cache->add('krinkle:test', 'x', 20) );
bool(false)

> var_dump( $s->cache->get('krinkle:test' ) );
string(1) "x"
• fdans moved this task from Incoming to Radar on the Analytics board.Jul 2 2018, 4:18 PM
Krinkle closed this task as Resolved.Jul 2 2018, 7:17 PM
Krinkle assigned this task to aaron.
Liuxinyu970226 unsubscribed.Jul 3 2018, 3:25 AM
gerritbot added a comment.Jul 10 2018, 8:32 PM

Change 445005 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@wmf/1.32.0-wmf.10] objectcache: make MultiWriteBagOStuff handle duplicate add() operations

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

gerritbot added a comment.Jul 10 2018, 8:46 PM

Change 445005 merged by jenkins-bot:
[mediawiki/core@wmf/1.32.0-wmf.10] objectcache: make MultiWriteBagOStuff handle duplicate add() operations

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

ReleaseTaggerBot edited projects, added MW-1.32-notes (WMF-deploy-2018-06-26 (1.32.0-wmf.10)); removed MW-1.32-notes (WMF-deploy-2018-07-10 (1.32.0-wmf.12)).Jul 11 2018, 12:01 AM
Krinkle mentioned this in T199237: Unable to submit edit due to Exception "Key contains invalid characters" from MemcachedBagOStuff.Jul 11 2018, 3:44 AM
Krinkle mentioned this in T198239: Rollout use of mcrouter for MediaWiki in production.Jul 12 2018, 3:24 AM
Aklapper edited projects, added Analytics-Radar; removed Analytics.Jun 10 2020, 6:43 AM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL · Credits