Core Symfony Mailer throws error on transport shutdown

At first glance this looks similar to 🐛 Transaction autocommit during shutdown relies on unreliable object destruction order (xdebug 3.3+ enabled) Needs review where things happen in __destruct() but the order of destruction is not guaranteed, so the database connection might have been closed before the transport is shut down.

Had a quick test: with xdebug disabled, it also happens. The error message is a bit shorter:

Fatal error: Uncaught TypeError: Drupal\Core\Database\StatementWrapperIterator::__construct(): Argument #2 ($clientConnection) must be of type object, null given, called in /app/web/core/lib/Drupal/Core/Database/Connection.php on line 557 and defined in /app/web/core/lib/Drupal/Core/Database/StatementWrapperIterator.php:54 Stack trace: #0 /app/web/core/lib/Drupal/Core/Database/Connection.php(557): Drupal\Core\Database\StatementWrapperIterator->__construct(Object(Drupal\mysql\Driver\Database\mysql\Connection), NULL, 'INSERT INTO "wa...', Array, false) #1 /app/web/core/modules/mysql/src/Driver/Database/mysql/Insert.php(42): Drupal\Core\Database\Connection->prepareStatement('INSERT INTO "wa...', Array) #2 /app/web/core/modules/dblog/src/Logger/DbLog.php(78): Drupal\mysql\Driver\Database\mysql\Insert->execute() #3 /app/web/core/lib/Drupal/Core/Logger/LoggerChannel.php(127): Drupal\dblog\Logger\DbLog->log(7, 'Email transport...', Array) #4 /app/vendor/psr/log/src/LoggerTrait.php(127): Drupal\Core\Logger\LoggerChannel->log(7, 'Email transport...', Array) #5 /app/vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(297): Drupal\Core\Logger\LoggerChannel->debug('Email transport...') #6 /app/vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(390): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport->stop() #7 [internal function]: Symfony\Component\Mailer\Transport\Smtp\SmtpTransport->__destruct() #8 {main} thrown in /app/web/core/lib/Drupal/Core/Database/StatementWrapperIterator.php on line 54

This is how the connection object looks in DbLog.php, right before the insert statement:

