Right now if there is a PHP fatal error during execution of tests, one has to both guess that this is the case and dig into the PHP error logs to find the true cause.

However, error logging in PHP is PHP_INI_ALL, so we can alter it at run time just for the tests. We already create a writable directory for each test that runs - that directory is abandoned in the case of a ftal error, which perhaps we can use to trap logged errors.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

pwolanin’s picture

Status: Active » Needs review
FileSize
1.8 KB

seems to work if, for example, I alter a function calls in one of the test cases to generate a "PHP Fatal error: Call to undefined function".

pwolanin’s picture

FileSize
1.8 KB

typo fix.

boombatower’s picture

Status: Needs review » Reviewed & tested by the community
FileSize
15.39 KB

This looks great.
php fatal log

Dries’s picture

Looking at the screenshot in #3, it sounds like we can clean-up the output a bit. The two first bullet items seem redundant? It might complicate the code though.

Personally, I wish the tests could write to the watchdog table of the master site, instead of introducing a special logging case. This might be a lot easier now with DBTNG.

pwolanin’s picture

@Dries - this is for fatal errors. i.e. WSOD. You lose the ability to do anything within PHP, hence the only way to handle this is via the PHP error log as far as I know. Drupal cannot watchodg these sorts of errrors.

Dries’s picture

D'oh -- you're right.

c960657’s picture

Right now if there is a PHP fatal error during execution of tests, one has to both guess that this is the case and dig into the PHP error logs to find the true cause.

Don't you see the error message like in this screenshoot from #313902: DX: Show fatal errors in tests? If not, does it work if you add ini_set('display_errors', '1') to DrupalWebTestCase::setUp() ?

AFAICT the patch only works for fatal errors on the testing side, not on the tested side (i.e. on pages fetched using $this->drupalGet()). Can it be extended to do both?

pwolanin’s picture

Status: Reviewed & tested by the community » Needs work

Hmm, good question - I think you're right in that we'd need to add these ini directive to the system under test as we do setting the DB prefix.

Dries’s picture

Issue tags: +Favorite-of-Dries

We need to get this one in! Tagging.

jrchamp’s picture

If you're looking for one to test on, the fix for the fatal error that I was experiencing in the modules/php/php.test #493296: Patch for a couple tests with an error is postponed until this issue is resolved.

Dries’s picture

Priority: Normal » Critical

Bumping this to critical because it causes us to waste time in the issue queue, and because some other patches are now blocked on it.

webchick’s picture

Subscribing as well. Sorry, I committed the fix for jrchamp's problem in another issue an attempt to get more testing slaves online; didn't know it was blocked on this.

catch’s picture

Title: Log PHP fatal errors during test runs to present informative error messages » Fatal errors in tests not reported as failures
Category: feature » bug

This isn't a feature request, broken patches are getting committed with fatal errors in tests because they 'pass'.

scor’s picture

FileSize
1.87 KB

patch #2 does not apply any more. rerolling

chx’s picture

Iterating the files directory is not something I can agree with. If we have no better idea then create a files/simpletest directory and work in there , I rather have files/simpletest/123 than iterating the whole of files. (NowPublic has a couple million files there for eg)

chx’s picture

Also? That's a DSM. How does that become an assert failure?

boombatower’s picture

Assigned: Unassigned » boombatower

Currently working on this.

Also note that the patch won't work for run-tests.sh and if multiple testing sessions are run at once it will screw up...or if clean button is not used. Although if we do this right we might be able to eliminate clean button.

This leads into the cleanup of the test runner I am working on which would make one set of code run for start/end of test..etc.

boombatower’s picture

boombatower’s picture

Status: Needs work » Needs review
FileSize
5.72 KB

This needs a bit more cleanup and documentation and needs a quick code addition in run-tests.sh. In the mean time I would like to see what the bot thinks. It also needs to depend on other patch and have those parts removed.

A possible followup patch could auto-run cleanup since we now know the database prefix that crashed. :)

boombatower’s picture

FileSize
6.29 KB

run-tests.sh integration...now we can see if core has any fatal errors

boombatower’s picture

FileSize
6.86 KB

Documented and cleaned. This still has the file directory structure patch applied...for testing. Once other is committed I can easily remove it.

