Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sendmail transport throwing unneccessary exceptions on worker restart #54532

Closed
bobvandevijver opened this issue Apr 9, 2024 · 5 comments
Closed

Comments

@bobvandevijver
Copy link
Contributor

Symfony version(s) affected

7.0.6, 6.4.6, 5.4.38

Description

Due to bugfix #54239 the sendmail transport is now throwing an unnecessary exception on messenger worker exit when used in combination with the -bs option (which is the default), where the sendmail process stream is actually being wrapped with an SMTP transport instance.

This option causes Exim to accept one or more messages by reading SMTP commands on the standard input, and producing SMTP replies on the standard output. SMTP policy controls, as defined in ACLs are applied. Some user agents use this interface as a way of passing locally-generated messages to the MTA.

When used together with the SMTP transport the sendmail process is kept running in the background, and will at some time (depending on server configuration, default 5 minutes for Exim) output an SMTP command timeout. This is normally handled by the SMTP transport when a new message needs to be send, which automatically restarts the transport when necessary (although I haven't been able to verify what happens with the #54239). Instead, it will trigger an exception on worker exit for something that is not necessary.

How to reproduce

  1. Send an email with a worker using the Sendmail transport
  2. Wait until timeout is logged by Exim
  3. Stop the worker and see the exception being logged

Possible Solution

Wrapping the terminate lines for the embedded streams might be enough, but might also have unintended side effects I am not aware of as the stream is a common process stream.

Additional Context

Messenger log:

Apr 09 10:58:27 webdev83 php[7303]: 10:58:27 INFO      [messenger] Stopping worker. ["transport_names" => ["async"]]
Apr 09 10:58:27 webdev83 php[7303]: 10:58:27 INFO      [messenger] Worker stopped due to time limit of 3600s exceeded ["timeLimit" => 3600]
Apr 09 10:58:28 webdev83 php[7303]: Symfony\Component\Mailer\Exception\TransportException {#896
Apr 09 10:58:28 webdev83 php[7303]:   #message: "Process failed with exit code 1: 421 hostname.dev: SMTP command timeout - closing connection\r\n"
Apr 09 10:58:28 webdev83 php[7303]:   #code: 0
Apr 09 10:58:28 webdev83 php[7303]:   #file: "/var/www/project/vendor/symfony/mailer/Transport/Smtp/Stream/ProcessStream.php"
Apr 09 10:58:28 webdev83 php[7303]:   #line: 60
Apr 09 10:58:28 webdev83 php[7303]:   -debug: ""
Apr 09 10:58:28 webdev83 php[7303]:   trace: {
Apr 09 10:58:28 webdev83 php[7303]:     /var/www/project/vendor/symfony/mailer/Transport/Smtp/Stream/ProcessStream.php:60 { …}
Apr 09 10:58:28 webdev83 php[7303]:     /var/www/project/vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:303 { …}
Apr 09 10:58:28 webdev83 php[7303]:     /var/www/project/vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php:390 { …}
Apr 09 10:58:28 webdev83 php[7303]:     Symfony\Component\Mailer\Transport\Smtp\SmtpTransport->__destruct() {}
Apr 09 10:58:28 webdev83 php[7303]:   }
Apr 09 10:58:28 webdev83 php[7303]: }

Exim log:

2024-04-09 10:14:01 1ru6cD-0002Jy-1e <= email@somewhere.nl U=www-data P=local-smtp S=953 id=9c6306db5ac4e3d3d2ab7a7fed5bb55d@somewhere.nl
2024-04-09 10:14:05 1ru6cD-0002Jy-1e Completed
2024-04-09 10:19:01 SMTP command timeout on connection from www-data
@bobvandevijver
Copy link
Contributor Author

So, this seems to be a bit more broken than only on worker exit. When the worker is still running when having received an SMTP timeout, but needs to send a new email, it will now throw invalid stream resource errors. I assume this is because the stream is no longer being set to null when the initial exception occurs when the worker tries to restart the process as it had received the timeout.

TypeError: fwrite(): supplied resource is not a valid stream resource
#30 /vendor/symfony/mailer/Transport/Smtp/Stream/AbstractStream.php(48): fwrite
#29 /vendor/symfony/mailer/Transport/Smtp/Stream/AbstractStream.php(48): Symfony\Component\Mailer\Transport\Smtp\Stream\AbstractStream::write
#28 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(195): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::executeCommand
#27 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(316): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::ping
#26 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(205): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::doSend
#25 /vendor/symfony/mailer/Transport/AbstractTransport.php(90): Symfony\Component\Mailer\Transport\AbstractTransport::send
#24 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(137): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::send
#23 /vendor/symfony/mailer/Transport/SendmailTransport.php(74): Symfony\Component\Mailer\Transport\SendmailTransport::send
#22 /vendor/drenso/symfony-shared/src/Email/EmailService.php(51): Drenso\Shared\Email\EmailService::sendDirectly
#21 /src/MessageHandler/MailSaleReceiptHandler.php(65): App\MessageHandler\MailSaleReceiptHandler::__invoke
#20 /vendor/symfony/messenger/Middleware/HandleMessageMiddleware.php(152): Symfony\Component\Messenger\Middleware\HandleMessageMiddleware::callHandler
#19 /vendor/symfony/messenger/Middleware/HandleMessageMiddleware.php(91): Symfony\Component\Messenger\Middleware\HandleMessageMiddleware::handle
#18 /vendor/symfony/messenger/Middleware/SendMessageMiddleware.php(71): Symfony\Component\Messenger\Middleware\SendMessageMiddleware::handle
#17 /vendor/symfony/messenger/Middleware/FailedMessageProcessingMiddleware.php(34): Symfony\Component\Messenger\Middleware\FailedMessageProcessingMiddleware::handle
#16 /vendor/symfony/messenger/Middleware/DispatchAfterCurrentBusMiddleware.php(68): Symfony\Component\Messenger\Middleware\DispatchAfterCurrentBusMiddleware::handle
#15 /vendor/symfony/messenger/Middleware/RejectRedeliveredMessageMiddleware.php(41): Symfony\Component\Messenger\Middleware\RejectRedeliveredMessageMiddleware::handle
#14 /vendor/symfony/messenger/Middleware/AddBusNameStampMiddleware.php(37): Symfony\Component\Messenger\Middleware\AddBusNameStampMiddleware::handle
#13 /vendor/symfony/messenger/MessageBus.php(70): Symfony\Component\Messenger\MessageBus::dispatch
#12 /vendor/symfony/messenger/RoutableMessageBus.php(54): Symfony\Component\Messenger\RoutableMessageBus::dispatch
#11 /vendor/symfony/messenger/Worker.php(162): Symfony\Component\Messenger\Worker::handleMessage
#10 /vendor/symfony/messenger/Worker.php(109): Symfony\Component\Messenger\Worker::run
#9 /vendor/symfony/messenger/Command/ConsumeMessagesCommand.php(238): Symfony\Component\Messenger\Command\ConsumeMessagesCommand::execute
#8 /vendor/symfony/console/Command/Command.php(326): Symfony\Component\Console\Command\Command::run
#7 /vendor/symfony/console/Application.php(1096): Symfony\Component\Console\Application::doRunCommand
#6 /vendor/symfony/framework-bundle/Console/Application.php(126): Symfony\Bundle\FrameworkBundle\Console\Application::doRunCommand
#5 /vendor/symfony/console/Application.php(324): Symfony\Component\Console\Application::doRun
#4 /vendor/symfony/framework-bundle/Console/Application.php(80): Symfony\Bundle\FrameworkBundle\Console\Application::doRun
#3 /vendor/symfony/console/Application.php(175): Symfony\Component\Console\Application::run
#2 /vendor/symfony/runtime/Runner/Symfony/ConsoleApplicationRunner.php(49): Symfony\Component\Runtime\Runner\Symfony\ConsoleApplicationRunner::run
#1 /vendor/autoload_runtime.php(29): require_once
#0 /bin/console(15): null

When trying to restart the worker when this happens, another error is thrown.

TypeError: fwrite(): supplied resource is not a valid stream resource
#5 /vendor/symfony/mailer/Transport/Smtp/Stream/AbstractStream.php(48): fwrite
#4 /vendor/symfony/mailer/Transport/Smtp/Stream/AbstractStream.php(48): Symfony\Component\Mailer\Transport\Smtp\Stream\AbstractStream::write
#3 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(195): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::executeCommand
#2 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(300): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::stop
#1 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(390): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::__destruct
#0 [internal](0): null

TypeError: fclose(): supplied resource is not a valid stream resource
#4 /vendor/symfony/mailer/Transport/Smtp/Stream/ProcessStream.php(54): fclose
#3 /vendor/symfony/mailer/Transport/Smtp/Stream/ProcessStream.php(54): Symfony\Component\Mailer\Transport\Smtp\Stream\ProcessStream::terminate
#2 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(303): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::stop
#1 /vendor/symfony/mailer/Transport/Smtp/SmtpTransport.php(390): Symfony\Component\Mailer\Transport\Smtp\SmtpTransport::__destruct
#0 [internal](0): null

@lazka
Copy link

lazka commented Apr 22, 2024

We are seeing some emails not being send out recently and lots of "SMTP command timeout - closing connection" errors in the logs. Could this issue also cause emails being dropped? Using latest Symfony 6.4

@bobvandevijver
Copy link
Contributor Author

When using messenger it should (when configured correctly) be retried or placed in the failed queue. If the worker did not restart soon enough to create a new connection before the last send retry and you do not have a failed queue, it can be dropped.

@peter-otten
Copy link

We have the same problem, exactly described as @bobvandevijver dit. We are using "symfony/mailer": "6.4.4" for now so our mailings can continue.

@bobvandevijver
Copy link
Contributor Author

@lazka / @peter-otten Maybe you can try #54532 to verify whether my proposed fix solves your issues as well.

@fabpot fabpot closed this as completed May 30, 2024
fabpot added a commit that referenced this issue May 30, 2024
…active mode (bobvandevijver)

This PR was squashed before being merged into the 5.4 branch.

Discussion
----------

[Mailer] Fix sendmail transport failure handling and interactive mode

| Q             | A
| ------------- | ---
| Branch?       | 5.4
| Bug fix?      | yes
| New feature?  | no <!-- please update src/**/CHANGELOG.md files -->
| Deprecations? | no <!-- please update UPGRADE-*.md and src/**/CHANGELOG.md files -->
| Issues        | Fix #54532 <!-- prefix each issue number with "Fix #", no need to create an issue if none exists, explain below instead -->
| License       | MIT

#54239 introduced an issue for us when using sendmail in interactive mode using a long running background worker. It will throw exceptions due to an unclean shutdown in case of an SMTP timeout (5 minute by default), while in interactive mode all output is actually handled by the SMTP transport, including that timeout. That makes the exit code of the long running process not relevant in that mode. See the bug report for some more details.

I have verified that this change solves my production issues, although I am not particularly fond on the hoops I had to jump to show this in the test.

cc `@aboks`

Commits
-------

1b2ead3 [Mailer] Fix sendmail transport failure handling and interactive mode
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants