Topic on Project:Support desk

Hello,

Can someone tell me why MediaWiki is responding to every request with a header that sets the cpPosTime cookie?

This cookie (produced by the Apache backend serving MediaWiki) is causing Varnish to store a hit-for-pass in all of our pages, rendering our caching useless.

Debugging lead me to discover that when the Message Cache is disabled ($wgMessageCacheType = CACHE_NONE;) the cpPosTime cookie is not always returned, allowing varnish to cache. Without disabling the Message Cache, it appears that the Message Cache defaults to using the db. AFAICT, this makes every query to our MediaWiki site include a db write, causing the cpPosTime cookie to be set. Is this the desired default behaviour of MediaWiki?

This is occurring in our staging environment running Mediawiki 1.30.0, PHP 5.6.33, MariaDB 5.5.56-MariaDB, and ICU 50.1.2. In addition to upgrading Mediawiki, we're also adding varnish. Oh, and I've already disabled all MediaWiki extensions.

Both our production and staging environments have exactly 1 database. It is our master. We have no db slaves. There is no db replication.

Please help me to understand why our MediaWiki is setting the cpPosTime cookie for all requests, if this is normal behaviour, and--if so--how one should configure Varnish so it actually caches.

Thanks!

I have $wgDebugLogFile & $wgDebugDBTransactions enabled, so I'll include this here for reference.

Here's the debug output when the $wgMessageCacheType variable is *not* set to CACHE_NONE