boombatower’s picture

FileSize
5.87 KB

Dependent patch. Requires #512104: Simpletest breaks high volume sites

It passes since no log file is found and it simply ignores the code.

Berdir’s picture

I assume the tests here will fail once it is working correctly, because we have currently two issues with calls to non-existing functions.

This means that we need to fix those two issues first before we can commit this. On the other side, we can use them to verify that it is working as expected.

#395472-241: Plugin Manager in Core: Part 1 (backend)
#373201-37: Enhance drupal_render() themeing. Return renderable array on tracker page.

Dries’s picture

Status: Needs review » Needs work

I was initially confused about assertStatic(). It doesn't return TRUE or FALSE, instead it enters something in the database. In fact, it doesn't even perform an assert. I suggest renaming the function to be less confusing, say logAssert() or something.

That said, I went ahead and committed this patch. Given that this de-blocks us, we can clean it up some more in follow-up patches. Marking 'code needs work'.

catch’s picture

This doesn't actually show up the fatal errors yet - because we have them in HEAD still, so I guess there's more work to do in this issue.

Berdir’s picture

Also, after an error occured, I'm getting the following exception:
PDOException: SQLSTATE[42S22]: Column not found: 1054 Unknown column 'last_prefix' in 'field list': SELECT last_prefix FROM {simpletest_test_id} WHERE test_id = :test_id; Array ( [:test_id] => 9 ) in simpletest_log_read() (line 224 of .../d7/drupal/modules/simpletest/simpletest.module).

(Web and cli)

jrchamp’s picture

I had to look up the schema. Disabling and reenabling the simpletest module did not resolve it.

alter table simpletest_test_id add last_prefix varchar(60) not null default '' comment 'The last database prefix used during testing.';

boombatower’s picture

Need to re-install module.

Can someone point me to the fatal errors...that we have in core. I tested this is a call to non-existent function and it worked great.

Berdir’s picture

drupal_render() has been fixed, #395472-241: Plugin Manager in Core: Part 1 (backend) is still open. these are in FileTransferTest.

I figured that much, but still.. if it would work as expected, all tests should now fail...

scor’s picture

In the System > FileTransfer unit tests:
Fatal error: Call to undefined function dd() in /Applications/MAMP/htdocs/d702_filter/modules/simpletest/tests/filetransfer.test on line 122
though might be specific to my MAMP installation.

boombatower’s picture

Try this patch out.

Index: modules/block/block.test
===================================================================
RCS file: /cvs/drupal/drupal/modules/block/block.test,v
retrieving revision 1.20
diff -u -r1.20 block.test
--- modules/block/block.test	8 Jun 2009 09:23:50 -0000	1.20
+++ modules/block/block.test	8 Jul 2009 20:48:57 -0000
@@ -43,6 +43,7 @@
     $box['title'] = $this->randomName(8);
     $box['body'] = $this->randomName(32);
     $this->drupalPost('admin/build/block/add', $box, t('Save block'));
+    hax();
 
boombatower’s picture

As discussed in IRC, I cannot re-create this and when I test the patch and such it picks up fatal error.

boombatower’s picture

Status: Needs work » Needs review
FileSize
2.22 KB

Per #24, I agree that it is not clear and have attached patch to correct.

boombatower’s picture

FileSize
2.26 KB

Documentation addition, and fixed method call.

jrchamp’s picture

"recorder" should be "recorded" in:

   * This is useful for inserting assertions that can only be recorder after
webchick’s picture

Question. If this patch actually works, how is it passing tests atm? Shouldn't the dd() in the testCopyDirectory() test cause it to always fail?

jrchamp’s picture

@webchick It correctly failed for me when the fatal error occurred. However, the test bot likely uses a different method for evaluating tests whose fatal errors are not handled by this patch.

The web interface makes a series of AJAX calls pulling each test at a time. The test bot likely runs them directly. I'm not sure who to ask about the test bot's procedure for running these tests so that we could identify a way for it to handle these types of errors as well.

webchick’s picture

IMO the point of this patch should be for test bot to fail spectacularly when someone adds dd() in their patch. If it doesn't do that, then it doesn't resolve the issue. Although it's nice that it allows for the manual case, that's not what's causing us to completely break HEAD periodically.

