Page MenuHomePhabricator

Watchlist get requests should be idempotent; Logstash info: Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 3)
Closed, ResolvedPublic5 Estimated Story Points

Description

About 6000 every 3 hours I'm seeing

Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 3):
query-m: INSERT IGNORE INTO `user_properties` (up_user,up_property,up_value) VALUES ('X') [TRX#fc1af7]
#0 /srv/mediawiki/php-1.31.0-wmf.5/includes/libs/rdbms/TransactionProfiler.php(219): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.31.0-wmf.5/includes/libs/rdbms/database/Database.php(1037): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion()
#2 /srv/mediawiki/php-1.31.0-wmf.5/includes/libs/rdbms/database/Database.php(937): Wikimedia\Rdbms\Database->doProfiledQuery()
#3 /srv/mediawiki/php-1.31.0-wmf.5/includes/libs/rdbms/database/Database.php(1608): Wikimedia\Rdbms\Database->query()
#4 /srv/mediawiki/php-1.31.0-wmf.5/includes/user/User.php(5423): Wikimedia\Rdbms\Database->insert()
#5 /srv/mediawiki/php-1.31.0-wmf.5/includes/user/User.php(4061): User->saveOptions()
#6 /srv/mediawiki/php-1.31.0-wmf.5/extensions/MobileFrontend/includes/specials/SpecialMobileWatchlist.php(87): User->saveSettings()
#7 /srv/mediawiki/php-1.31.0-wmf.5/includes/deferred/MWCallableUpdate.php(30): Closure$SpecialMobileWatchlist::executeWhenAvailable()
#8 /srv/mediawiki/php-1.31.0-wmf.5/includes/deferred/DeferredUpdates.php(259): MWCallableUpdate->doUpdate()
#9 /srv/mediawiki/php-1.31.0-wmf.5/includes/deferred/DeferredUpdates.php(210): DeferredUpdates::runUpdate()
#10 /srv/mediawiki/php-1.31.0-wmf.5/includes/deferred/DeferredUpdates.php(131): DeferredUpdates::execute()
#11 /srv/mediawiki/php-1.31.0-wmf.5/includes/MediaWiki.php(897): DeferredUpdates::doUpdates()
#12 /srv/mediawiki/php-1.31.0-wmf.5/includes/MediaWiki.php(719): MediaWiki->restInPeace()
#13 (): Closure$MediaWiki::doPostOutputShutdown()
#14 {main}

https://logstash.wikimedia.org/app/kibana#/discover?_g=(refreshInterval:(display:Off,pause:!f,value:0),time:(from:now-7d,mode:quick,to:now))&_a=(columns:!(_source),index:'logstash-*',interval:auto,query:(query_string:(analyze_wildcard:!t,query:'message:%22User-%3EsaveSettings()%22')),sort:!('@timestamp',desc))

As Timo points out a GET request is supposed to be idempotent

I'm not sure if this will resolve the logstash issue, but moving this code to JS, seems like a sane thing to do. The stickiness of the tab is not the most important of features and could be done in the client after inspecting the value mw.user.options.get('mfWatchlistView') and comparing it to the current view.

Options:

  1. Remove feature SpecialMobileWatchlist::updateStickyTabs and surrounding code
  2. Add logic to client-side instead.
mw.loader.using('mediawiki.api.options').done( () => {
  new mw.Api().saveOption('mfWatchlistView', 'a-z')
} )
  1. Make view switch a form with button instead of link. (See T179445#3725385 for other benefits, and proposal by @Krinkle)

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptOct 31 2017, 10:48 PM

Since violations are reported for 1, 2, and 3 writes, I guess the number of incidents is probably ~2000.

Krinkle added a subscriber: Krinkle.EditedNov 1 2017, 1:22 AM

It appears that Special:MobileWatchlist has a feature that is designed to write to the database from a GET page view, this violates best practices from a technical perspective. From a user perspective, it seems that an invisible user preference is saved every time the page is viewed to memorise which version of the page is used, presumably as way of saving as a default for a future visit.

It might be better (and more efficient) to only save the setting when the user changes the view mode, and such switch would need to occur over a POST request instead, not by following a navigation link, which are expected to be "safe" and stateless. E.g. let the server output the anchor link based on preference, and the button to change view be a form that submits over POST.

Indirectly, the current approach creates a security problem because it means someone can point you to a link within a hidden iframe (resulting in a plain navigation to a predictable url) and the mere loading of this insecure URL would lead to a database write on behalf of your user account (and change your user preferences).

By changing the switch to be explicit via a form, you can also start to distinguish between the user visiting the alternate view directly (e.g. via a shared link), and the user explicitly switching their view within the page (you'd only save the latter case). This also has the benefit of not needing client-side JavaScript.

What else needs clarification with this task? Can we update the description with some A/C and move the task along?

Jdlrobson triaged this task as Medium priority.Nov 2 2017, 11:03 PM
Jdlrobson updated the task description. (Show Details)
pmiazga set the point value for this task to 5.Nov 8 2017, 6:02 PM
pmiazga added a subscriber: pmiazga.Nov 8 2017, 6:10 PM

During Sprint prioritization we decided to give 5 points value mostly because of risk that some code might depend on the modified state and it might require a bit more work than only removing the DB UPDATE action and adding that logic within the client.

I also want to say, that having a check that GET request did 0 db update queries is one of the most awesome things I saw so far. It's great we have checks like that.

Jdlrobson renamed this task from Logstash info: Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 3) to Watchlist get requests should be idempotent; Logstash info: Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 3).Jan 10 2018, 5:20 PM
Krinkle updated the task description. (Show Details)Feb 16 2018, 7:59 AM
Krinkle updated the task description. (Show Details)

Change 414852 had a related patch set uploaded (by Jdlrobson; owner: Jdlrobson):
[mediawiki/extensions/MobileFrontend@master] Watchlist sticky preference is moved to client

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

pmiazga claimed this task.Feb 27 2018, 7:35 PM
pmiazga removed pmiazga as the assignee of this task.Feb 27 2018, 10:37 PM
pmiazga removed a project: Patch-For-Review.

Change 414852 merged by jenkins-bot:
[mediawiki/extensions/MobileFrontend@master] Watchlist sticky preference is moved to client

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

This is skipping QA as we'll want to verify the fix via logstash. Any devs open to helping with this?

Niedzielski closed this task as Resolved.Feb 28 2018, 3:52 PM
Niedzielski claimed this task.

I reviewed the Logstash dashboard as part of my chores today. I only see a single event reported but it's for Echo so I'm calling this task done.

{"@timestamp":"2018-02-27T03:18:16.000000+00:00","@version":1,"host":"mw1323","message":"Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 3):
query-m: DELETE FROM `user_newtalk` WHERE user_id = 'X' [TRX
db7]
#0 /srv/mediawiki/php-1.31.0-wmf.22/includes/libs/rdbms/TransactionProfiler.php(219): Wikimedia\\Rdbms\\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.31.0-wmf.22/includes/libs/rdbms/database/Database.php(1055): Wikimedia\\Rdbms\\TransactionProfiler->recordQueryCompletion()
#2 /srv/mediawiki/php-1.31.0-wmf.22/includes/libs/rdbms/database/Database.php(953): Wikimedia\\Rdbms\\Database->doProfiledQuery()
#3 /srv/mediawiki/php-1.31.0-wmf.22/includes/libs/rdbms/database/Database.php(2425): Wikimedia\\Rdbms\\Database->query()
#4 /srv/mediawiki/php-1.31.0-wmf.22/includes/user/User.php(2434): Wikimedia\\Rdbms\\Database->delete()
#5 /srv/mediawiki/php-1.31.0-wmf.22/includes/user/User.php(2469): User->deleteNewtalk()
#6 /srv/mediawiki/php-1.31.0-wmf.22/extensions/Echo/includes/NotifUser.php(375): User->setNewtalk()
#7 /srv/mediawiki/php-1.31.0-wmf.22/extensions/Echo/Hooks.php(932): MWEchoNotifUser->markRead()
#8 /srv/mediawiki/php-1.31.0-wmf.22/includes/deferred/MWCallableUpdate.php(34): Closure$EchoHooks::onPersonalUrls()
#9 /srv/mediawiki/php-1.31.0-wmf.22/includes/deferred/DeferredUpdates.php(259): MWCallableUpdate->doUpdate()
#10 /srv/mediawiki/php-1.31.0-wmf.22/includes/deferred/DeferredUpdates.php(210): DeferredUpdates::runUpdate()
#11 /srv/mediawiki/php-1.31.0-wmf.22/includes/deferred/DeferredUpdates.php(131): DeferredUpdates::execute()
#12 /srv/mediawiki/php-1.31.0-wmf.22/includes/MediaWiki.php(907): DeferredUpdates::doUpdates()
#13 /srv/mediawiki/php-1.31.0-wmf.22/includes/MediaWiki.php(727): MediaWiki->restInPeace()
#14 (): Closure$MediaWiki::doPostOutputShutdown()
#15 {main}","type":"mediawiki","channel":"DBPerformance","level":"WARNING","shard":"s4","normalized_message":"Expectation ({measure} <= {max}) by {by} not met (actual: {actual}):
{query}
#0 /srv/mediawiki/php-1.31.0-wmf.22/includes/libs/rdbms/TransactionProfiler.php(219): Wikimedia\\Rdbms\\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.31.","url":"/w/index.php?title=User_talk:Hi%C3%A0n&action=edit&autoclick=wpSave&actoken=444c08e870d6551a&autoimpl=np20140416&autosummary=Revert%20to%20revision%20$1%20dated%20$2%20by%20$3%20using%20[[:en:Wikipedia:Tools/Navigation_popups|popups]]&autorv=286174484&oldid=286174484","ip":"10.64.0.102","http_method":"GET","server":"commons.wikimedia.org","referrer":"https://commons.wikimedia.org/wiki/Special:Watchlist?hidemyself=1&hidepreviousrevisions=1&translations=filter&hidecategorization=1&hideWikibase=1&limit=250&days=3&urlversion=2","unique_id":"WpTN@ApAICwAAFt2GUcAAACB","wiki":"commonswiki","mwversion":"1.31.0-wmf.22","reqId":"WpTN@ApAICwAAFt2GUcAAACB","measure":"writes","max":0,"by":"MediaWiki::restInPeace","actual":3,"query":"query-m: DELETE FROM `user_newtalk` WHERE user_id = 'X' [TRX
db7]"}