Page MenuHomePhabricator

VisualEditor fails with "cannot start a transaction within a transaction"
Closed, DeclinedPublic

Description

I have these installed on my Arch Linux system:

  • mediawiki 1.28.2
  • VisualEditor branch wmf/1.28.0-wmf.21, commit rEVED005f3145a3bd
  • sqlite 3.18.0
  • php-fpm 7.1.5
  • parsoid 0.6.1
  • nodejs 7.10.0

When I start VisualEditor I get this: 500: docserver-http: HTTP 500

The parsoid log has this:

{
  "name": "parsoid",
  "hostname": "lilywork",
  "pid": 9839,
  "level": 60,
  "err": {
    "message": "API response Error for ConfigRequest: request=; error={\"code\":\"internal_api_error_DBQueryError\",\"info\":\"[aa2912d03e745e2c8664f42d] Exception Caught: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? \\nQuery: BEGIN\\nFunction: Database::query (MessageCache::loadFromDB(zh-hans)-big)\\nError: 1 cannot start a transaction within a transaction\\n\"}",
    "name": "lib/index.js",
    "stack": "lib/index.js: API response Error for ConfigRequest: request=; error={\"code\":\"internal_api_error_DBQueryError\",\"info\":\"[aa2912d03e745e2c8664f42d] Exception Caught: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? \\nQuery: BEGIN\\nFunction: Database::query (MessageCache::loadFromDB(zh-hans)-big)\\nError: 1 cannot start a transaction within a transaction\\n\"}\n    at ConfigRequest.ApiRequest._errorObj (/usr/share/webapps/parsoid/lib/mw/ApiRequest.js:327:9)\n    at ConfigRequest._handleJSON (/usr/share/webapps/parsoid/lib/mw/ApiRequest.js:907:18)\n    at ConfigRequest.ApiRequest._handleBody (/usr/share/webapps/parsoid/lib/mw/ApiRequest.js:454:7)\n    at ConfigRequest.ApiRequest._requestCB (/usr/share/webapps/parsoid/lib/mw/ApiRequest.js:401:8)\n    at Request.self.callback (/usr/share/webapps/parsoid/node_modules/request/request.js:187:22)\n    at emitTwo (events.js:106:13)\n    at Request.emit (events.js:194:7)\n    at Request.<anonymous> (/usr/share/webapps/parsoid/node_modules/request/request.js:1044:10)\n    at emitOne (events.js:96:13)\n    at Request.emit (events.js:191:7)\n    at IncomingMessage.<anonymous> (/usr/share/webapps/parsoid/node_modules/request/request.js:965:12)\n    at emitNone (events.js:91:20)\n    at IncomingMessage.emit (events.js:188:7)\n    at endReadableNT (_stream_readable.js:975:12)\n    at _combinedTickCallback (internal/process/next_tick.js:80:11)\n    at process._tickCallback (internal/process/next_tick.js:104:9)",
    "levelPath": "fatal/request"
  },
  "msg": "API response Error for ConfigRequest: request=; error={\"code\":\"internal_api_error_DBQueryError\",\"info\":\"[aa2912d03e745e2c8664f42d] Exception Caught: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? \\nQuery: BEGIN\\nFunction: Database::query (MessageCache::loadFromDB(zh-hans)-big)\\nError: 1 cannot start a transaction within a transaction\\n\"}",
  "time": "2017-05-23T09:06:09.239Z",
  "v": 0
}

The request URL is http://localhost/w/api.php?format=json&action=query&meta=siteinfo&siprop=namespaces%7Cnamespacealiases%7Cmagicwords%7Cfunctionhooks%7Cextensiontags%7Cgeneral%7Cinterwikimap%7Clanguages%7Cprotocols%7Cspecialpagealiases&rawcontinue=1 but I don't get the error when I visit it directly.

It reproduces every time.

Event Timeline

Anomie subscribed.

This does not appear to have anything to do with the MediaWiki action API beyond that something happens to be using it when encountering the error. Removing MediaWiki-Action-API.

Tip: Make sure you have MediaWiki logging set up, then search your logs for that code included in the exception message (e.g. "aa2912d03e745e2c8664f42d") to find a stack trace in the PHP code.

Here is the log since I retry after the error is shown. I've removed the cookies.