webchick’s picture

Also, the manual case wouldn't catch this kind of stuff to begin with. I'm sure whoever rolled the Plugin Manager patch had Devel module on their copy of Drupal, and dd() wouldn't have flagged an error for them.

boombatower’s picture

It works for both the web runner and run-tests.sh.

/me tired of clarifying how test bot works

Test bot simply invoked run-tests.sh and pulls results out of db...so if run-tests.sh catches it...bot will.

boombatower’s picture

FileSize
2.26 KB

Updated for #35.

This is simple fix...main patch already committed...so lets get this in.

boombatower’s picture

Create #515998: Bot test - catch fatal error to test with bot.

boombatower’s picture

FileSize
3.67 KB

Cannot test locally since test craps in a different way locally.

Try this out.

boombatower’s picture

FileSize
3.69 KB

Basically the issue is that logging isn't enabled on drupalGet|Post() side, only test side. This is why I can get it to pick up errors, but test doesn't.

Also require tweak for run-tests.sh edge case.

boombatower’s picture

FileSize
2.97 KB

Ok...this temp...till I figure out where to put it.

boombatower’s picture

Ok, I got this figured out. Need a bit of time to come up with solution...the underlying code is mad.

boombatower’s picture

FileSize
4.73 KB

This should fix issue for bot.

This is not a clean fix and still needs work, just want to see if both notices fatal.

boombatower’s picture

FileSize
5.75 KB

Ok, one hell of an ugly patch. Needs cleanup.

Status: Needs review » Needs work

The last submitted patch failed testing.

boombatower’s picture

Status: Needs work » Needs review
FileSize
5.63 KB

Progress!

This is a delicate matter and the previous patch a debug statement that may have caused errors...removing to see.

Status: Needs review » Needs work

The last submitted patch failed testing.

boombatower’s picture

Status: Needs work » Needs review
FileSize
5.64 KB

Gotta love how sensitive this stuff is.

boombatower’s picture

Not catching dd() issue since test is not written properly.

/me glares at the author.

function setUp() {
    $this->testConnection = TestFileTransfer::factory(DRUPAL_ROOT, array('hostname' => $this->hostname, 'username' => $this->username, 'password' => $this->password, 'port' => $this->port));
  }

Notice anything missing?

function setUp() {
    parent::setUp();
    $this->testConnection = TestFileTransfer::factory(DRUPAL_ROOT, array('hostname' => $this->hostname, 'username' => $this->username, 'password' => $this->password, 'port' => $this->port));
  }
webchick’s picture

boombatower and I have been going back and forth on IRC all day since I can reproduce the bug and he couldn't. The next patch should be the one that allows his changes to work on my machine.

boombatower’s picture

FileSize
5.81 KB

Confirmed by webchick...that was the issue.

Updated patch should parse stack trace and changed default line number to 0.

boombatower’s picture

FileSize
6.03 KB

Parse PHP stack.

Dries’s picture

I wonder if this opens a security door:

+if (isset($_SERVER['HTTP_USER_AGENT']) && preg_match("/^simpletest\d+$/", $_SERVER['HTTP_USER_AGENT'])) {
+  // Log fatal errors.
+  ini_set('log_errors', 1);
+  ini_set('error_log', file_directory_path() . '/error.log');
+}

It basically enables people to write to an error.log stored in the publicly accessible file directory. This change makes me a bit nervous.

I've done some reading on php.net and I think error_get_last() in combination with a shutdown function could make for a more elegant solution: (i) it avoids error parsing and (ii) it avoids writing to files (that can be read by the world). See http://us2.php.net/manual/en/function.error-get-last.php. I believe custom shutdown functions are always called.

Thoughts?

boombatower’s picture

Seems as though a shutdown hook won't work...I tried that first.

Problem is the shutdown hook loses all context (especially depending on the OS configuration). Meaning It loses the drupal root directory and is running in a separate PHP process so you can't just call the db layer and write the assertion.

Again, simpletest is not intended to be installed on live sites...for a number of reason. It should ONLY be used on development computers. It may be a good idea to add some sort of warning.

Another option is to ensure that the database with that prefix exists before doing anything like enabling logging since only SimpleTest can create the prefixed db.

