On 08/10/2014 04:10 PM, Bjoern Kahl wrote: In case this is a private wiki: Did you set $wgSessionsInObjectCache = true; following the instructions at https://www.mediawiki.org/wiki/Extension:VisualEditor#Linking_with_Parsoid_… ?

What seems like a deadlock may in fact be parsoid timing out while trying to connect to your local wiki's API end point. We have had some users report problems of this sort which were caused by their firewall or access control setup. You might want to verify that the API end point for your local wiki is configured correctly, and that you can successfully connect to it from the machine Parsoid is running on.

On Sun, Aug 10, 2014 at 11:56 PM, Bjoern Kahl <mls(a)bjoern-kahl.de> wrote: > > Am 10.08.14 um 20:52 schrieb Gabriel Wicke: >> On 08/10/2014 04:10 PM, Bjoern Kahl wrote: >>> What could cause this behavior and how should I configure my >>> system to prevent the deadlocks? If this is a Bug in either >>> MediWiki or the VisualEditor or Parsoid, how to further >>> investigate and fix it? >> >> In case this is a private wiki: >> >> Did you set $wgSessionsInObjectCache = true; >> >> following the instructions at >> https://www.mediawiki.org/wiki/Extension:VisualEditor#Linking_with_Parsoid_… >> >> ? > > Yes, I have (and had) "$wgSessionsInObjectCache = true;" in my > LocalSettings.php > > I have just disabled it (set to false) to counter-check, and it > does produce a different sequence of activities. On a first > glance, it seems to stop earlier, but in the end process and > answer three calls from Parsoid instead of zero. > > I'll have a closer look tomorrow, for today it's to late (1 in > the morning (1 CEST / 23 UTC))

Holding a database lock while a Parsoid query is made seems like a really bad idea. That seems like it could be a big in MediaWiki core. However, I'm running an almost identical setup on my machine (Debian/unstable rather than wheezy) as are most Parsoid developers (Ubuntu instead of Debian) and I've never seen this.

Perhaps I might suggest looking closely at the code which takes database locks, and why it is doing so? Perhaps more details on your db configuration would also be helpful, if you're not using Debian and MediaWiki defaults.

+ require_once ( 'extensions/BibTex/bibtex.php' ); + require_once ( 'extensions/MathJax/MathJax.php' ); + require_once('extensions/WikiEditor/WikiEditor.php'); + require_once('extensions/UserMerge/UserMerge.php'); + require_once("$IP/extensions/LastUserLogin/LastUserLogin.php");

Is this happening for all pages on the wiki, or just for this “TestPage”?

