Problem/Motivation

In batch runs, when there is a fatal error, the current batch operation is invoked again, causing an "endless" loop (possibly eventually ended by a DB connection error). This may happen especially in the web-UI test runner during development, because WIP code is more likely to contain fatal errors.

This occurs since #2481453: Implement query parameter based content negotiation as alternative to extensions (#25)

Workaround: to run tests, use core/scripts/run-tests.sh rather than the web UI.

Proposed resolution

Remaining tasks

User interface changes

API changes

Data model changes

Original report by Arla

In web tests as well as kernel tests, when there is a fatal error, the test is run again from the beginning, causing an endless loop of test runs.

Drupal 8.0.0-beta8, 3700144
PHP 5.5.23, 5.5.26, 5.6.9, 5.6.4-4ubuntu6
MySQL 5.5.44, 5.6.25, 5.6.24-0ubuntu2

Comments

arla’s picture

@miro_dietiker spent some time debugging this. In short, if I understood it correctly, the batch system in this case fails to indicate sets as claimed and have it persisted for the next request. When the fatal error happens, the next batch request then claims the same item.

We could not identify a change that introduced this behaviour. We have been having it for a week or so.

We should create a tiny test that produces a fatal error, and then test different core checkouts and PHP/MySQL versions to pinpoint the critical conditions.

LKS90’s picture

Issue summary: View changes
StatusFileSize
new309.89 KB
new156.26 KB

