- Issue created by @drubb
- π¬π§United Kingdom longwave UK
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. - π©πͺGermany drubb Sindelfingen
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
- π©πͺGermany drubb Sindelfingen
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] => )
- π©πͺGermany drubb Sindelfingen
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()
- π©πͺGermany jurgenhaas Gottmadingen
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?
- π©πͺGermany drubb Sindelfingen
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).
- π©πͺGermany drubb Sindelfingen
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; }
- π¨πSwitzerland znerol
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. - πΊπΈUnited States m.stenta
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'smail()
method, along with ahook_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.
- πΊπΈUnited States m.stenta
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).
- Status changed to Needs review
4 months ago 11:24am 9 May 2024 - πΊπΈUnited States m.stenta
@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
. - Merge request !8002Issue #3420372 by drubb, longwave, m.stenta, jurgenhaas: Core Symfony Mailer... β (Open) created by m.stenta
- π¨πSwitzerland znerol
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. - Status changed to Needs work
4 months ago 12:29pm 10 May 2024 - πΊπΈUnited States smustgrave
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.