Considering the damage SimpleTest can do to a production site if a test screws up...and the fact that it is a development tool...it should not be placed on a production server even as it now, without this patch.

For example as the issue with the other test I was having trouble with. If you don't add the parent::setUp() SimpleTest will modify the live site.

I'll try and clean up this patch soon.

chx’s picture

Meaning It loses the drupal root directory and is running in a separate PHP process so you can't just call the db layer and write the assertion.

hm, the shutdown functions registered with register_shutdown_function definitely run in the same process and I believe the objects are not yet destructed so the DB connection should be there. Care to enlight me what and how did you test to reach this conclusion?

Damien Tournoud’s picture

+if (isset($_SERVER['HTTP_USER_AGENT']) && preg_match("/^simpletest\d+$/", $_SERVER['HTTP_USER_AGENT'])) {
+  // Log fatal errors.
+  ini_set('log_errors', 1);
+  ini_set('error_log', file_directory_path() . '/error.log');
+}

This will not flight, (1) for the reason described by Dries above and (2) because it makes it impossible to write proper error_log() statement in your code (which I do a lot during debugging).

Given that...

  1. The test bot uses run-tests.sh, which prints the fatal errors in its standard output, and
  2. Fatal errors are already printed in the batch API error message when running tests interactively.

... I'm close to won't fixing this issue. The only real bug seems to be in PIFR, that doesn't parse the run-tests.sh results for fatal errors.

boombatower’s picture

PIFR does not and should not parse the text...that is troublesome, inaccurate, and slow (11,000 assertion messages and fatal log messages to regex, catch the test and group they are related to...why?). It reads the results out of the db, as it should. The fatal errors NEED to be failed assertions. The test NEED to fail locally as well as on test servers...consistent results, otherwise we'll have more people complaining that the bot reports errors they don't see...that is the last thing I need.

When debugging you can simply do trigger_error() and it will be picked up...plus we need to work on the facility all together. If you prefer a file with all your output...file_put_contents('out.txt', 'stuff', FILE_APPEND).

This needs to be fixed, this solution (in design, not current code) is clean and works well. It even catches XDEBUG stack trace and provides it on the assertions page.

Seems like the outstanding issue #1 is to confirm that this is a developer tool (as it only can be...it does not add to user experience of a site) and should be treated like one. So the code needs some flags in places to ensure that simpletest is enabled or w/e and then and only then should it allow the error log to be printed. (I think this is what Dries meant)

I'll look into shutdown hook again, but that really does not seem like the solution as per my previous experience and when I played with it. It looses way too much context, and we won't be able to catch XDEBUG and such.

pwolanin’s picture

@Dries - re #57, in general I think we need some sort of more careful check that we are actually running tests before respecting this UA header.

I can think of a few (a bit ugly) possibilities - we can check that a matching table is in the DB. We could check that the matching simpltest files director has been created, we could put a file in the Drupal tmp dir and even include a timestamp inside it as content so that we limit the time window over which we will accept this header.

Anyhow - we have some bare protection now to prevent the installer from being run with this header, but I agree with the general nervousness about sec holes being possible via the testing code.

boombatower’s picture

Something we had in SimpleTest when it went in core originally (or close to that time) was a key that was used in addition to the db prefix to confirm that SimpleTest was the one sending the prefix. The key is much easier to check than other methods (db or files), but technically isn't quite as secure. Once someone figures out the key (not easy of course) it doesn't matter if SimpleTest is doing anything. Although we can just neglect to generate the key until SimpleTest is installed...end remove the key on uninstall.

Not sure if drupal_get_private_key() would be of use here to use as the key.

Personally that the key seems like the simplest and least expensive option. One issue to consider although is that we need a way to check before invoking the db.

pwolanin’s picture

Since it's kind of unrelated, a separate issue : #518404: Lock down DB config based on simpletest UA headers

Let's discuss security there - I can roll a generic validation function for the UA header so just get it working here asap.

Damien Tournoud’s picture

@boombatower: last time I looked, PIFR was parsing the result of run-tests.sh. Maybe that changed in PIFR2?

boombatower’s picture

