Possible random failure in build tests for cron updates

Created on 27 October 2023, 8 months ago
Updated 21 March 2024, 3 months ago

Problem/Motivation

https://www.drupal.org/pift-ci-job/2795252 β†’

There was just a doc block change that triggered the tests. On retest it passed

There error comes from the first line

$this->assertExpectedStageEventsFired(ConsoleUpdateStage::class, wait: 360);
$this->assertCronUpdateSuccessful();

My guess is the 360 wait not long enough because by the events logged we have not gotten to post-apply.
the other possibility is that randomly there is something that goes wrong with the apply.

but I am leaning towards the wait not being long enough because I have only seen this with cron related build tests we just have to wait and don't get intermittent UI checks.

Steps to reproduce

Proposed resolution

  1. Run a test run here of just testAutomatedCron but run say 50 times. See if we get random fails
  2. Try increase wait time and see if it goes away, We could also decrease the wait time and see if it happens more
  3. If the longer wait time makes the problem go away just increase the wait time. \Drupal\Tests\package_manager\Build\TemplateProjectTestBase::assertExpectedStageEventsFired checks every 5 seconds if all the event have fired so increasing the wait time should not actually make the test run longer in most cases(as we very rarely see this error)

Remaining tasks

User interface changes

API changes

Data model changes

πŸ› Bug report
Status

Needs work

Version

3.0

Component

Code

Created by

πŸ‡ΊπŸ‡ΈUnited States tedbow Ithaca, NY, USA

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

Merge Requests

