- 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 Active 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
over 1 year 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
over 1 year 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.
- Merge request !9873Issue #3420372: Add development setting to enable mailer verbose logging β (Open) created by znerol
- π¨πSwitzerland znerol
znerol β changed the visibility of the branch 3420372-core-symfony-mailer to hidden.
- π¨πSwitzerland znerol
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 intoTransport::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.
- π¨πSwitzerland znerol
znerol β changed the visibility of the branch 3420372-add-mailer-development-setting to hidden.
- π¨πSwitzerland znerol
znerol β changed the visibility of the branch 11.x to hidden.
- π¨πSwitzerland znerol
znerol β changed the visibility of the branch 3420372-core-symfony-mailer to active.
- π¨πSwitzerland znerol
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.
- π¨πSwitzerland znerol
Adding Novice tag. I'm going to stick around for guidance and review.
- πΊπΈUnited States edward.radau
I haven't been able to reproduce this. Are there any more specific details as to the setup? So far running test SMTP messages using Symfony Mailer via SMTP transport have not generated errors.
- First commit to issue fork.
- Merge request !12828Issue #3420372 by znerol, m.stenta, mkdok, drubb: Core Symfony Mailer throws... β (Open) created by mkdok
- πΊπ¦Ukraine mkdok
The issue remains relevant in Drupal 11.1.8. I've opened a new MR request based on the suggested changes from @znerol
- π¨πSwitzerland znerol
znerol β changed the visibility of the branch 3420372-core-symfony-mailer to hidden.
- π¨πSwitzerland znerol
Thanks! You could remove the
public static create
method and adapt the constructor as well. This class is explicitly experimental and marked@internal
. No need to maintain backwards compatibility here. - πΊπΈUnited States smustgrave
Possible to get a test case or additional assertion to an existing test to show this fatal error?
- π¨πSwitzerland znerol
Update the steps to reproduce and did manual testing for the fix.
There are two things which are standing in the way for an automated test here:
- The repro requires the SMTP transport (because that is the only built-in transport which attempts to log anything during service destruction). The test systems tries very hard to make sure that no email is sent during automated tests.
- The error occurs extremely late in the request-response cycle. It errors when the response is already sent to the simpletest parent site, so we cannot use response headers to communicate it. And we cannot use the database to communicate back the result, because the database connection has been closed already as well. The only thing which could work would be to attempt to search the webserevr / php error log.
Attempting to write an end-to-end test for this case would most probably result in another complex, hard to debug and potentially random failing edge case test.
We are dealing with an experimental plugin here. I propose to either fix it with the proposed one liner or just close the issue as a won't fix.