Yea, in pifr 2 it reads DB...which is much better. Since we are trying to deploy that now it doesn't make sense to be messing with PIFR 1.x, not to mention that it needs to be an assertion so it fails locally.

Reading out of text that PHP just dumps is not a clean and is a complete hack.

boombatower’s picture

FileSize
7.99 KB

Since the security issue has been solved I went ahead and cleaned this up.

I abstracted the log read so it can be called without being forced to run queries. Eventually I could see having it clear the logs or something so that it can be called after each drupalGet|Post() if in verbose/debug mode so that the fatal error is require after the call that caused it, but for now we at least collect them on both sides.

This patch also read PHP XDebug output to provide line numbers and such, any message that does not match the format will simply be inserted as a whole. Updated the default line number and such (per talk with webchick).

And updated the static assertion method names per Dries' comment.

I have thoroughly tested this with both the web runner and run-tests.sh.

chx’s picture

Status: Needs review » Needs work

Just comments need upgrading, one, around the pregs some examples would be good to see what's going on there (and maybe name the preg parts), two, refer why the simpletest user agent is valid like "function X already checked"

boombatower’s picture

Status: Needs work » Needs review
FileSize
8.37 KB

Provided example next to regex with documentation and added a comment in common.inc to clarify how user-agent is validated per IRC review by chx.

EDIT: chx posted :)

boombatower’s picture

Status: Needs review » Reviewed & tested by the community

Per comment in IRC, chx indicated that he was functionally fine with this.

chx’s picture

yes this patch is fine!

boombatower’s picture

FileSize
8.4 KB

Correct query sort order and add db_query_range() noticed by DamZ.

boombatower’s picture

FileSize
10.14 KB

Log during installation process.

boombatower’s picture

FileSize
10.14 KB

Change 4th argument to be more clear/simple and update documentation.

boombatower’s picture

IRC review from webchick:

1. remove the xdebug special-case.
2. please move $operations[0][1][1] to a local variable like $test_id
3. Is add comments to both of those hunks in run-tests.sh and simpletest.module to explain to poor suckers who don't know the magic of list() what the hell that code is doing

webchick’s picture

Status: Reviewed & tested by the community » Needs work

Damn. There is some ugly code in here that makes baby kittens cry. :\ Unfortunately, most of it was here before and wasn't introduced in this patch...

-    simpletest_log_read($operations[0][1][1]);
+    list($last_prefix, $last_test_class) = simpletest_last_test_get($operations[0][1][1]);
+    simpletest_log_read($operations[0][1][1], $last_prefix, $last_test_class);

1. Please for the love of all that is holy, stick $operations[0][1][1] in a local variable called $test_id.
2. Please for the love of all that is holy, document what this bit of code is doing (both here and in run-tests.sh)

+      elseif (preg_match('/\[.*?\] (.*?) \/(.*?):(\d+)/', $line, $match)) {
+        // Parse XDebug statements.
         $caller = array(
           'line' => $match[3],
           'file' => $match[2],
         );
-        DrupalTestCase::assertStatic($test_id, $test_class, FALSE, $match[1], 'Fatal error', $caller);
+        DrupalTestCase::insertAssert($test_id, $test_class, FALSE, $match[1], 'PHP stack', $caller);
       }

While I use and love XDebug, I think it's not the place for core to be catering to specific development tools. Please remove this.

boombatower’s picture

Status: Needs work » Reviewed & tested by the community
FileSize
10.3 KB

Fresh off the press soaked in kitten tears.

chx’s picture

Do not hoid this one up but a followup really should add back xdebug support. It's quite expectable that ppl who want to use this will have xdebug on.

Status: Reviewed & tested by the community » Needs work

The last submitted patch failed testing.

boombatower’s picture

Status: Needs work » Reviewed & tested by the community
FileSize
10.29 KB

Re-rolled and double checked.

@Dries: Do you agree with #78, if so I will roll a followup.

Dries’s picture

I agree with #78. We can worry about xdebug after. I also agree with webchick that there is some ugly code, but we can clean that up later too (unless you want to do some of that now).

Dries’s picture

Status: Reviewed & tested by the community » Fixed

Committed to CVS HEAD. Thanks. Feel free to re-roll still.

Status: Fixed » Closed (fixed)
Issue tags: -Favorite-of-Dries

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