Can confirm this issue, already asked for some feedback on IRC but no luck there (someone tried reproducing it by adding some random characters to a file, that's actually not enough, calling a method on a non object is a reliable way to loop the test [or $this->test()] where test() is not a valid function)

Some information:
simpletest.module will run until line 325 $test->run(); and never finishes it's testing loop. The reason seems to be that the batch information is somehow lost between runs.

Here is a screenshot of my database:

Fixing the fatal error completes the test, btw.

alexpott’s picture

Can someone upload a do not test patch so people can replicate the issue without having to think too much.

To create a do not test patch add "do-not-test" before the .patch. For example "drupal.do_nothing_555555-do-not-test.patch"

LKS90’s picture

Issue summary: View changes
StatusFileSize
new644 bytes
new106.55 KB

Here is a patch. It adds a line to the Form\ElementTest.
And a screenshot of it looping:

LKS90’s picture

Issue summary: View changes
LKS90’s picture

Issue summary: View changes
arla’s picture

Issue summary: View changes

I just tried also with MySQL 5.5.44. Latest Drupal head as well as beta8. Fresh site installs after switching core version.

Now I have no idea what might be causing this behaviour. AFAIK I haven't changed my PHP version recently.

LKS90’s picture

Just reproduced this with my patch at home. Forgot it was running...

09:01:31 {8.0.x} /var/www/drupal$ drush test-clean
Removed 836 leftover tables.                                        [status]
Removed 36 temporary directories.                              [status]
Removed 1 test result.                                                  [status]
LKS90’s picture

Issue summary: View changes
LKS90’s picture

Issue summary: View changes
StatusFileSize
new24.62 KB

But I just managed to have a PHP fatal error without the loop:

arla’s picture

Tested older Drupal versions again, with PHP 5.5 and MySQL 5.6. Procedure:

  1. Checkout Drupal core
  2. Applied attached patch (very similar to #4 but for a kernel test, for speed)
  3. drush si -y && drush en -y simpletest
  4. Login and run the modified test class
  5. Expected:
    An AJAX HTTP error occurred.
    HTTP Result Code: 200
    Debugging information follows.
    Path: /batch?id=2&op=do_nojs&op=do
    StatusText: OK
    ResponseText: 
    Fatal error:  Call to undefined function Drupal\system\Tests\TypedData\fail_miserably() in /usr/local/var/www/d8/www/core/modules/system/src/Tests/TypedData/TypedDataDefinitionTest.php on line 43
    

This time, unlike in #7, I get the expected error for core checkouts 8.0.0-beta10 and 8.0.0-beta11, but not 8.0.x (6bb1ba3).

I will try to find the commit between beta11 and current head that causes this.

arla’s picture

Well this is strange.

git lg -2 7d532f7
* 7d532f7 - Back to dev (4 weeks ago)<Nathaniel Catchpole>
* 598ccc5 - (HEAD, tag: 8.0.0-beta11) Update version constant for 8.0.0-beta11 (4 weeks ago)<Nathaniel Catchpole>

On commit 8.0.0-beta11 it works, but on 7d532f7 it does not. The single change is:

   /**
    * The current system version.
    */
-  const VERSION = '8.0.0-beta11';
+  const VERSION = '8.0.0-dev';

How can changing the VERSION constant cause this? Can someone confirm?

LKS90’s picture

Can confirm, works with beta11, broken in 7d532f7..., only difference seems to be the version constant.

LKS90’s picture

Issue summary: View changes
StatusFileSize
new126.09 KB

Managed to cause a loop while not testing:

The batch page isn't happy about php fatal errors it seems.
Example: Search_API currently has broken indexing and uses the batch page for indexing. When adding a fatal error to Index::indexItems and clicking 'Index now' on /admin/config/search/search-api/index/default_index, the batch will never finish.

berdir’s picture

I think this is related to either display_errors or xdebug being enabled.

Also strange.. When I just start a batch, it loops forever. But when I then manually refresh the page while it's looping, its' running once more and then displays the xdebug error message below the "An error happened" page.

dawehner’s picture

Just adding a tag

jhedstrom’s picture

Issue tags: +Needs tests

We'll want to test this.

LKS90’s picture

StatusFileSize
new673 bytes

Here is my try for a test for this error. It loops in the browser (unless you hit refresh), I think the testbot won't loop, but it won't reach the second assertion and have the standard test fail The test did not complete due to a fatal error..

LKS90’s picture

Status: Active » Needs review

Setting to needs review to get a testbot run for this patch.

Status: Needs review » Needs work

The last submitted patch, 18: fatal_error_during_test-2508888-18.patch, failed testing.

The last submitted patch, 18: fatal_error_during_test-2508888-18.patch, failed testing.

jhedstrom’s picture

Confirmed the patch in #18 loops through the UI, and finishes from CLI (it doesn't pass on CLI though--we'll probably need a catchable fatal error, rather than an outright fatal which isn't catchable).

I also confirmed that the looping doesn't occur if display_errors is off (the batch response at that point is a 500). When turned on, the response is a 200! Enabling/disabling xdebug doesn't appear to impact.

So, something in the batch system is changing the response code to a 200 if display_errors is turned on.

berdir’s picture

500 vs 200 is the standard PHP behavior for display_errors being on or off. No idea why it does that, but it AFAIK always behaved like this. I don't understand what changed in batch API, but somehow, we need to treat any response that can't be parsed as an error and abort, instead of trying to do something with it.

jhedstrom’s picture

Assigned: Unassigned » jhedstrom

500 vs 200 is the standard PHP behavior for display_errors being on or off

Good to know!

I've tested this without JS, and it fails as expected upon encountering a fatal error. So, this is only an issue with the JS-processing of responses. I'll dig into this now.

jhedstrom’s picture

Status: Needs work » Needs review
Issue tags: -Needs tests +Needs manual testing
StatusFileSize
new382 bytes

It appears that the removal of dataType in the ajax request from #2481453: Implement query parameter based content negotiation as alternative to extensions. Is responsible. Without that parameter, the ajax method won't detect invalid json as a problem, and happily continue on even though progress.status and progress.data aren't set.

Removing the 'needs tests' tag, because I don't think this will be reproducible without javascript tests.

This patch fixes the issue in my manual testing with the patch from #18 applied.

jhedstrom’s picture

Assigned: jhedstrom » Unassigned
jhedstrom’s picture

Priority: Normal » Major
Issue tags: +rc target triage

Since this is a bug in progress.js, this has wider implications than just testing. It could mask fatal errors during any other batch operation using JS.

xjm’s picture

Title: Fatal error during test causes endless test loop » Fatal error during batch operations causes endless test loop

Retitling per #27.

xjm’s picture

Issue tags: -rc target triage +rc target

@alexpott and I agreed on this being an RC target.

jhodgdon’s picture

Component: simpletest.module » batch system

Seems like this is batch system and not simpletest.

jhodgdon’s picture

What do we need to do to test this one-line patch and get it in?

arla’s picture

Status: Needs review » Needs work

Tested manually with LKS90's test from #18, but jhedstrom's fix in #25 does not fix it.

Again, for anyone testing this, please note that this bug occurs only in the Simpletest web UI, not when using run-tests.sh.

arla’s picture

Issue summary: View changes

Updated IS.

jhedstrom’s picture

Status: Needs work » Needs review
StatusFileSize
new300.23 KB
new451.02 KB

I just tried this again, and the issue still occurs, and the patch in #25 fixes it. To reproduce, and test the fix:

  1. Download and apply only the patch from #18
  2. Browse to /admin/config/development/testing
  3. Open the chrome network inspector (or equivalent)
  4. Run SimpleTestTest
  5. Note the batch requests just keep on going:
  6. Download and apply the patch from #25. Make sure to clear caches so updated js is used
  7. Run SimpleTestTest again. The error is caught because the returned fatal error is invalid json:
longwave’s picture

Status: Needs review » Reviewed & tested by the community

Confirmed that the test steps in #34 fix the problem.

I also confirmed this separately by introducing a deliberate fatal error in the Ubercart test suite. I had seen this issue before but was unsure of the cause - fatal errors cause the Simpletest UI to run in an infinite loop without the patch in #25, but with the patch in #25 tests with errors stop as expected with an error message after a single run.

arla’s picture

Ah, yes, sorry for the sloppy testing. Didn't realise that the unpatched js was cached in the browser. I just tested again and I agree that #25 has a successful patch.

catch’s picture

Status: Reviewed & tested by the community » Fixed

Committed/pushed to 8.0.x, thanks!

  • catch committed b59c94a on 8.0.x
    Issue #2508888 by LKS90, jhedstrom: Fatal error during batch operations...

  • catch committed b59c94a on 8.1.x
    Issue #2508888 by LKS90, jhedstrom: Fatal error during batch operations...

Status: Fixed » Closed (fixed)

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