[DBReplication] Wikimedia\Rdbms\LBFactory::getChronologyProtector: using request info {
    "IPAddress": "127.0.0.1",
    "UserAgent": "curl\/7.29.0",
    "ChronologyProtection": "true"
}
IP: 127.0.0.1
Start request GET /wiki/Michael_Log
HTTP HEADERS:
X-REAL-IP: 138.201.84.223
X-FORWARDED-PROTO: https
X-FORWARDED-PORT: 443
HOST: wiki.opensourceecology.org
USER-AGENT: curl/7.29.0
ACCEPT: */*
X-FORWARDED-FOR: 127.0.0.1
X-VARNISH: 494755
[caches] cluster: EmptyBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: SqlBagOStuff, session: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreDB
[CryptRand] openssl_random_pseudo_bytes generated 20 bytes of strong randomness.
[CryptRand] 0 bytes of randomness leftover in the buffer.
[DBReplication] Wikimedia\Rdbms\LBFactory::getChronologyProtector: using request info {
    "IPAddress": "127.0.0.1",
    "UserAgent": "curl\/7.29.0",
    "ChronologyProtection": false
}
[DBConnection] Wikimedia\Rdbms\LoadBalancer::openConnection: calling initLB() before first connection.
[DBConnection] Connected to database 0 at 'localhost'.
[SQLBagOStuff] Connection 1064033 will be used for SqlBagOStuff
[session] SessionBackend "lg3t586cdk8n4q9ba89ug1su8ind99ck" is unsaved, marking dirty in constructor
[session] SessionBackend "lg3t586cdk8n4q9ba89ug1su8ind99ck" save: dataDirty=1 metaDirty=1 forcePersist=0
[cookie] already deleted setcookie: "osewiki_db_wiki__session", "", "1489629400", "/", "", "1", "1"
[cookie] already deleted setcookie: "osewiki_db_wiki_UserID", "", "1489629400", "/", "", "1", "1"
[cookie] already deleted setcookie: "osewiki_db_wiki_Token", "", "1489629400", "/", "", "1", "1"
[cookie] already deleted setcookie: "forceHTTPS", "", "1489629400", "/", "", "", "1"
[DBConnection] Connected to database 0 at 'localhost'.
Title::getRestrictionTypes: applicable restrictions to Michael Log are {edit,move}
[ContentHandler] Created handler for wikitext: WikitextContentHandler
Title::getRestrictionTypes: applicable restrictions to Maltfield Log are {edit,move}
OutputPage::checkLastModified: client did not send If-Modified-Since header
[DBPerformance] Expectation (writes <= 0) by MediaWiki::main not met (actual: 1):
query-m: REPLACE INTO `wiki_objectcache` (keyname,value,exptime) VALUES ('X')
#0 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/TransactionProfiler.php(219): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writes', 'query-m: REPLAC...', 1)                                                                                                                                                                                
#1 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(1037): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: REPLAC...', 1521165400.3345, true, 1)                                                                                                                                                                        
#2 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(937): Wikimedia\Rdbms\Database->doProfiledQuery('REPLACE INTO `w...', 'REPLACE /* SqlB...', true, 'SqlBagOStuff::s...')                                                                                                                                                                  
#3 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(2263): Wikimedia\Rdbms\Database->query('REPLACE INTO `w...', 'SqlBagOStuff::s...')
#4 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/DatabaseMysqlBase.php(497): Wikimedia\Rdbms\Database->nativeReplace('objectcache', Array, 'SqlBagOStuff::s...')                                                                                                                                                                                       
#5 /var/www/html/wiki.opensourceecology.org/htdocs/includes/objectcache/SqlBagOStuff.php(362): Wikimedia\Rdbms\DatabaseMysqlBase->replace('objectcache', Array, Array, 'SqlBagOStuff::s...')                                                                                                                                                                                          
#6 /var/www/html/wiki.opensourceecology.org/htdocs/includes/objectcache/SqlBagOStuff.php(376): SqlBagOStuff->setMulti(Array, 30)
#7 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php(545): SqlBagOStuff->set('osewiki_db-wiki...', 1, 30)
#8 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php(418): BagOStuff->add('osewiki_db-wiki...', 1, 30)
#9 [internal function]: BagOStuff->{closure}()
#10 /var/www/html/wiki.opensourceecology.org/htdocs/vendor/wikimedia/wait-condition-loop/src/WaitConditionLoop.php(92): call_user_func(Object(Closure))
#11 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php(429): Wikimedia\WaitConditionLoop->invoke()
#12 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php(472): BagOStuff->lock('osewiki_db-wiki...', 0, 30, 'MessageCache::g...')
#13 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(762): BagOStuff->getScopedLock('osewiki_db-wiki...', 0, 30, 'MessageCache::g...')
#14 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(420): MessageCache->getReentrantScopedLock('osewiki_db-wiki...', 0)
#15 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(350): MessageCache->loadFromDBWithLock('en', Array, NULL)
#16 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(991): MessageCache->load('en')
#17 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(921): MessageCache->getMsgFromNamespace('Pagetitle', 'en')
#18 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(888): MessageCache->getMessageForLang(Object(LanguageEn), 'pagetitle', true, Array)
#19 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(829): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'pagetitle', true)
#20 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(1275): MessageCache->get('pagetitle', true, Object(LanguageEn))
#21 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(842): Message->fetchMessage()
#22 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(934): Message->toString('text')
#23 /var/www/html/wiki.opensourceecology.org/htdocs/includes/OutputPage.php(950): Message->text()
#24 /var/www/html/wiki.opensourceecology.org/htdocs/includes/OutputPage.php(998): OutputPage->setHTMLTitle(Object(Message))
#25 /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/Article.php(463): OutputPage->setPageTitle('Maltfield Log')
#26 /var/www/html/wiki.opensourceecology.org/htdocs/includes/actions/ViewAction.php(68): Article->view()
#27 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(499): ViewAction->show()
#28 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(293): MediaWiki->performAction(Object(Article), Object(Title))
#29 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(861): MediaWiki->performRequest()
#30 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(523): MediaWiki->main()
#31 /var/www/html/wiki.opensourceecology.org/htdocs/index.php(43): MediaWiki->run()
#32 {main}
[DBPerformance] Expectation (writes <= 0) by MediaWiki::main not met (actual: 2):
query-m: REPLACE INTO `wiki_objectcache` (keyname,value,exptime) VALUES ('X')
#0 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/TransactionProfiler.php(219): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writes', 'query-m: REPLAC...', 2)                                                                                                                                                                                
#1 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(1037): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: REPLAC...', 1521165400.3374, true, 2)                                                                                                                                                                        
#2 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(937): Wikimedia\Rdbms\Database->doProfiledQuery('REPLACE INTO `w...', 'REPLACE /* SqlB...', true, 'SqlBagOStuff::s...')                                                                                                                                                                  
#3 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(2263): Wikimedia\Rdbms\Database->query('REPLACE INTO `w...', 'SqlBagOStuff::s...')
#4 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/DatabaseMysqlBase.php(497): Wikimedia\Rdbms\Database->nativeReplace('objectcache', Array, 'SqlBagOStuff::s...')                                                                                                                                                                                       
#5 /var/www/html/wiki.opensourceecology.org/htdocs/includes/objectcache/SqlBagOStuff.php(362): Wikimedia\Rdbms\DatabaseMysqlBase->replace('objectcache', Array, Array, 'SqlBagOStuff::s...')                                                                                                                                                                                          
#6 /var/www/html/wiki.opensourceecology.org/htdocs/includes/objectcache/SqlBagOStuff.php(376): SqlBagOStuff->setMulti(Array, 0)
#7 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(690): SqlBagOStuff->set('osewiki_db-wiki...', Array)
#8 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(428): MessageCache->saveToCaches(Array, 'all', 'en')
#9 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(350): MessageCache->loadFromDBWithLock('en', Array, NULL)
#10 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(991): MessageCache->load('en')
#11 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(921): MessageCache->getMsgFromNamespace('Pagetitle', 'en')
#12 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(888): MessageCache->getMessageForLang(Object(LanguageEn), 'pagetitle', true, Array)
#13 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(829): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'pagetitle', true)
#14 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(1275): MessageCache->get('pagetitle', true, Object(LanguageEn))
#15 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(842): Message->fetchMessage()
#16 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(934): Message->toString('text')
#17 /var/www/html/wiki.opensourceecology.org/htdocs/includes/OutputPage.php(950): Message->text()
#18 /var/www/html/wiki.opensourceecology.org/htdocs/includes/OutputPage.php(998): OutputPage->setHTMLTitle(Object(Message))
#19 /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/Article.php(463): OutputPage->setPageTitle('Maltfield Log')
#20 /var/www/html/wiki.opensourceecology.org/htdocs/includes/actions/ViewAction.php(68): Article->view()
#21 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(499): ViewAction->show()
#22 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(293): MediaWiki->performAction(Object(Article), Object(Title))
#23 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(861): MediaWiki->performRequest()
#24 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(523): MediaWiki->main()
#25 /var/www/html/wiki.opensourceecology.org/htdocs/index.php(43): MediaWiki->run()
#26 {main}
[DBPerformance] Expectation (writes <= 0) by MediaWiki::main not met (actual: 3):
query-m: DELETE FROM `wiki_objectcache` WHERE keyname = 'X'
#0 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/TransactionProfiler.php(219): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writes', 'query-m: DELETE...', 3)                                                                                                                                                                                
#1 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(1037): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: DELETE...', 1521165400.3392, true, 1)                                                                                                                                                                        
#2 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(937): Wikimedia\Rdbms\Database->doProfiledQuery('DELETE FROM `wi...', 'DELETE /* SqlBa...', true, 'SqlBagOStuff::d...')                                                                                                                                                                  
#3 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/rdbms/database/Database.php(2370): Wikimedia\Rdbms\Database->query('DELETE FROM `wi...', 'SqlBagOStuff::d...')
#4 /var/www/html/wiki.opensourceecology.org/htdocs/includes/objectcache/SqlBagOStuff.php(433): Wikimedia\Rdbms\Database->delete('objectcache', Array, 'SqlBagOStuff::d...')
#5 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php(447): SqlBagOStuff->delete('osewiki_db-wiki...')
#6 /var/www/html/wiki.opensourceecology.org/htdocs/includes/libs/objectcache/BagOStuff.php(485): BagOStuff->unlock('osewiki_db-wiki...')
#7 [internal function]: BagOStuff->{closure}()
#8 /var/www/html/wiki.opensourceecology.org/htdocs/vendor/wikimedia/scoped-callback/src/ScopedCallback.php(76): call_user_func_array(Object(Closure), Array)
#9 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(350): Wikimedia\ScopedCallback->__destruct()
#10 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(350): MessageCache->loadFromDBWithLock('en', Array, NULL)
#11 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(991): MessageCache->load('en')
#12 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(921): MessageCache->getMsgFromNamespace('Pagetitle', 'en')
#13 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(888): MessageCache->getMessageForLang(Object(LanguageEn), 'pagetitle', true, Array)
#14 /var/www/html/wiki.opensourceecology.org/htdocs/includes/cache/MessageCache.php(829): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'pagetitle', true)
#15 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(1275): MessageCache->get('pagetitle', true, Object(LanguageEn))
#16 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(842): Message->fetchMessage()
#17 /var/www/html/wiki.opensourceecology.org/htdocs/includes/Message.php(934): Message->toString('text')
#18 /var/www/html/wiki.opensourceecology.org/htdocs/includes/OutputPage.php(950): Message->text()
#19 /var/www/html/wiki.opensourceecology.org/htdocs/includes/OutputPage.php(998): OutputPage->setHTMLTitle(Object(Message))
#20 /var/www/html/wiki.opensourceecology.org/htdocs/includes/page/Article.php(463): OutputPage->setPageTitle('Maltfield Log')
#21 /var/www/html/wiki.opensourceecology.org/htdocs/includes/actions/ViewAction.php(68): Article->view()
#22 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(499): ViewAction->show()
#23 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(293): MediaWiki->performAction(Object(Article), Object(Title))
#24 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(861): MediaWiki->performRequest()
#25 /var/www/html/wiki.opensourceecology.org/htdocs/includes/MediaWiki.php(523): MediaWiki->main()
#26 /var/www/html/wiki.opensourceecology.org/htdocs/index.php(43): MediaWiki->run()
#27 {main}
[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is expired/volatile, loading from database
Unstubbing $wgParser on call of $wgParser::firstCallInit from MessageCache->getParser
Parser: using preprocessor: Preprocessor_DOM
Unstubbing $wgLang on call of $wgLang::_unstub from ParserOptions->__construct
[caches] parser: SqlBagOStuff
Article::view using parser cache: yes
Parser cache options found.
ParserOutput cache found.
Article::view: showing parser cache contents
MediaWiki::preOutputCommit: primary transaction round committed
MediaWiki::preOutputCommit: pre-send deferred updates completed
[cookie] setcookie: "cpPosTime", "1521165400.3692", "1521165460", "/", "", "1", "1"
[DBReplication] Wikimedia\Rdbms\ChronologyProtector::shutdownLB: DB 'localhost' touched

MediaWiki::preOutputCommit: LBFactory shutdown completed
Title::getRestrictionTypes: applicable restrictions to Maltfield Log are {edit,move}
OutputPage::haveCacheVaryCookies: no cache-varying cookies found
OutputPage::sendCacheControl: private caching; Fri, 16 Mar 2018 01:55:42 GMT **
Request ended normally
[session] Saving all sessions on shutdown
[DBConnection] Closing connection to database 'localhost'.
[DBConnection] Closing connection to database 'localhost'.

And here's the debug output when it *is* set to CACHE_NONE.

[DBReplication] Wikimedia\Rdbms\LBFactory::getChronologyProtector: using request info {
    "IPAddress": "127.0.0.1",
    "UserAgent": "curl\/7.29.0",
    "ChronologyProtection": "true"
}
IP: 127.0.0.1
Start request GET /wiki/Michael_Log
HTTP HEADERS:
X-REAL-IP: 138.201.84.223
X-FORWARDED-PROTO: https
X-FORWARDED-PORT: 443
HOST: wiki.opensourceecology.org
USER-AGENT: curl/7.29.0
ACCEPT: */*
X-FORWARDED-FOR: 127.0.0.1
ACCEPT-ENCODING: gzip
X-VARNISH: 146580
[caches] cluster: EmptyBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: EmptyBagOStuff, session: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreDB
[CryptRand] openssl_random_pseudo_bytes generated 20 bytes of strong randomness.
[CryptRand] 0 bytes of randomness leftover in the buffer.
[DBReplication] Wikimedia\Rdbms\LBFactory::getChronologyProtector: using request info {
    "IPAddress": "127.0.0.1",
    "UserAgent": "curl\/7.29.0",
    "ChronologyProtection": false
}
[DBConnection] Wikimedia\Rdbms\LoadBalancer::openConnection: calling initLB() before first connection.
[DBConnection] Connected to database 0 at 'localhost'.
[SQLBagOStuff] Connection 1064073 will be used for SqlBagOStuff
[session] SessionBackend "nhu5kl4t72jhuu3nfcus835sjgpdfpa0" is unsaved, marking dirty in constructor
[session] SessionBackend "nhu5kl4t72jhuu3nfcus835sjgpdfpa0" save: dataDirty=1 metaDirty=1 forcePersist=0
[cookie] already deleted setcookie: "osewiki_db_wiki__session", "", "1489629637", "/", "", "1", "1"
[cookie] already deleted setcookie: "osewiki_db_wiki_UserID", "", "1489629637", "/", "", "1", "1"
[cookie] already deleted setcookie: "osewiki_db_wiki_Token", "", "1489629637", "/", "", "1", "1"
[cookie] already deleted setcookie: "forceHTTPS", "", "1489629637", "/", "", "", "1"
[DBConnection] Connected to database 0 at 'localhost'.
Title::getRestrictionTypes: applicable restrictions to Michael Log are {edit,move}
[ContentHandler] Created handler for wikitext: WikitextContentHandler
Title::getRestrictionTypes: applicable restrictions to Maltfield Log are {edit,move}
OutputPage::checkLastModified: client did not send If-Modified-Since header
[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is empty, loading from database
Unstubbing $wgParser on call of $wgParser::firstCallInit from MessageCache->getParser
Parser: using preprocessor: Preprocessor_DOM
Unstubbing $wgLang on call of $wgLang::_unstub from ParserOptions->__construct
[caches] parser: SqlBagOStuff
Article::view using parser cache: yes
Parser cache options found.
ParserOutput cache found.
Article::view: showing parser cache contents
MediaWiki::preOutputCommit: primary transaction round committed
MediaWiki::preOutputCommit: pre-send deferred updates completed
MediaWiki::preOutputCommit: LBFactory shutdown completed
Title::getRestrictionTypes: applicable restrictions to Maltfield Log are {edit,move}
OutputPage::haveCacheVaryCookies: no cache-varying cookies found
OutputPage::haveCacheVaryCookies: no cache-varying cookies found
OutputPage::sendCacheControl: local proxy caching; Fri, 16 Mar 2018 01:58:47 GMT **
Request ended normally
[session] Saving all sessions on shutdown
[DBConnection] Closing connection to database 'localhost'.
[DBConnection] Closing connection to database 'localhost'.

Note the "[caches]" line that shows "message: EmptyBagOStuff" instead of "message: SqlBagOStuff"

Note that the "[MessageCache]" line is also different

# when it is *not* set to CACHE_NONE.
[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is expired/volatile, loading from database

# when it *is* set to CACHE_NONE.
[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is empty, loading from database

But the "[MessageCache]" line when it is *not* set to CACHE_NONE is preceded by a bunch of stack traces from "[DBPerformance]". This is absent when it *is* set to CACHE_NONE.

Please let me know if there's any more information I can provide for context. TIA!

This may be a bug.

The purpose of the "Expectation (writes <= 0)" is that GET requests don't write to the database. This is generally true, except when the database is used for the object cache, l10n cache and even sessions, which is a common setting on small wikis. To avoid database writes, caching should be configured to use redis or memcache.

That cookie is used by the "ChronologyProtection", a concept that has no documentation but I guess it's used to control reads from database slaves and prevent reading a slave that is lagging after a write to the database has been done.

Maybe the fact that database is used for cache is causing it to send cookies every time, something that shouldn't happen for cache writes from my understanding.

This may be worth opening a BUGREPORT, and CC Aaron Schultz if you open a bug about this :)

Thanks for the fast response :)

So are you saying that most wikis that utilize a varnish proxy for caching change the default behaviour of the built-in MediaWiki caches such that they do *not* use the DB for caching? What about the other caches (Main, MainStash, SessionCache)?

If so, this would be great to document in the Manual:Varnish_caching guide.

Also, I'm not sure we want to deploy a redis/memcache dependency. I'm debating between

 (a) configuring varnish to simply strip the Chronology Protection 'cpPosTime' cookie from the backend, causing varnish to cache responses where that cookie was present, but without the cookie present or

 (b) disabling the message cache

What would be the consequences of each?

I don't fully understand the use of the Chronology Protection, but I would expect the worst-case is that we end up caching a page that is slightly out-of-date. So maybe it could end up that a visitor that's not logged-in will see old versions of the page.

What are the consequences of the message cache being disabled entirely? If >90% of our queries are cache hits, I doubt this would be a significant performance loss. Or would it? There is no section on the Message Cache in Manual:Performance_tuning.

In case anyone else has this issue, I decided to use APCU for the message cache using the following line in LocalSettings.php

$wgMessageCacheType = CACHE_ACCEL;

The How to make MediawWiki fast article by Aaron Schulz and Manual:Performance_tuning helped me to come up with the following settings in LocalSettings.php

#################
# OPTIMIZATIONS #
#################

# See these links for more info:    
#  * https://www.mediawiki.org/wiki/Manual:Performance_tuning
#  * https://www.mediawiki.org/wiki/Manual:Caching
#  * https://www.mediawiki.org/wiki/User:Aaron_Schulz/How_to_make_MediaWiki_fast

# INTERNAL MEDIAWIKI CACHE OPTIONS (DISTINCT FROM VARNISH)

# MainCache and MessageCache should use APCU per Aaron Schulz
$wgMainCacheType = CACHE_ACCEL;

# note that if message cache uses the db (per defaults), then it may make every
# page load include a db change, which causes mediawiki to emmit a set-cookie
# for cpPosTime. The cookie's presence coming from the backend causes varnish
# not to cache the page (rightfully so), and the result is that varnish (which
# is our most important cache) is rendered useless. For more info, see:
#  * https://www.mediawiki.org/wiki/Topic:U9fys4phj04a85vu
#  * https://wiki.opensourceecology.org/wiki/Maltfield_log_2018#Thr_Mar_15.2C_2018
$wgMessageCacheType = CACHE_ACCEL;
$wgUseLocalMessageCache = true;

# Parser Cache should still use the DB per Aaron Schulz
$wgParserCacheType = CACHE_DB;

# enable caching navigation sidebar per Aaron Schulz
$wgEnableSidebarCache = true;

# cache interface messages to files in this directory per Aaron Schulz
# note that this should be outside the docroot!
$wgCacheDirectory = "$IP/../cache";

# OTHER OPTIMIZATIONS

# decrease db-heavy features per Aaron Schulz
$wgMiserMode = true;

# Causes serious encoding problems
$wgUseGzip = false;

Hi Maltfield,

After you set the $wgMessageCacheType = CACHE_ACCEL; , have you ever saw the following error message anymore?

[MessageCache] MessageCache::load: Loading en... local cache is empty, global cache is expired/volatile, loading from database

We tried to set $wgMessageCacheType to CACHE_ACCEL (with uAPC) or redis. But both of these two setting result-in same error message about.