Drupal\mysql\Driver\Database\mysql\Connection Object
(
    [target:protected] => default
    [key:protected] => default
    [logger:protected] => 
    [transactionLayers:protected] => Array
        (
        )

    [driverClasses:protected] => Array
        (
        )

    [statementWrapperClass:protected] => Drupal\Core\Database\StatementWrapperIterator
    [transactionalDDLSupport:protected] => 
    [connection:protected] => 
    [connectionOptions:protected] => Array
        (
            [database] => drupal10
            [username] => drupal10
            [password] => drupal10
            [prefix] => 
            [host] => database
            [port] => 3306
            [namespace] => Drupal\mysql\Driver\Database\mysql
            [driver] => mysql
            [init_commands] => Array
                (
                    [isolation_level] => SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED
                    [sql_mode] => SET sql_mode = 'ANSI,TRADITIONAL'
                )

            [autoload] => core/modules/mysql/src/Driver/Database/mysql/
            [pdo] => Array
                (
                    [3] => 2
                    [1000] => 1
                    [1005] => 1
                    [20] => 1
                    [1013] => 
                    [17] => 1
                )

        )

    [schema:protected] => 
    [prefix:protected] => 
    [tablePlaceholderReplacements:protected] => Array
        (
            [0] => "
            [1] => "
        )

    [prefixes:protected] => Array
        (
        )

    [prefixSearch:protected] => Array
        (
        )

    [prefixReplace:protected] => Array
        (
        )

    [unprefixedTablesMap:protected] => Array
        (
        )

    [escapedTables:protected] => Array
        (
            [config] => config
            [key_value] => key_value
            [key_value_expire] => key_value_expire
            [path_alias] => path_alias
            [config_pages] => config_pages
            [crop_field_data] => crop_field_data
            [menu_tree] => menu_tree
            [sessions] => sessions
            [users_field_data] => users_field_data
        )

    [escapedFields:protected] => Array
        (
            [] => 
            [collection] => "collection"
            [name] => "name"
            [config.name] => "config"."name"
            [uid] => "uid"
            [type] => "type"
            [message] => "message"
            [variables] => "variables"
            [severity] => "severity"
            [link] => "link"
            [location] => "location"
            [referer] => "referer"
            [hostname] => "hostname"
            [timestamp] => "timestamp"
            [base_table.status] => "base_table"."status"
            [base_table.path] => "base_table"."path"
            [base_table.langcode] => "base_table"."langcode"
            [base_table.alias] => "base_table"."alias"
            [base_table.id] => "base_table"."id"
            [config_pages.type] => "config_pages"."type"
            [config_pages.context] => "config_pages"."context"
            [cfd.uri] => "cfd"."uri"
            [cfd.type] => "cfd"."type"
            [cfd.cid] => "cfd"."cid"
            [menu_name] => "menu_name"
            [expanded] => "expanded"
            [has_children] => "has_children"
            [enabled] => "enabled"
            [parent] => "parent"
            [id] => "id"
            [menu_tree.id] => "menu_tree"."id"
            [sid] => "sid"
            [session] => "session"
            [access] => "access"
        )

    [escapedAliases:protected] => Array
        (
            [name] => "name"
            [config] => "config"
            [path] => "path"
            [alias] => "alias"
            [base_table] => "base_table"
            [id] => "id"
            [langcode] => "langcode"
            [base_table_id] => "base_table_id"
            [config_pages] => "config_pages"
            [type] => "type"
            [cid] => "cid"
            [cfd] => "cfd"
            [menu_tree] => "menu_tree"
            [expression] => "expression"
            [sessions] => "sessions"
        )

    [rootTransactionEndCallbacks:protected] => Array
        (
        )

    [identifierQuotes:protected] => Array
        (
            [0] => "
            [1] => "
        )

    [enabledEvents:Drupal\Core\Database\Connection:private] => Array
        (
        )

    [transactionManager:protected] => Drupal\mysql\Driver\Database\mysql\TransactionManager Object
        (
            [stack:Drupal\Core\Database\Transaction\TransactionManagerBase:private] => Array
                (
                )

            [voidedItems:Drupal\Core\Database\Transaction\TransactionManagerBase:private] => Array
                (
                )

            [postTransactionCallbacks:Drupal\Core\Database\Transaction\TransactionManagerBase:private] => Array
                (
                )

            [connection:protected] => Drupal\mysql\Driver\Database\mysql\Connection Object
 *RECURSION*
        )

    [needsCleanup:protected] => 
    [serverVersion:Drupal\mysql\Driver\Database\mysql\Connection:private] => 
)

The stack trace in PhpStorm starts with the __destruct function of SmtpTransport.php, there the connection seems to be missing already:

DbLog.php:61, Drupal\dblog\Logger\DbLog->log()
LoggerChannel.php:127, Drupal\Core\Logger\LoggerChannel->log()
LoggerTrait.php:127, Drupal\Core\Logger\LoggerChannel->debug()
SmtpTransport.php:297, Symfony\Component\Mailer\Transport\Smtp\SmtpTransport->stop()
SmtpTransport.php:390, Symfony\Component\Mailer\Transport\Smtp\SmtpTransport->__destruct()


I'm seeing the same issue. Without XDebug this can be reproduced by using a drush command to send an email. The database connection is gone before the symfony mailer destructor.

It seems that the symfony mail logging is a bit too verbose anyways. By turning that off, the issue may be gone?

This was my thought, too. However, I have no idea how to do this. Logging is part of the smtp mail transport class of Symfony Mailer, not done in Drupal. This class has a constructor where it initializes a logger, at that time with the correct database connection. One might be able to patch it, but...

Logging the transport stop is done in the destructor of the same class, at this point the logger property is missing the database connection (null).

The destructor calls a stop() method, where logging is done (and fails).

Here's a workaround I'm using now to disable logging and thus prevent errors:

      $email
        ->to($message['to'])
        ->subject($message['subject'])
        ->html($message['html'])
        ->text($message['body']);

      // Disable logging, it's verbose and throws exceptions
      // on transport shutdown.
      $this->logger = new NullLogger();
      $this->getMailer()->send($email);
      return TRUE;
    } catch (\Exception|TransportExceptionInterface $e) {
      return FALSE;
    }

Indeed. The log messages produced by the symfony mailer component are useless for most production setups.