IP: ::1
Start request GET /w/api.php?action=visualeditor&format=json&paction=parse&page=Dpkg&uselang=zh-hans
HTTP HEADERS:
CONNECTION: keep-alive
COOKIE: [...]
REFERER: http://localhost/w/index.php?title=Dpkg&veaction=edit&vesection=1
X-REQUESTED-WITH: XMLHttpRequest
ACCEPT-ENCODING: gzip, deflate
ACCEPT-LANGUAGE: zh-CN,zh;q=0.7,en;q=0.3
ACCEPT: application/json, text/javascript, */*; q=0.01
USER-AGENT: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0
HOST: localhost
CONTENT-LENGTH:
[caches] cluster: EmptyBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: SqlBagOStuff, parser: SqlBagOStuff, session: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreCDB
[DBReplication] LBFactory::getChronologyProtector: using request info {
    "IPAddress": "::1",
    "UserAgent": "Mozilla\/5.0 (X11; Linux x86_64; rv:52.0) Gecko\/20100101 Firefox\/52.0",
    "ChronologyProtection": false
}
[DBConnection] Connected to database 0 at 'localhost'.
User: cache miss for user 2
[SQLBagOStuff] Connection SQLite 3.18.0 will be used for SqlBagOStuff
[MessageCache] MessageCache::load: Loading zh-hans... local cache is empty, global cache is expired/volatile, loading from database
MediaWikiGadgetsDefinitionRepo::fetchStructuredList: MediaWiki:Gadgets-definition parsed, cache entry should be updated
User: loading options for user 2 from database.
Fully initialised
[visualeditor] called on 'Dpkg' with paction: 'parse'
IP: 127.0.0.1
Start request GET /w/api.php?format=json&action=query&meta=siteinfo&siprop=namespaces%7Cnamespacealiases%7Cmagicwords%7Cfunctionhooks%7Cextensiontags%7Cgeneral%7Cinterwikimap%7Clanguages%7Cprotocols%7Cspecialpagealiases&rawcontinue=1
HTTP HEADERS:
HOST: localhost
CONNECTION: close
USER-AGENT: Parsoid/0.6.1
X-REQUEST-ID: null
CONTENT-LENGTH:
[caches] cluster: EmptyBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: SqlBagOStuff, parser: SqlBagOStuff, session: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreCDB
[CryptRand] Generating cryptographic random bytes for

[CryptRand] openssl_random_pseudo_bytes generated 20 bytes of strong randomness.

[CryptRand] 0 bytes of randomness leftover in the buffer.

[DBReplication] LBFactory::getChronologyProtector: using request info {
    "IPAddress": "127.0.0.1",
    "UserAgent": "Parsoid\/0.6.1",
    "ChronologyProtection": false
}
[DBConnection] Connected to database 0 at 'localhost'.
[SQLBagOStuff] Connection SQLite 3.18.0 will be used for SqlBagOStuff
[session] SessionBackend "kha129qeb6q95v4ibn4r8kcr3nr1ld24" is unsaved, marking dirty in constructor
[session] SessionBackend "kha129qeb6q95v4ibn4r8kcr3nr1ld24" save: dataDirty=1 metaDirty=1 forcePersist=0
[cookie] already deleted setcookie: "wikidb_session", "", "1464062551", "/", "", "", "1"
[cookie] already deleted setcookie: "wikidbUserID", "", "1464062551", "/", "", "", "1"
[cookie] already deleted setcookie: "wikidbToken", "", "1464062551", "/", "", "", "1"
[cookie] already deleted setcookie: "forceHTTPS", "", "1464062551", "/", "", "", "1"
Fully initialised
Unstubbing $wgParser on call of $wgParser::firstCallInit from ApiQuerySiteinfo->execute
Parser: using preprocessor: Preprocessor_DOM
[DBPerformance] Expectation (writes <= 0) by ApiMain::setRequestExpectations not met:
query-m: REPLACE INTO objectcache (keyname,value,exptime) VALUES ('X') [TRX#4b71c1]
#0 /usr/share/webapps/mediawiki/includes/libs/rdbms/TransactionProfiler.php(215): TransactionProfiler->reportExpectationViolated('writes', 'query-m: REPLAC...')
#1 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(958): TransactionProfiler->recordQueryCompletion('query-m: REPLAC...', 1495598551.7045, true, 0)
#2 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(870): Database->doProfiledQuery('REPLACE INTO ob...', 'REPLACE /* SqlB...', true, 'SqlBagOStuff::s...')
#3 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(2162): Database->query('REPLACE INTO ob...', 'SqlBagOStuff::s...')
#4 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/DatabaseSqlite.php(649): Database->nativeReplace('objectcache', Array, 'SqlBagOStuff::s...')
#5 /usr/share/webapps/mediawiki/includes/objectcache/SqlBagOStuff.php(366): DatabaseSqlite->replace('objectcache', Array, Array, 'SqlBagOStuff::s...')
#6 /usr/share/webapps/mediawiki/includes/objectcache/SqlBagOStuff.php(381): SqlBagOStuff->setMulti(Array, 30)
#7 /usr/share/webapps/mediawiki/includes/libs/objectcache/BagOStuff.php(545): SqlBagOStuff->set('wikidb:messages...', 1, 30)
#8 /usr/share/webapps/mediawiki/includes/libs/objectcache/BagOStuff.php(418): BagOStuff->add('wikidb:messages...', 1, 30)
#9 [internal function]: BagOStuff->{closure}()
#10 /usr/share/webapps/mediawiki/vendor/wikimedia/wait-condition-loop/src/WaitConditionLoop.php(92): call_user_func(Object(Closure))
#11 /usr/share/webapps/mediawiki/includes/libs/objectcache/BagOStuff.php(429): Wikimedia\WaitConditionLoop->invoke()
#12 /usr/share/webapps/mediawiki/includes/libs/objectcache/BagOStuff.php(472): BagOStuff->lock('wikidb:messages...', 0, 30, 'MessageCache::g...')
#13 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(705): BagOStuff->getScopedLock('wikidb:messages...', 0, 30, 'MessageCache::g...')
#14 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(402): MessageCache->getReentrantScopedLock('wikidb:messages...', 0)
#15 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(330): MessageCache->loadFromDBWithLock('zh-hans', Array, NULL)
#16 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(932): MessageCache->load('zh-hans')
#17 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(862): MessageCache->getMsgFromNamespace('Mainpage', 'zh-hans')
#18 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(831): MessageCache->getMessageForLang(Object(LanguageZh_hans), 'mainpage', true, Array)
#19 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(771): MessageCache->getMessageFromFallbackChain(Object(LanguageZh_hans), 'mainpage', true)
#20 /usr/share/webapps/mediawiki/includes/Message.php(1188): MessageCache->get('mainpage', true, Object(LanguageZh_hans))
#21 /usr/share/webapps/mediawiki/includes/Message.php(802): Message->fetchMessage()
#22 /usr/share/webapps/mediawiki/includes/Message.php(902): Message->toString()
#23 /usr/share/webapps/mediawiki/includes/Title.php(557): Message->text()
#24 /usr/share/webapps/mediawiki/includes/api/ApiQuerySiteinfo.php(134): Title::newMainPage()
#25 /usr/share/webapps/mediawiki/includes/api/ApiQuerySiteinfo.php(45): ApiQuerySiteinfo->appendGeneralInfo('general')
#26 /usr/share/webapps/mediawiki/includes/api/ApiQuery.php(251): ApiQuerySiteinfo->execute()
#27 /usr/share/webapps/mediawiki/includes/api/ApiMain.php(1435): ApiQuery->execute()
#28 /usr/share/webapps/mediawiki/includes/api/ApiMain.php(510): ApiMain->executeAction()
#29 /usr/share/webapps/mediawiki/includes/api/ApiMain.php(481): ApiMain->executeActionWithErrorHandling()
#30 /usr/share/webapps/mediawiki/api.php(83): ApiMain->execute()
#31 {main}
[DBQuery] SQL ERROR: database is locked

[SQLBagOStuff] DBError: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? 
Query: REPLACE INTO objectcache (keyname,value,exptime) VALUES ('wikidb:messages:zh-hans:lock',x'cbb432b40600','20170524040301')
Function: SqlBagOStuff::setMulti/multi-row
Error: 5 database is locked

[SQLBagOStuff] SqlBagOStuff::handleWriteError: ignoring query error
[DBQuery] SQL ERROR: cannot start a transaction within a transaction

[DBQuery] SQL ERROR: cannot start a transaction within a transaction

[SQLBagOStuff] DBError: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? 
Query: BEGIN
Function: Database::query (SqlBagOStuff::delete)
Error: 1 cannot start a transaction within a transaction

[SQLBagOStuff] SqlBagOStuff::handleWriteError: ignoring query error
[exception] [f8d0aac7200172500d9be77b] /w/api.php?format=json&action=query&meta=siteinfo&siprop=namespaces%7Cnamespacealiases%7Cmagicwords%7Cfunctionhooks%7Cextensiontags%7Cgeneral%7Cinterwikimap%7Clanguages%7Cprotocols%7Cspecialpagealiases&rawcontinue=1   DBQueryError from line 1054 of /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? 
Query: BEGIN
Function: Database::query (MessageCache::loadFromDB(zh-hans)-big)
Error: 1 cannot start a transaction within a transaction

#0 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(912): Database->reportQueryError(string, integer, string, string, boolean)
#1 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/DatabaseSqlite.php(752): Database->query(string, string)
#2 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(2718): DatabaseSqlite->doBegin(string)
#3 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(851): Database->begin(string, string)
#4 /usr/share/webapps/mediawiki/includes/libs/rdbms/database/Database.php(1254): Database->query(string, string)
#5 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(485): Database->select(string, string, array, string)
#6 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(408): MessageCache->loadFromDB(string, NULL)
#7 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(330): MessageCache->loadFromDBWithLock(string, array, NULL)
#8 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(932): MessageCache->load(string)
#9 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(862): MessageCache->getMsgFromNamespace(string, string)
#10 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(831): MessageCache->getMessageForLang(LanguageZh_hans, string, boolean, array)
#11 /usr/share/webapps/mediawiki/includes/cache/MessageCache.php(771): MessageCache->getMessageFromFallbackChain(LanguageZh_hans, string, boolean)
#12 /usr/share/webapps/mediawiki/includes/Message.php(1188): MessageCache->get(string, boolean, LanguageZh_hans)
#13 /usr/share/webapps/mediawiki/includes/Message.php(802): Message->fetchMessage()
#14 /usr/share/webapps/mediawiki/includes/Message.php(902): Message->toString()
#15 /usr/share/webapps/mediawiki/includes/Title.php(557): Message->text()
#16 /usr/share/webapps/mediawiki/includes/api/ApiQuerySiteinfo.php(134): Title::newMainPage()
#17 /usr/share/webapps/mediawiki/includes/api/ApiQuerySiteinfo.php(45): ApiQuerySiteinfo->appendGeneralInfo(string)
#18 /usr/share/webapps/mediawiki/includes/api/ApiQuery.php(251): ApiQuerySiteinfo->execute()
#19 /usr/share/webapps/mediawiki/includes/api/ApiMain.php(1435): ApiQuery->execute()
#20 /usr/share/webapps/mediawiki/includes/api/ApiMain.php(510): ApiMain->executeAction()
#21 /usr/share/webapps/mediawiki/includes/api/ApiMain.php(481): ApiMain->executeActionWithErrorHandling()
#22 /usr/share/webapps/mediawiki/api.php(83): ApiMain->execute()
#23 {main}
ApiMain::setCacheMode: setting cache mode private
MediaWiki::preOutputCommit: primary transaction round committed
MediaWiki::preOutputCommit: pre-send deferred updates completed
[cookie] setcookie: "cpPosTime", "1495598551.7059", "1495598611", "/", "", "", "1"
[DBReplication] ChronologyProtector::shutdownLB: DB 'localhost' touched

MediaWiki::preOutputCommit: LBFactory shutdown completed
Request ended normally
[session] Saving all sessions on shutdown
[DBConnection] Closing connection to database ''.
ApiMain::setCacheMode: setting cache mode private
MediaWiki::preOutputCommit: primary transaction round committed
MediaWiki::preOutputCommit: pre-send deferred updates completed
[cookie] setcookie: "cpPosTime", "1495598551.727", "1495598611", "/", "", "", "1"
[DBReplication] ChronologyProtector::shutdownLB: DB 'localhost' touched

MediaWiki::preOutputCommit: LBFactory shutdown completed
Request ended normally
[session] Saving all sessions on shutdown
[DBConnection] Closing connection to database ''.
Deskana subscribed.

Sadly, the Wikimedia Foundation Editing team does not have enough capacity to help with debugging third party installations. All I can recommend is updating everything to the latest versions, which can often fix many problems.