setMiddlewares in Doctrine\DBAL\Configuration called after createConnection

[mrAndersen]

Trying to implement Doctrine\DBAL\Driver\Middleware i am getting some strange results:

1) I define my custom MyApp\Doctrine\Middleware\AppLoggingMiddleware implements Middleware 2) I define in services.yaml the following rule

services:
    _instanceof:
        Doctrine\DBAL\Driver\Middleware:
            tags: [ 'doctrine.middleware' ]

3) And i don't see any calls to wrap method inside my custom Middleware

Further debug shows that Doctrine\Bundle\DoctrineBundle\DependencyInjection\Compiler\MiddlewaresPass is instructing to call setMiddlewares after \Doctrine\Bundle\DoctrineBundle\ConnectionFactory::createConnection method is called, thus not wrapping the actual middleware, because createConnection is callingDriverManager::getConnection which in turn is calling $middleware->wrap($driver) on all existing middlewares which does not yet exist, because setMiddlewares is not yet called.

doctrine/doctrine-bundle is 2.6.2 doctrine/orm is 2.12.0 symfony/runtime is 6.0.7

This is what kind of container i am getting:

/**
     * Gets the public 'doctrine.dbal.default_connection' shared service.
     *
     * @return \Doctrine\DBAL\Connection
     */
    protected function getDoctrine_Dbal_DefaultConnectionService()
    {
        $a = new \Doctrine\DBAL\Configuration();

        $this->services['doctrine.dbal.default_connection'] = $instance = (new \Doctrine\Bundle\DoctrineBundle\ConnectionFactory($this->parameters['doctrine.dbal.connection_factory.types']))->createConnection(['url' => $this->getEnv('resolve:DATABASE_URL'), 'driver' => 'pdo_mysql', 'host' => 'localhost', 'port' => NULL, 'user' => 'root', 'password' => NULL, 'platform' => new \App\Doctrine\PostgreSQL130Platform(), 'driverOptions' => [], 'defaultTableOptions' => []], $a, new \Symfony\Bridge\Doctrine\ContainerAwareEventManager(new \Symfony\Component\DependencyInjection\Argument\ServiceLocator($this->getService, [
            'doctrine.orm.default_listeners.attach_entity_listeners' => ['privates', 'doctrine.orm.default_listeners.attach_entity_listeners', 'getDoctrine_Orm_DefaultListeners_AttachEntityListenersService', true],
            'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber' => ['privates', 'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber', 'getDoctrine_Orm_Listeners_DoctrineDbalCacheAdapterSchemaSubscriberService', true],
            'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber' => ['privates', 'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber', 'getDoctrine_Orm_Listeners_DoctrineTokenProviderSchemaSubscriberService', true],
            'doctrine.orm.messenger.doctrine_schema_subscriber' => ['privates', 'doctrine.orm.messenger.doctrine_schema_subscriber', 'getDoctrine_Orm_Messenger_DoctrineSchemaSubscriberService', true],
        ], [
            'doctrine.orm.default_listeners.attach_entity_listeners' => '?',
            'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber' => '?',
            'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber' => '?',
            'doctrine.orm.messenger.doctrine_schema_subscriber' => '?',
        ]), [0 => 'doctrine.orm.messenger.doctrine_schema_subscriber', 1 => 'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber', 2 => 'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber', 3 => [0 => [0 => 'loadClassMetadata'], 1 => 'doctrine.orm.default_listeners.attach_entity_listeners']]), []);
        $b = new \Symfony\Bridge\Monolog\Logger('doctrine');
        $b->pushHandler(($this->privates['monolog.handler.null_internal'] ?? ($this->privates['monolog.handler.null_internal'] = new \Monolog\Handler\NullHandler())));

        $a->setSQLLogger(new \Doctrine\DBAL\Logging\LoggerChain([0 => new \Symfony\Bridge\Doctrine\Logger\DbalLogger(NULL, ($this->privates['debug.stopwatch'] ?? ($this->privates['debug.stopwatch'] = new \Symfony\Component\Stopwatch\Stopwatch(true)))), 1 => new \Doctrine\DBAL\Logging\DebugStack()]));
        $a->setMiddlewares([0 => new \App\Doctrine\Middleware\AppLoggingMiddleware($instance), 1 => new \Doctrine\DBAL\Logging\Middleware($b)]);

        return $instance;
    }

[dmaicher]

I cannot reproduce this on my apps using Symfony 5.4.8. Are you able to provide a minimal reproducer?

[mrAndersen]

@dmaicher Here you go https://github.com/mrAndersen/doctrine-bundle-middleware-bug

You can pull repo, bin/console cache:clear and bin/console test, and you shall not see message left in App\Doctrine\Middleware\AppLoggingMiddleware, in addition to that you can navigate to var/cache and search there for setMiddleware call to ensure that it's made after actual connection is created and wrapped in Container***** classes

[dmaicher]

thanks for the reproducer @mrAndersen . Indeed something seems weird with the order of method calls :disappointed:

Not sure why though. I also tried downgrading to Symfony 5.4.* and its the same behavior. On my app the order is different and setMiddlewares is executed before the connection is created.

[mrAndersen]