% grep -i 'log[^- ]*->' -r vendor/symfony/mailer
vendor/symfony/mailer/DataCollector/MessageDataCollector.php:        $this->events = $logger->getEvents();
vendor/symfony/mailer/Transport/AbstractTransport.php:            $this->logger->debug(sprintf('Email transport "%s" sleeps for %.2f seconds', __CLASS__, $sleep));
vendor/symfony/mailer/Transport/SendmailTransport.php:        $this->getLogger()->debug(sprintf('Email transport "%s" starting', __CLASS__));
vendor/symfony/mailer/Transport/SendmailTransport.php:        $this->getLogger()->debug(sprintf('Email transport "%s" stopped', __CLASS__));
vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:                $this->getLogger()->debug(sprintf('Email transport "%s" stopped', __CLASS__));
vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:        $this->getLogger()->debug(sprintf('Email transport "%s" starting', __CLASS__));
vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:        $this->getLogger()->debug(sprintf('Email transport "%s" started', __CLASS__));
vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:        $this->getLogger()->debug(sprintf('Email transport "%s" stopping', __CLASS__));
vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:            $this->getLogger()->debug(sprintf('Email transport "%s" stopped', __CLASS__));
vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:            $this->getLogger()->debug(sprintf('Email transport "%s" sleeps for %d seconds after stopping', __CLASS__, $sleep));

Also, symfony docs recommend to use event subscribers and the getDebug() method in order to gather useful information.

I am experiencing the same issue when an email is sent via Drush. With or without XDebug.

Notably, I am not seeing any errors in Apache logs when I test the password reset form via /user/password in the browser. So it seems that only Drush is affected?

Here's a workaround I'm using now to disable logging and thus prevent errors:

@drubb Where are you implementing this workaround?

In my case, I'm trying to send an email from a custom Drush command, which is using the plugin.manager.mail service's mail() method, along with a hook_mail() implementation that builds the subject, body, etc.

You appear to be doing something different, so I'm curious to understand your context a bit better in hopes that I can replicate the workaround in mine.

Notably, I am not seeing any errors in Apache logs when I test the password reset form via /user/password in the browser. So it seems that only Drush is affected?

Correction: I *am* seeing errors in Apache logs for /user/password (without Xdebug).

@drubb Where are you implementing this workaround?

Nevermind I found it. :-)

I started a draft MR with this change. Also attaching a patch for use with cweagans/composer-patches.

I think it would be nice to have this configurable in a similar manner as twig debugging (see ✨ Make it easier for theme builders to enable Twig debugging and disable render cache Fixed and 📌 Move twig_debug and other development toggles into raw key/value Fixed ).

Note that with 📌 [PP-1] Add symfony mailer transports to DIC Postponed , mailer related services will be registered in the container. Since $logger is supposed to be injected into transports (via transport factories), I think that a compiler pass based approach is sensible here.

Thanks for reporting and working on this issue

Believe we will need test coverage for this change.

Also believe the failures are unrelated and may just need a rebase.

Implemented approach in #16. The new setting is off by default.

znerol → changed the visibility of the branch 3420372-core-symfony-mailer to hidden.

Some manual testing led me to conclude that the debug messages aren't of any use, not even in development mode. Exposing a switch in the UI is overkill. Hence, I think it is better to simply remove the logger argument from the call into Transport::getDefaultFactories().

I found another place where we do the same (i.e., not passing the logger into a symfony component):

See the service definition for the Symfony router_listener, especially the last argument:

  router_listener:
    class: Symfony\Component\HttpKernel\EventListener\RouterListener
    arguments: ['@router', '@request_stack', '@router.request_context', NULL]

Setting this to needs work. I hope that somebody will find the time to adapt the original PR, I'll stick around for rewiews.

znerol → changed the visibility of the branch 3420372-add-mailer-development-setting to hidden.

znerol → changed the visibility of the branch 11.x to hidden.

znerol → changed the visibility of the branch 3420372-core-symfony-mailer to active.

I'm tentatively removing the needs test tag here. In order to reliably cover that corner case we'd need to add an end-to-end test which successfully sends an email message over SMTP and then asserts that there were no errors after service destruction. This is neither possible with unit tests nor with kernel tests.

Given that we are dealing with an experimental plugin here, I'd say that we can save ourselves the effort to add a test for this.