On Monday, August 11, 2014 at 4:48 PM, Bjoern Kahl wrote: > > Dear Scott > dear All, > > Am 11.08.14 um 11:54 schrieb C. Scott Ananian: >>> What could cause this behavior and how should I configure my system to >>> prevent the deadlocks? If this is a Bug in either MediWiki or the >>> VisualEditor or Parsoid, how to further investigate and fix it? >>> Wikitech-l mailing list >>> Wikitech-l(a)lists.wikimedia.org (mailto:Wikitech-l@lists.wikimedia.org) >>> https://lists.wikimedia.org/mailman/listinfo/wikitech-l >>> >> >> >> Holding a database lock while a Parsoid query is made seems like a really >> bad idea. That seems like it could be a big in MediaWiki core. However, >> I'm running an almost identical setup on my machine (Debian/unstable rather >> than wheezy) as are most Parsoid developers (Ubuntu instead of Debian) and >> I've never seen this. >> > > > Honestly, I was surprised running into this problem and I am still not > sure where the culprit is. MediaWiki is used at so many places, it is > hard to believe in a locking bug, although possible. > > >> Perhaps I might suggest looking closely at the code which takes database >> locks, and why it is doing so? Perhaps more details on your db >> configuration would also be helpful, if you're not using Debian and >> MediaWiki defaults. >> > > > Here come more details: > > - Everything runs on a single server, single core. > > - System runs in 32 bit mode (although CPU is capable of 64 bit mode) > > - mySQL table type is InnoDB > > - no unusual mysql server options are in effect, as far as I remember > > - PHP is not using memcache or any other caching module > > - the Wiki is mostly idle, approx 30 users and highest ever concurrent > login count was 3 users. > > - All tests so far done with a copy where at most one user was active > at anytime (myself) > > - my LocalSettings.php might be a bit non-standard. Here some > settings that may or may not be relevant (in order of appearance > in LocalSettings.php): > > + $wgDBprefix = "wiki_"; > + $wgDBTableOptions = "ENGINE=InnoDB, DEFAULT CHARSET=binary"; > + $wgDBmysql5 = false; > + $wgMainCacheType = CACHE_NONE; > + $wgMemCachedServers = array(); > + $wgUseInstantCommons = false; > + $wgDefaultSkin = "vector"; > + $wgResourceLoaderMaxQueryLength = -1; > + $wgGroupPermissions['*']['createaccount'] = false; > + $wgGroupPermissions['*']['edit'] = false; > + $wgGroupPermissions['*']['read'] = false; > + require_once ( 'extensions/BibTex/bibtex.php' ); > + require_once ( 'extensions/MathJax/MathJax.php' ); > + $wgParserCacheType = CACHE_NONE; > + $wgTexvc = '/extensions/Math/math/texvc'; > + $wgUseTeX = true; > + require_once('extensions/WikiEditor/WikiEditor.php'); > + require_once "$IP/extensions/Parsoid/Parsoid.php"; > + require_once "$IP/extensions/VisualEditor/VisualEditor.php"; > + $wgDefaultUserOptions['visualeditor-enable'] = 1; > + $wgVisualEditorParsoidURL = 'http://<my.server.name (http://my.server.name)>:8000'00'; > + $wgVisualEditorParsoidPrefix = 'testwiki'; > + $wgSessionsInObjectCache = true; > + $wgVisualEditorParsoidForwardCookies = true; > + require_once('extensions/UserMerge/UserMerge.php'); > + require_once("$IP/extensions/LastUserLogin/LastUserLogin.php"); > > - Also in LocalSettings.php, I have enabled debugging using: > > + $wgDebugLogFile = "</some/path/to>/mediawiki-debug-{$wgDBname}.log"; > + $wgShowSQLErrors = true; > + $wgShowDBErrorBacktrace = true; > + $wgDebugTimestamps = true; > + $wgDebugDumpSql = true; > > Are there other / better options to get a comprehensive trace of > what happens when? > > > - - - - Please find below an excerpt from the debug log - - - - > > Note: > I tweaked wfDebugTimer() to have absolute timestamps and to have > client address/port in order to relate debug log lines to tcpdump > logs from capturing the on-wire conversation between MediaWiki and > Parsoid service. > > Sorry for the overlong lines. > > If I should upload the log somewhere, please tell me where. > > > (1) client access to API for visual editor > > <client.ip>:55246 17:49:15.640 0.1347 1.5M Start request GET > /wiki/api.php?format=json&action=visualeditor&paction=parse&page=TestPage > HTTP HEADERS: > HOST: <my.server.name (http://my.server.name)> > X-REQUESTED-WITH: XMLHttpRequest > USER-AGENT: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) > AppleWebKit/534.59.10 (KHTML, like Gecko) Version/5.1.9 Safari/534.59.10 > ACCEPT: application/json, text/javascript, */*; q=0.01 > REFERER: http://<my.server.name (http://my.server.name)>/wiki/index.php/TestPage?veaction=edit > ACCEPT-LANGUAGE: de-de > ACCEPT-ENCODING: gzip, deflate > COOKIE: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > CONNECTION: keep-alive > <client.ip>:55246 17:49:15.662 0.1566 1.5M [caches] main: > EmptyBagOStuff, message: SqlBagOStuff, parser: EmptyBagOStuff > <client.ip>:55246 17:49:15.730 0.2252 2.2M Connected to database 0 > at localhost > <client.ip>:55246 17:49:15.737 0.2318 2.2M Connected to database 0 > at localhost > <client.ip>:55246 17:49:15.738 0.2326 2.2M Query test (1) (slave): > SELECT /* SqlBagOStuff::getMulti */ keyname,value,exptime FROM > `wiki_objectcache` WHERE keyname = > 'test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0' > <client.ip>:55246 17:49:15.837 0.3320 3.2M [caches] > LocalisationCache: using store LCStoreDB > <client.ip>:55246 17:49:15.924 0.4189 4.2M Unstubbing $wgParser on > call of $wgParser::setHook from wfBibtexExtension > <client.ip>:55246 17:49:15.990 0.4846 4.8M Parser: using > preprocessor: Preprocessor_DOM > <client.ip>:55246 17:49:15.997 0.4921 4.8M DatabaseBase::query: > Writes done: UPDATE `wiki_user` SET user_touched = '20140809154915' > WHERE user_id = 18 > > *** next line starts transaction *** > > <client.ip>:55246 17:49:15.998 0.4926 4.8M Query test (2) (slave): > BEGIN /* DatabaseBase::query (DatabaseBase::query) */ > <client.ip>:55246 17:49:15.998 0.4932 4.8M Query test (3) (slave): > UPDATE /* DatabaseBase::query */ `wiki_user` SET user_touched = > '20140809154915' WHERE user_id = 18 > <client.ip>:55246 17:49:20.242 4.7366 4.8M Fully initialised > <client.ip>:55246 17:49:20.298 4.7928 5.2M User: cache miss for user 18 > <client.ip>:55246 17:49:20.299 4.7937 5.2M Query test (4) (slave): > SELECT /* User::loadFromDatabase */ > user_id,user_name,user_real_name,user_password,user_newpassword,user_newpass_time,user_email,user_touched,user_token,user_email_authenticated,user_email_token,user_email_token_expires,user_password_expires,user_registration,user_editcount > FROM `wiki_user` WHERE user_id = '18' LIMIT 1 > <client.ip>:55246 17:49:20.305 4.8003 5.2M Query test (5) (slave): > SELECT /* User::loadGroups */ ug_group FROM `wiki_user_groups` > WHERE ug_user = '18' > <client.ip>:55246 17:49:20.315 4.8096 5.5M Query test (6) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'deps' LIMIT 1 > <client.ip>:55246 17:49:20.317 4.8120 5.5M Query test (7) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'list' LIMIT 1 > <client.ip>:55246 17:49:20.323 4.8181 6.0M Query test (8) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'preload' LIMIT 1 > <client.ip>:55246 17:49:20.332 4.8275 6.0M Query test (9) (slave): > SELECT /* LCStoreDB::get */ lc_value FROM `wiki_l10n_cache` WHERE > lc_lang = 'en' AND lc_key = 'preload' LIMIT 1 > <client.ip>:55246 17:49:20.336 4.8310 6.0M User: loading options > for user 18 from database. > <client.ip>:55246 17:49:20.337 4.8318 6.0M Query test (10) (slave): > SELECT /* User::loadOptions */ up_property,up_value FROM > `wiki_user_properties` WHERE up_user = '18' > <client.ip>:55246 17:49:20.338 4.8330 6.0M User: logged in from session > <client.ip>:55246 17:49:20.356 4.8515 6.0M Query test (11) (slave): > SELECT /* LCStoreDB::get TestUser */ lc_value FROM `wiki_l10n_cache` > WHERE lc_lang = 'en' AND lc_key = 'namespaceGenderAliases' LIMIT 1 > <client.ip>:55246 17:49:20.358 4.8527 6.0M Query test (12) (slave): > SELECT /* LinkCache::addLinkObj TestUser */ > page_id,page_len,page_is_redirect,page_latest,page_content_model FROM > `wiki_page` WHERE page_namespace = '2' AND page_title = 'TestUser' > LIMIT 1 > <client.ip>:55246 17:49:20.367 4.8623 6.0M Query test (13) (slave): > SELECT /* Revision::fetchFromConds TestUser */ > rev_id,rev_page,rev_text_id,rev_timestamp,rev_comment,rev_user_text,rev_user,rev_minor_edit,rev_deleted,rev_len,rev_parent_id,rev_sha1,rev_content_format,rev_content_model,page_namespace,page_title,page_id,page_latest,page_is_redirect,page_len,user_name > FROM `wiki_revision` INNER JOIN `wiki_page` ON ((page_id = rev_page)) > LEFT JOIN `wiki_user` ON ((rev_user != 0) AND (user_id = rev_user)) > WHERE page_namespace = '2' AND page_title = 'TestUser' > > Note: no "COMMIT" here. Transaction will eventually be COMMITed after > timing out interaction with Parsoid service and aborting the > VisualEditor request (not part of this log excerpt). > > > (2) Mediawiki calling Parsoid service (from tcpdump, abridged) > > 17:49:20.387646 IP <server.ip>.37260 > <server.ip>.8000: Flags [S], seq > 3008505020, win 32792 > 17:49:20.387678 IP <server.ip>.8000 > <server.ip>.37260: Flags [S.], seq > 59446639, ack 3008505021, win 32768 > 17:49:20.387702 IP <server.ip>.37260 > <server.ip>.8000: Flags [.], ack > 1, win 2050 > 17:49:20.389966 IP <server.ip>.37260 > <server.ip>.8000: Flags [P.], seq > 1:387, ack 1, win 2050 > GET /testwiki/TestPage?oldid=4053 HTTP/1.0 > Host: <my.server.name (http://my.server.name)>:8000 > Accept: */* > Accept-Encoding: deflate, gzip^MCookie: > wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > User-Agent: MediaWiki/1.23.2 > > > 17:49:20.390014 IP <server.ip>.8000 > <server.ip>.37260: Flags [.], ack > 387, win 2048 > > > (3a) Parsoid calling MediaWiki API (from tcpdump, abridged) > > > 17:49:20.412369 IP <server.ip>.43619 > <server.ip>.80: Flags [S], seq > 1070720780, win 32792 > 17:49:20.412402 IP <server.ip>.80 > <server.ip>.43619: Flags [S.], seq > 4074871095, ack 1070720781, win 32768 > 17:49:20.412427 IP <server.ip>.43619 > <server.ip>.80: Flags [.], ack 1, > win 2050 > 17:49:20.413214 IP <server.ip>.43619 > <server.ip>.80: Flags [P.], seq > 1:459, ack 1, win 2050 > GET > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > HTTP/1.1 > User-Agent: Parsoid/0.1 > Connection: close > Cookie: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > host: <my.server.name (http://my.server.name)> > > > 17:49:20.413264 IP <server.ip>.80 > <server.ip>.43619: Flags [.], ack > 459, win 2048 > > > (3b) Parsoid calling MediaWiki API (from MediaWiki debug log) > > <server.ip>:43619 17:49:20.492 0.0759 1.5M Start request GET > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > HTTP HEADERS: > USER-AGENT: Parsoid/0.1 > CONNECTION: close > COOKIE: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > HOST: <my.server.name (http://my.server.name)> > <server.ip>:43619 17:49:20.502 0.0859 1.5M [caches] main: > EmptyBagOStuff, message: SqlBagOStuff, parser: EmptyBagOStuff > <server.ip>:43619 17:49:20.538 0.1221 2.2M Connected to database 0 > at localhost > <server.ip>:43619 17:49:20.539 0.1234 2.2M Connected to database 0 > at localhost > <server.ip>:43619 17:49:20.540 0.1241 2.2M Query test (1) (slave): > SELECT /* SqlBagOStuff::getMulti */ keyname,value,exptime FROM > `wiki_objectcache` WHERE keyname = > 'test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0' > <server.ip>:43619 17:49:20.594 0.1782 3.2M [caches] > LocalisationCache: using store LCStoreDB > <server.ip>:43619 17:49:20.640 0.2249 4.2M Unstubbing $wgParser on > call of $wgParser::setHook from wfBibtexExtension > <server.ip>:43619 17:49:20.672 0.2567 4.8M Parser: using > preprocessor: Preprocessor_DOM > <server.ip>:43619 17:49:20.676 0.2603 4.8M DatabaseBase::query: > Writes done: UPDATE `wiki_user` SET user_touched = '20140809154920' > WHERE user_id = 18 > <server.ip>:43619 17:49:20.676 0.2608 4.8M Query test (2) (slave): > BEGIN /* DatabaseBase::query (DatabaseBase::query) */ > <server.ip>:43619 17:49:20.677 0.2614 4.8M Query test (3) (slave): > UPDATE /* DatabaseBase::query */ `wiki_user` SET user_touched = > '20140809154920' WHERE user_id = 18 > > *** dead lock occurred *** > > (4) Parsoid timing out and recalling > > <server.ip>:43620 17:50:00.515 0.0757 1.5M Start request GET > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > HTTP HEADERS: > USER-AGENT: Parsoid/0.1 > CONNECTION: close > COOKIE: wikiEditor-0-toolbar-section=advanced; > test_wiki__session=gt5evdjgg9ebdrkcg4i6c6gqc0; > test_wiki_UserName=TestUser; test_wiki_UserID=18; > PHPSESSID=ts0j9nug4oa0o2c4fka2ok5ei3 > HOST: <my.server.name (http://my.server.name)> > <server.ip>:43620 17:50:00.525 0.0854 1.5M [caches] main: > EmptyBagOStuff, message: SqlBagOStuff, parser: EmptyBagOStuff > <server.ip>:43620 17:50:00.559 0.1197 2.2M Connected to database 0 > at localhost > <server.ip>:43620 17:50:00.560 0.1209 2.2M Connected to database 0 > at localhost > <server.ip>:43620 17:50:00.561 0.1216 2.2M Query test (1) (slave): > SELECT /* SqlBagOStuff::getMulti */ keyname,value,exptime FROM > `wiki_objectcache` WHERE keyname = > 'test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0' > <server.ip>:43620 17:50:00.612 0.1727 3.2M [caches] > LocalisationCache: using store LCStoreDB > <server.ip>:43620 17:50:00.657 0.2171 4.2M Unstubbing $wgParser on > call of $wgParser::setHook from wfBibtexExtension > <server.ip>:43620 17:50:00.687 0.2475 4.8M Parser: using > preprocessor: Preprocessor_DOM > <server.ip>:43620 17:50:00.691 0.2510 4.8M DatabaseBase::query: > Writes done: UPDATE `wiki_user` SET user_touched = '20140809155000' > WHERE user_id = 18 > <server.ip>:43620 17:50:00.691 0.2515 4.8M Query test (2) (slave): > BEGIN /* DatabaseBase::query (DatabaseBase::query) */ > <server.ip>:43620 17:50:00.692 0.2521 4.8M Query test (3) (slave): > UPDATE /* DatabaseBase::query */ `wiki_user` SET user_touched = > '20140809155000' WHERE user_id = 18 > > *** dead lock *** > > (5) MediaWiki timing out on lock acquisition > > <server.ip>:43619 17:50:11.927 51.5110 4.8M SQL ERROR: Lock wait > timeout exceeded; try restarting transaction (localhost) > <server.ip>:43619 17:50:11.937 51.5217 4.8M [Bug56269] Exception > thrown with an uncommited database transaction: [5640864b] > /wiki/api.php?format=json&action=query&prop=revisions&rvprop=content%7Cids%7Ctimestamp%7Cuser%7Cuserid%7Csize%7Csha1%7Ccontentmodel%7Ccomment&revids=4053 > Exception from line 1157 of > </some/path>/wiki/includes/db/Database.php: A database error has > occurred. Did you forget to run maintenance/update.php after upgrading? > See: https://www.mediawiki.org/wiki/Manual:Upgrading#Run_the_update_script > Query: UPDATE `wiki_user` SET user_touched = '20140809154920' WHERE > user_id = 18 > Function: DatabaseBase::query > Error: 1205 Lock wait timeout exceeded; try restarting transaction > (localhost) > > #0 </some/path>/wiki/includes/db/Database.php(1123): > DatabaseBase->reportQueryError('Lock wait timeo...', 1205, 'UPDATE > `wiki_us...', 'DatabaseBase::q...', false) > #1 </some/path>/wiki/extensions/LastUserLogin/LastUserLogin.php(64): > DatabaseBase->query('UPDATE `wiki_us...') > #2 [internal function]: wfUpdateUserTouched() > #3 </some/path>/wiki/includes/Setup.php(601): > call_user_func('wfUpdateUserTou...') > #4 </some/path>/wiki/includes/WebStart.php(156): > require_once('/var/www/virtua...') > #5 </some/path>/wiki/api.php(43): require('/var/www/virtua...') > #6 {main} > <server.ip>:43619 17:50:11.938 51.5224 4.8M Query test (4) (slave): > ROLLBACK /* LoadBalancer::rollbackMasterChanges */ > <server.ip>:43619 17:50:11.941 51.5257 4.8M DatabaseBase::query: > Writes done: REPLACE INTO `wiki_objectcache` (keyname,value,exptime) > VALUES ('test-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0','<binary data > removed>','20140809165011') > <server.ip>:43619 17:50:11.942 51.5262 4.8M Query test (5) (slave): > REPLACE /* SqlBagOStuff::set */ INTO `wiki_objectcache` > (keyname,value,exptime) VALUES > ('testtest-wiki_:session:gt5evdjgg9ebdrkcg4i6c6gqc0','<binary data > removed>','20140809165011')