Page MenuHomePhabricator

Wikibase composer modules breaks LoggerFactory configurations when merged into mediawiki/core composer.json
Closed, ResolvedPublic

Description

I discovered this, when I worked in switching my wiki from the default, file-based logging, to Monolog loggers (my wiki uses Wikibase). So, I thought I "simply" configure $wgMWLoggerDefaultSpi in my LocalSettings.php, and let the logs be redirected to redis (which then is read by logstash and visualized in kibana, at least that's my plan). This resulted in the following configuration (based on the example on-wiki):

$wgMWLoggerDefaultSpi = array(
    'class' => '\\MediaWiki\\Logger\\MonologSpi',
    'args' => array( array(
        'loggers' => array(
            '@default' => array(
                'processors' => array( 'wiki', 'psr', 'pid', 'uid', 'web' ),
                'handlers'   => array( 'default', 'redis' ),
            ),
            'wfDebug' => array(
                'handlers'   => array( 'default' ),
                'processors' => array( 'psr' ),
            ),
            'profileoutput' => array(
                'handlers'   => array( 'profiler' ),
                'processors' => array( 'psr' ),
            ),
        ),

        'processors' => array(
            'wiki' => array(
                'class' => '\\MediaWiki\\Logger\\Monolog\\WikiProcessor',
            ),
            'psr' => array(
                'class' => '\\Monolog\\Processor\\PsrLogMessageProcessor',
            ),
            'pid' => array(
                'class' => '\\Monolog\\Processor\\ProcessIdProcessor',
            ),
            'uid' => array(
                'class' => '\\Monolog\\Processor\\UidProcessor',
            ),
            'web' => array(
                'class' => '\\Monolog\\Processor\\WebProcessor',
            ),
        ),

        'handlers' => array(
            'default' => array(
                'class' => '\\MediaWiki\\Logger\\Monolog\\LegacyHandler',
                'args' => array( '/data/www/mediawiki-log/monolog-'.date('Ymd').'.log' ),
                'formatter' => 'line',
            ),
            'redis' => array(
                'class' => '\\Monolog\\Handler\\RedisHandler',
                'args' => array(
                    function() {
                        $redis = new Redis();
                        $redis->connect( '127.0.0.1', 6379 );
                        return $redis;
                    },
                    'logstash'
                ),
                'formatter' => 'logstash',
            ),
            'profiler' => array(
                'class' => '\\MediaWiki\\Logger\\Monolog\\LegacyHandler',
                'args' => array( '/data/www/mediawiki-log/profiler-'.date('Ymd').'.log' ),
                'formatter' => 'profiler',
            ),
        ),

        'formatters' => array(
            'line' => array(
                'class' => '\\Monolog\\Formatter\\LineFormatter',
            ),
            'logstash' => array(
                'class' => '\\Monolog\\Formatter\\LogstashFormatter',
                'args'  => array( 'mediawiki', php_uname( 'n' ), null, '', 1 ),
            ),
            'profiler' => array(
                'class' => '\\Monolog\\Formatter\\LineFormatter',
                'args' => array( "%datetime% %message%\n\n", null, true, true ),
            ),
        ),
    ) ),
);

After setting the $wgMWLoggerDefaultSpi config variable, I recognized, that no data is sent to logstash, and even not to redis (which I checked after that).

After some time, I checked, if my configuration is applied by putting the following code directly after the assignment of the $wgMWLoggerDefaultSpi variable:

$logger = LoggerFactory::getInstance( 'test' );
var_dump( get_class( $logger ) );
exit;

And I got the output, that the LegacyLogger is returned by the LoggerFactory, which shouldn't happen if the configuration above is applied. So, after checking, that I used the correct global variable (twice) I checked, when getInstance() of LoggerFactory is called the first time by adding a debug_print_backtrace() call to the method, and I got the following output:

#0 MediaWiki\Logger\LoggerFactory::getProvider() called at [/data/mediawiki/main/includes/debug/logger/LoggerFactory.php:97] 
#1 MediaWiki\Logger\LoggerFactory::getInstance(objectcache) called at [/data/mediawiki/main/includes/objectcache/ObjectCache.php:175] 
#2 ObjectCache::newFromParams(Array) called at [/data/mediawiki/main/includes/ServiceWiring.php:336] 
#3 Closure$
#34(Object of class MediaWiki\MediaWikiServices could not be converted to string) 
#4 call_user_func_array(Object of class Closure$
#34;2111707029$8f1050010a79dba3428a504eb49b3b82$ could not be converted to string, Array) called at [/data/mediawiki/main/includes/services/ServiceContainer.php:361] 
#5 MediaWiki\Services\ServiceContainer->createService(LocalServerObjectCache) called at [/data/mediawiki/main/includes/services/ServiceContainer.php:344] 
#6 MediaWiki\Services\ServiceContainer->getService(LocalServerObjectCache) called at [/data/mediawiki/main/includes/MediaWikiServices.php:648] 
#7 MediaWiki\MediaWikiServices->getLocalServerObjectCache() called at [/data/mediawiki/main/includes/registration/ExtensionRegistry.php:90] 
#8 ExtensionRegistry->__construct() called at [/data/mediawiki/main/includes/registration/ExtensionRegistry.php:80] 
#9 ExtensionRegistry::getInstance() called at [/data/mediawiki/main/includes/GlobalFunctions.php:116] 
#10 wfLoadExtension(WikibaseDataModel, /data/mediawiki/main/vendor/wikibase/data-model/mediawiki-extension.json) called at [/data/mediawiki/main/vendor/wikibase/data-model/WikibaseDataModel.php:13] 
#11 include(/data/mediawiki/main/vendor/wikibase/data-model/WikibaseDataModel.php) called at [/data/mediawiki/main/vendor/composer/autoload_real.php:70] 
#12 composerRequire207f40de2cbb0083fd2081ddb0bacdd9(dc2c047038b9f5c71759f55f00aba99b, /data/mediawiki/main/vendor/wikibase/data-model/WikibaseDataModel.php) called at [/data/mediawiki/main/vendor/composer/autoload_real.php:60] 
#13 ComposerAutoloaderInit207f40de2cbb0083fd2081ddb0bacdd9::getLoader() called at [/data/mediawiki/main/vendor/autoload.php:7] 
#14 include(/data/mediawiki/main/vendor/autoload.php) called at [/data/mediawiki/main/includes/WebStart.php:86] 
#15 include(/data/mediawiki/main/includes/WebStart.php) called at [/data/mediawiki/main/index.php:40]

So, the Wikibase modules, which (in my setup) are loaded into the MediaWiki vendor directory (by merging all extension composer.json files into the main mediawiki core one, so I've to use composer update only once), uses wfLoadExtension to load itself. This, on its own, shouldn't be a problem. However, the MediaWiki composer autoloader is loaded before the LocalSettings.php is included in WebStart.php. That means, that any code, which is called in the composer autoloader files, is executed with the default configuration of MediaWiki. All objects, which uses singletons (e.g. LoggerFactory) then caches the objects and later calls get objects which are initialized with the MediaWiki default configuration.

I'm not sure, if this is a bug in mediawiki/core, in the Wikibase data-model modules (it's not just this one mentioned in the stack trace, it's just the first one) or if my setup isn't supported in this way (especially merging all extension composer.jsons into the mediawiki/core one:

"extra": {
        "merge-plugin": {
                "include": [
                        "extensions/*/composer.json"
                ]
        }
}

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

However, the MediaWiki composer autoloader is loaded before the LocalSettings.php is included in WebStart.php.

Before someone starts messing with the loading order [0], we (SMW) rely on that order to make sure PSR-4 is loaded before any LocalSettings have access to a possible referenced class or function.

[0] https://github.com/wikimedia/mediawiki/commit/b1c73fc670461c2e8ac5e64edb1e450e8873b189#diff-646df86dc8b6d449f3042f2ed4a18b76

Right, we can't change the initialization order because we need the composer dependencies to be available before LocalSettings.php runs.

Side-note: I wonder if rMWa6f172ef3cce: registration: Don't initialize MWServices super early made any difference since part of the problem in the stack trace looks like MWServices is getting initialized early...

Florian assigned this task to Legoktm.

@Legoktm: Thanks for pointing me to this commit! :) I first reproduced the problem locally (like explained in the task description). After it, I checked out master and tested it again. It seemed to work pretty fine (at least the expected logger class was returned: Monolog\Logger). I reverted a6f172ef3cce locally and checked again. At this time I got the MediaWiki\Logger\LegacyLogger logger class. So, it seems, that this commit fixed this bug, too. It's probably not the best solution, but I'm totally fine with it! Thanks @Legoktm :)