Comments & Activities

  • Issue created by @tedbow
  • Merge request !978Resolve #3397228 "Possible random failure" β†’ (Open) created by tedbow
  • Open in Jenkins β†’ Open on Drupal.org β†’
    Core: 10.1.x + Environment: PHP 8.1 & MySQL 8
    last update 8 months ago
    Custom Commands Failed
  • Open in Jenkins β†’ Open on Drupal.org β†’
    Core: 10.1.x + Environment: PHP 8.1 & MySQL 8
    last update 8 months ago
    1 pass, 1 fail
  • Open in Jenkins β†’ Open on Drupal.org β†’
    Core: 10.1.x + Environment: PHP 8.1 & MySQL 8
    last update 8 months ago
    1 pass
  • Open in Jenkins β†’ Open on Drupal.org β†’
    Core: 10.1.x + Environment: PHP 8.1 & MySQL 8
    last update 8 months ago
    1 pass
  • Open in Jenkins β†’ Open on Drupal.org β†’
    Core: 10.1.x + Environment: PHP 8.1 & MySQL 8
    last update 8 months ago
    1 pass, 1 fail
  • Open in Jenkins β†’ Open on Drupal.org β†’
    Core: 10.1.x + Environment: PHP 8.1 & MySQL 8
    last update 8 months ago
    1 pass
  • Status changed to Postponed 8 months ago
  • πŸ‡ΊπŸ‡ΈUnited States tedbow Ithaca, NY, USA

    Hmmm. with 50 test runs the current tests don't fail.

    I think lets just keep an on out for more random failures and re-open this issue if needed

    I also wonder if when we finally drop support for Drupalci if this will not happen on gitlabci

  • Status changed to Needs work 3 months ago
  • πŸ‡ΊπŸ‡ΈUnited States tedbow Ithaca, NY, USA

    I think this happening again now that we are using gitlab ci https://git.drupalcode.org/project/automatic_updates/-/jobs/1113256

    example

    ---- Drupal\Tests\automatic_updates\Build\CoreUpdateTest ----
    Status    Group      Filename          Line Function                            
    --------------------------------------------------------------------------------
    Fail      Other      phpunit-1.xml        0 Drupal\Tests\automatic_updates\Buil
        PHPUnit Test failed to complete; Error: PHPUnit 9.6.17 by Sebastian
        Bergmann and contributors.
        
        Testing Drupal\Tests\automatic_updates\Build\CoreUpdateTest
        F......                                                             7 / 7
        (100%)
        
        Time: 13:20.850, Memory: 24.27 MB
        
        There was 1 failure:
        
        1) Drupal\Tests\automatic_updates\Build\CoreUpdateTest::testApi
        Error response: The website encountered an unexpected error. Please try
        again later.Drupal\package_manager\Exception\StageEventException:
        assert(Inspector::assertAll(fn($message) => $message instanceof
        TranslatableMarkup, $messages)) in
        Drupal\package_manager\StageBase->dispatch() (line 627 of
        modules/contrib/automatic_updates/package_manager/src/StageBase.php).
        Drupal\package_manager\ValidationResult->__construct(2, Array, Object, 1)
        (Line: 93)
        Drupal\package_manager\ValidationResult::createError(Array, Object) (Line:
        52)
        Drupal\package_manager\Event\PreOperationStageEvent->addError(Array,
        Object) (Line: 129)
        Drupal\package_manager\Validator\SupportedReleaseValidator->validate(Object,
        'Drupal\package_manager\Event\PreApplyEvent', Object)
        call_user_func(Array, Object, 'Drupal\package_manager\Event\PreApplyEvent',
        Object) (Line: 111)
        Drupal\Component\EventDispatcher\ContainerAwareEventDispatcher->dispatch(Object)
        (Line: 618)
        Drupal\package_manager\StageBase->dispatch(Object, Object) (Line: 498)
        Drupal\package_manager\StageBase->apply() (Line: 37)
        Drupal\automatic_updates_test_api\ApiController->createAndApplyStage(Object)
        (Line: 100)
        Drupal\package_manager_test_api\ApiController->run(Object)
        call_user_func_array(Array, Array) (Line: 123)
        Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}()
        (Line: 592)
        Drupal\Core\Render\Renderer->executeInRenderContext(Object, Object) (Line:
        124)
        Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->wrapControllerExecutionInRenderContext(Array,
        Array) (Line: 97)
        Drupal\Core\EventSubscriber\EarlyRenderingControllerWrapperSubscriber->Drupal\Core\EventSubscriber\{closure}()
        (Line: 181)
        Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1) (Line: 76)
        Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1) (Line: 58)
        Drupal\Core\StackMiddleware\Session->handle(Object, 1, 1) (Line: 48)
        Drupal\Core\StackMiddleware\KernelPreHandle->handle(Object, 1, 1) (Line:
        106)
        Drupal\page_cache\StackMiddleware\PageCache->pass(Object, 1, 1) (Line: 85)
        Drupal\page_cache\StackMiddleware\PageCache->handle(Object, 1, 1) (Line:
        48)
        Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Object, 1, 1)
        (Line: 51)
        Drupal\Core\StackMiddleware\NegotiationMiddleware->handle(Object, 1, 1)
        (Line: 51)
        Drupal\Core\StackMiddleware\StackedHttpKernel->handle(Object, 1, 1) (Line:
        704)
        Drupal\Core\DrupalKernel->handle(Object) (Line: 19)
        require('/tmp/build_workspace_a63f489ecaf5e45ff6b4b6e418b75a69rZVogN/project/web/index.php')
        (Line: 71)
        
        Failed asserting that two arrays are identical.
        --- Expected
        +++ Actual
        @@ @@
             4 => 'Drupal\package_manager\Event\PreRequireEvent'
             5 => 'Drupal\package_manager\Event\PostRequireEvent'
             6 => 'Drupal\package_manager\Event\PreApplyEvent'
        -    7 => 'Drupal\package_manager\Event\PostApplyEvent'
         )
        
        /builds/project/automatic_updates/vendor/phpunit/phpunit/src/Framework/Constraint/Constraint.php:121
        /builds/project/automatic_updates/vendor/phpunit/phpunit/src/Framework/Constraint/IsIdentical.php:79
        /builds/project/automatic_updates/web/modules/custom/automatic_updates/package_manager/tests/src/Build/TemplateProjectTestBase.php:621
        /builds/project/automatic_updates/web/modules/custom/automatic_updates/tests/src/Build/CoreUpdateTest.php:126
    /builds/project/automatic_updates/vendor/phpunit/phpunit/src/Framework/TestResult.php:728
    /builds/project/automatic_updates/vendor/phpunit/phpunit/src/Framework/TestSuite.php:684
    /builds/project/automatic_updates/vendor/phpunit/phpunit/src/TextUI/TestRunner.php:651
    /builds/project/automatic_updates/vendor/phpunit/phpunit/src/TextUI/Command.php:145
    /builds/project/automatic_updates/vendor/phpunit/phpunit/src/TextUI/Command.php:98
    FAILURES!
    Tests: 7, Assertions: 495, Failures: 1.
    Remaining self deprecation notices (9)
    Remaining direct deprecation notices (3)
    Other deprecation notices (1)
    
  • Pipeline finished with Failed
    3 months ago
    #125396
  • Pipeline finished with Failed
    3 months ago
    #125510
  • πŸ‡ΊπŸ‡ΈUnited States tedbow Ithaca, NY, USA

    ok this is very confusing.

    1. \Drupal\package_manager\Validator\SupportedReleaseValidator::validate was finding an error because
      if ($unknown_packages) {
            $summary = $this->formatPlural(
              count($unknown_packages),
              'Cannot update because the following new or updated Drupal package does not have project information.',
              'Cannot update because the following new or updated Drupal packages do not have project information.',
            );
            $event->addError($unknown_packages, $summary);
          }

      was being hit. but the actually was showing up because $unknown_packages was was just strings so \Drupal\package_manager\ValidationResult::__construct threw an exception because of assert(Inspector::assertAll(fn ($message) => $message instanceof TranslatableMarkup, $messages));

      I fixed this problem by $unknown_packages was an array of translatable objects.

      This would at least let us see what packages where in$unknown_packages. Basically why did randomly 1 out of 20 times did \Drupal\Tests\automatic_updates\Build\CoreUpdateTest::testApi fail.

      which led to.....

    2. PHPUnit Test failed to complete; Error: PHPUnit 9.6.18 by Sebastian
          Bergmann and contributors.
          
          Testing Drupal\Tests\automatic_updates\Build\CoreUpdateTest
          .F..................                                              20 / 20
          (100%)
          
          Time: 42:09.652, Memory: 28.00 MB
          
          There was 1 failure:
          
          1) Drupal\Tests\automatic_updates\Build\CoreUpdateTest::testApi with data
          set #1 (1)
          Error response: The website encountered an unexpected error. Please try
          again later.Drupal\package_manager\Exception\StageEventException: The
          update cannot proceed because the following Drupal project was unexpectedly
          updated. Only Drupal Core updates are currently supported.
          module 'drupal/automatic_updates' from 3.1.x-dev to 3.0.x-dev.
          Cannot update because the following new or updated Drupal package does not
          have project information.
          drupal/automatic_updates of type drupal-module
           in Drupal\package_manager\StageBase->dispatch() (line 622 of
          modules/contrib/automatic_updates/package_manager/src/StageBase.php).
          Drupal\package_manager\StageBase->apply() (Line: 37)
          Drupal\automatic_updates_test_api\ApiController->createAndApplyStage(Object)
          (Line: 100)
          Drupal\package_manager_test_api\ApiController->run(Object)

      So now that the translation problem has been solved we can see the actual $unknown_packages that where change 1 in 20 times of running this test.

      So we have 2 validation errors here:
      StagedProjectsValidator:

      Drupal project was unexpectedly
      updated. Only Drupal Core updates are currently supported.
      module 'drupal/automatic_updates' from 3.1.x-dev to 3.0.x-dev.

      and

      \Drupal\package_manager\Validator\SupportedReleaseValidator

      Cannot update because the following new or updated Drupal package does not
      have project information.
      drupal/automatic_updates of type drupal-module

      This is because there is no project key in the info file even though it is a drupal-module since we testing from the git clone.

    3. Big question is why did composer update 'drupal/automatic_updates' from 3.1.x-dev to 3.0.x-dev but only 1 out of 20 times the test was run 😱
  • Pipeline finished with Failed
    3 months ago
    Total: 2660s
    #125593
  • Pipeline finished with Failed
    3 months ago
    Total: 418s
    #125620
  • Pipeline finished with Canceled
    3 months ago
    Total: 220s
    #128807
  • Pipeline finished with Success
    3 months ago
    #128819
Production build 0.69.0 2024