@dmaicher Maybe the way i am telling the bundle to add my middleware is incorrect? Because unless the whole middleware mechanics should be broken...

[dmaicher]

In your case also the logging middleware is ineffective as its not set before the connection is created. I suspect this has something todo with the Symfony DI logic of resolving the dependency graph and the order of things? Not too sure.

Maybe @stof has an idea

[ostrolucky]

Issue here is that your middleware requires Connection. But for creating connection, middleware needs to be set... The only thing Symfony can do in this situation is to set middlewares after connection was created. But at that point it's too late in this case. I'm afraid this is a design of DBAL and there isn't anything we can do in bundle. So better please report issue there.

[dmaicher]

@ostrolucky I don't think this is a DBAL issue. The middlewares work fine.

The issue is that somehow the middlewares configured by DoctrineBundle are added too late to the Doctrine\DBAL\Configuration instance via setMiddlewares.

However this only happens for some apps/cases.

Correct order (this is the case on my apps):

1. create Doctrine\DBAL\Configuration instance $c
2. call setMiddlewares on $c
3. use $c for creating connection via ConnectionFactory

Wrong order as shown here and with the reproducer:

1. create Doctrine\DBAL\Configuration instance $c
2. use $c for creating connection via ConnectionFactory
3. call setMiddlewares on $c

So the middlewares are registered after the connection was created - which is too late.

So for me this is an issue with the Symfony DI configuration of this Bundle and order of calls or priority of things.

[ostrolucky]

It's impossible to instantiate these in correct order because of circular dependency. Look at this generated configuration

$a = new \Doctrine\DBAL\Configuration();

$container->services['doctrine.dbal.default_connection'] = $instance = (new \Doctrine\Bundle\DoctrineBundle\ConnectionFactory([]))->createConnection(['url' => $container->getEnv('resolve:DATABASE_URL'), 'driver' => 'pdo_mysql', 'host' => 'localhost', 'port' => NULL, 'user' => 'root', 'password' => NULL, 'driverOptions' => [], 'defaultTableOptions' => []], $a, new \Symfony\Bridge\Doctrine\ContainerAwareEventManager(new \Symfony\Component\DependencyInjection\Argument\ServiceLocator($container->getService, [
    'doctrine.orm.default_listeners.attach_entity_listeners' => ['privates', 'doctrine.orm.default_listeners.attach_entity_listeners', 'getDoctrine_Orm_DefaultListeners_AttachEntityListenersService', true],
    'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber' => ['privates', 'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber', 'getDoctrine_Orm_Listeners_DoctrineDbalCacheAdapterSchemaSubscriberService', true],
    'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber' => ['privates', 'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber', 'getDoctrine_Orm_Listeners_DoctrineTokenProviderSchemaSubscriberService', true],
], [
    'doctrine.orm.default_listeners.attach_entity_listeners' => '?',
    'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber' => '?',
    'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber' => '?',
]), [0 => 'doctrine.orm.listeners.doctrine_dbal_cache_adapter_schema_subscriber', 1 => 'doctrine.orm.listeners.doctrine_token_provider_schema_subscriber', 2 => [0 => [0 => 'loadClassMetadata'], 1 => 'doctrine.orm.default_listeners.attach_entity_listeners']]), []);
$b = new \Symfony\Bridge\Monolog\Logger('doctrine');
$b->pushHandler(($container->privates['monolog.handler.main'] ?? $container->getMonolog_Handler_MainService()));

$a->setSQLLogger(new \Doctrine\DBAL\Logging\LoggerChain([0 => new \Symfony\Bridge\Doctrine\Logger\DbalLogger(NULL, NULL), 1 => new \Doctrine\DBAL\Logging\DebugStack()]));
$a->setMiddlewares([0 => new \App\Doctrine\Middleware\AppLoggingMiddleware($instance), 1 => new \Doctrine\DBAL\Logging\Middleware($b)]);

return $instance;

How would you fix the order to make this work? $instance is created via createConnection method. This method requres $a. Middlewares are set in $a. One of the middlewares requires $instance.

[dmaicher]

Ah sorry I totally missed this circular dependency. This indeed cannot work.

Wondering if we should somehow fail container compilation in this case? 🤔

[ostrolucky]

Yes that would make sense I think

[mrAndersen]

If container compilation will be failed in this case, how middlewares and connection middlewares in particular should be used at the first place ? :)

[dmaicher]

@mrAndersen your use-case is impossible by design. You cannot have a middleware that has a dependency on the connection. That's a "chicken and egg problem". The middlewares are used to create the connection.

[mrAndersen]

@dmaicher ok, so how i should implement old SqlLogger mechanics (for example) - to be able to log each subsequent sql query and their execution time with new middleware logic? As long as i understood from new doc i should wrap Connection by creating middleware accordingly, which I've done in reproducer repo. This was the original problem, and as far as i understood, middleware logic was implemented to have more control over doctrine, not being able to wrap Connection seems strange in this case...

[dmaicher]

See for example https://github.com/doctrine/dbal/blob/3.3.x/src/Logging/Middleware.php#L23

https://github.com/doctrine/dbal/blob/3.3.x/src/Logging/Driver.php#L33

You can add a middleware, your own driver and your own connection decorator for example.

[mrAndersen]

@dmaicher thx!