Handling emails in MailerTestService::destruct() can be too late.

Created on 24 July 2024, about 2 months ago
Updated 29 August 2024, 9 days ago

Problem/Motivation

While working with symfony_mailer_test, I noticed random test failures, where an expected email was not received.
E.g. I would run a test 10 times, and randomly around 3 out of 10 test runs would fail.

I created a custom log file to track the calls to:
MailerTestService::postSend(), from the web request.
MailerTestService::destruct(), from the web request.
MailerTestTrait::init(), from a test class.

I found that the order of these calls was not consistent between test runs.
Sometimes the ::destruct() in the web request would run _after_ the ::init() in the test class.

Successful order:
Drupal\symfony_mailer_test\MailerTestService::postSend()
Drupal\symfony_mailer_test\MailerTestService::destruct() - 1 emails
Drupal\symfony_mailer_test\MailerTestTrait::init()

Failing order:
Drupal\symfony_mailer_test\MailerTestService::postSend()
Drupal\symfony_mailer_test\MailerTestTrait::init()
Drupal\symfony_mailer_test\MailerTestService::destruct() - 1 emails

Steps to reproduce

To artificially force the bug to reproduce:
(I did not actually try this yet)
- Create a functional test that uses symfony_mailer_test to check for emails.
- Run the test.
- Insert "usleep(200000);" at the start of MailerTestService::destruct().
- Run the test again.

In the first run, the test will likely be successful.
In the second run, with the usleep(), perhaps not.

I suppose there is a range for the usleep number where the order becomes unpredictable, so that the test will randomly fail at ~50%.
I suspect it can also depend on background activity on the machine where the test runs.

Proposed resolution

Don't wait for MailerTestService::destruct(), write to the state directly in ::postSend().

This said, I would be curious about the conditions that cause a delayed ::destruct() call after a response is already sent.

Remaining tasks

User interface changes

API changes

Data model changes

Possible follow-up tasks

Actually to me the state feels a bit fragile.
It can fail if emails are sent in parallel requests.
Normally this won't happen in a test, unless emails are sent in asset or ajax requests.

A cleaner alternative would be a dedicated db table with one record per email, which can behave like a queue.
But for the scope of this issue it is enough to drop the ::destruct().

🐛 Bug report
Status

Fixed

Version

1.0

Component

Miscellaneous

Created by

🇩🇪Germany donquixote

Live updates comments and jobs are added and updated live.
Sign in to follow issues

Merge Requests

Comments & Activities

  • Issue created by @donquixote
  • 🇩🇪Germany donquixote

    Actually...
    this is not a ::__destruct() method, but a ::destruct(), which is called from $kernel->terminate().

    We see this in index.php:

    $response->send();
    
    $kernel->terminate($request, $response);
    

    So this explains the order :)

  • 🇩🇪Germany donquixote

    Also, the current solution with using state assumes that all emails are sent during a single request.
    If there are multiple requests that happen before the test can collect the emails, e.g. as a batch process, and each of them is sending emails, then there will be a problem in the __construct() which expects the state collected mails to be empty.

    A database table with one row per mail and auto increment would solve this.
    There can be a counter in the test trait that contains the last read auto increment id.
    In the ::setUp() method the table can be truncated, and the auto increment reset, OR the internal counter variable/property can be set to the current auto increment counter from the db.

    We also want this to work with ExistingSite tests, where we cannot rely on the module being freshly installed each time.

  • Pipeline finished with Success
    about 1 month ago
    Total: 225s
    #234018
  • Pipeline finished with Success
    about 1 month ago
    Total: 183s
    #234022
  • Pipeline finished with Success
    about 1 month ago
    Total: 165s
    #234024
  • 🇩🇪Germany donquixote

    This is interesting.
    The "FAIL" merge request does not actually fail the phpunit test.
    But in my local env (with ddev) I do get test failures, even without the usleep().

    One thing I suspect is that usleep()/sleep() does not really work in the pipeline.

  • 🇩🇪Germany donquixote

    In my local I get these failures with the FAIL branch:

    Time: 00:37.938, Memory: 4.00 MB
    
    There were 4 failures:
    
    1) Drupal\Tests\symfony_mailer\Functional\LegacyEmailTest::testSendLegacyEmail
    Failed asserting that null is not null.
    
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:56
    /var/www/html/tests/modules/symfony_mailer_test/src/MailerTestTrait.php:46
    /var/www/html/tests/src/Functional/LegacyEmailTest.php:43
    /var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:729
    
    2) Drupal\Tests\symfony_mailer\Functional\LegacyEmailTest::testSendLegacyEmailWithTheme
    Failed asserting that null is not null.
    
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:56
    /var/www/html/tests/modules/symfony_mailer_test/src/MailerTestTrait.php:46
    /var/www/html/tests/src/Functional/LegacyEmailTest.php:81
    /var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:729
    
    3) Drupal\Tests\symfony_mailer\Functional\OverrideTest::testUpdate
    Failed asserting that null is not null.
    
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:56
    /var/www/html/tests/modules/symfony_mailer_test/src/MailerTestTrait.php:46
    /var/www/html/tests/src/Functional/OverrideTest.php:127
    /var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:729
    
    4) Drupal\Tests\symfony_mailer\Functional\TestEmailTest::testTest
    Failed asserting that null is not null.
    
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:56
    /var/www/html/tests/modules/symfony_mailer_test/src/MailerTestTrait.php:46
    /var/www/html/tests/src/Functional/TestEmailTest.php:27
    /var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:729
    
    FAILURES!
    Tests: 26, Assertions: 274, Failures: 4.
    

    With the 1.x branch I get 1 failure:

    Time: 00:47.724, Memory: 4.00 MB
    
    There was 1 failure:
    
    1) Drupal\Tests\symfony_mailer\Functional\OverrideTest::testUpdate
    Failed asserting that null is not null.
    
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:122
    /var/www/html/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:56
    /var/www/html/tests/modules/symfony_mailer_test/src/MailerTestTrait.php:46
    /var/www/html/tests/src/Functional/OverrideTest.php:127
    /var/www/html/vendor/phpunit/phpunit/src/Framework/TestResult.php:729
    
    FAILURES!
    Tests: 26, Assertions: 312, Failures: 1.
    

    With the fix branch, all tests pass.

  • Pipeline finished with Skipped
    23 days ago
    #255057
  • First commit to issue fork.
  • Status changed to Fixed 23 days ago
  • 🇬🇧United Kingdom AdamPS

    Thanks.

    I believe the current code was written for efficiency with a test that sent 1000s of emails. I guess the new code would be slower in that case?? But core TestMailCollector also rewrites the state for every mail, so it probably doesn't matter much.

    Please can you raise a follow on issue for the other problems you spotted?

  • Automatically closed - issue fixed for 2 weeks with no activity.

Production build 0.71.5 2024