Module enable/disable tests failing on testing servers

subscribing

Subscribing. Need to fix this to turn testing bot back on.

Apparently it causes these specific errors when the modules page doesn't save properly. I can confirm the problem is intermittent, happens on slower testing systems (quad core or worse) and can happen on either PIFR 1 or PIFR 2. It's line 117 that cascades into more errors because it's where the post to save the modules page happens.

CSV simpletest table dump:

"7617";"1";"EnableDisableTestCase";"fail";"Modules status has been updated.";"Other";"EnableDisableTestCase->testEnableDisable()";"118";"/var/www/sites/default/files/checkout/modules/system/system.test"
"7618";"1";"EnableDisableTestCase";"fail";"hook_modules_installed fired.";"Other";"EnableDisableTestCase->testEnableDisable()";"121";"/var/www/sites/default/files/checkout/modules/system/system.test"
"7619";"1";"EnableDisableTestCase";"fail";"hook_modules_enabled fired.";"Other";"EnableDisableTestCase->testEnableDisable()";"122";"/var/www/sites/default/files/checkout/modules/system/system.test"

I develop on a very slow machine, and I'm getting the same failures also for ModuleDependencyTestCase::testEnableWithoutDependency(), which equally tries to post to the module page.

But even when doing

--- modules/simpletest/drupal_web_test_case.php	17 Aug 2009 19:14:41 -0000	1.137
+++ modules/simpletest/drupal_web_test_case.php	20 Aug 2009 00:17:00 -0000
@@ -31,7 +31,7 @@ abstract class DrupalTestCase {
   /**
    * Time limit for the test.
    */
-  protected $timeLimit = 180;
+  protected $timeLimit = 0;

I'm still getting the same errors. I'm rather confused by the returned 403.

I am assuming this is due to:

case DRUPAL_BOOTSTRAP_DATABASE:
  // The user agent header is used to pass a database prefix in the request when
  // running tests. However, for security reasons, it is imperative that we
  // validate we ourselves made the request.
  if (isset($_SERVER['HTTP_USER_AGENT']) && (strpos($_SERVER['HTTP_USER_AGENT'], "simpletest") !== FALSE) && !drupal_valid_test_ua($_SERVER['HTTP_USER_AGENT'])) {
    header($_SERVER['SERVER_PROTOCOL'] . ' 403 Forbidden');
    exit;
  }

Attempting to fix.

Confirmed by changing the time window in drupal_valid_test_ua().

Supposed to generate a new one every request in curlInitialize(), but curl is handling the redirect since drupal_goto() returns a "Location" header.

This can be fixed by: a) increasing the time window, or b) turning off the auto redirect in curl and doing it ourselves.

Remove curl redirect follow and implements inside DWTC.

I still kind of like #9 as part of the solution to this. The whole 2 second check thing seems arbitrary. Why not just let it take as long as it takes in case the server happened to have some combination of high CPU, disk I/O, swapping, etc misc load. It's not like the 2 second window has some sort of runaway process kill functionality in it which might be the only useful part of having a counter on it...

Let's fix the bug first. That's highly critical, because it blocks many patches and code-freeze is coming.

Great sleuthing, folks!

Ok, switching testing bot back on....

Hm. Damn. No dice.

All of the patches that make it as far as running tests are getting the same failures. Random example:

http://testing.drupal.org/pifr/file/1/11678
Result received from slave #38 (Failed: 13069 passes, 15 fails, 4 exceptions).
Path aliases with translated nodes: 1 fail, 1 exception
Session tests: 1 fail
SimpleTest functionality: 4 fails, 1 exception
UI language negotiation: 9 fails, 2 exceptions

ok, testbot seems to fail on tests that may expect special treatment of redirects: http://testing.drupal.org/pifr/file/1/11677

Also, I decided to revert the previous patch. It might be close, but the situation before the patch was that under some conditions some machines might get 3 failures in the module tests, and the situation after is all machines are getting 15 failures in a number of seemingly unrelated tests. This stage of the core development cycle is the most critical, and I don't want to see core developers wasting time debugging things that are not their fault.

If there's a way to do a dry run on the testing servers with the next patch before it gets marked RTBC, I would really appreciate it. ;)

What's funny is the easiest way to test before would have been to have PIFR 2 to it, but I moved all the clients except my sandbox back to PIFR 1. Maybe amazon will come through with some additional clients.

Er, nevermind. It'll have to be local. PIFR 2 clients won't pass the self test with core broken (which is why my sandbox client is in failed state in PIFR 2).

Ok, committed the patch in #9.

Restarting the testing bot again....

Yay! I think it's back! :)

I had to disable slave #39, but the rest are coming back with passes. Turning reporting back on.

Thanks for all of your help folks!!!

Erm. Reopening that. We removed the time check instead of increasing it... (why?) thus strongly lowering the security of the system.

If we don't want a time check, we should clean-up the time variable from the token.

We definitely need the Simpletest tokens to be non-replayable. This patch removed that without any consideration about the risks involved.

indeed - this is really serious. Why was this committed?

#11 looks like it was trying to actually address the problem, not break our security model.

Here's a roll-back patch for #9 accounting for core changes since then.

chx asks for a 30 second window (the default PHP timeout) until we fix the curl behavior, etc.

It looks like #11 made it into core also? In that case, maybe we are ok with 2 seconds (or something shorter than 30)?

+++ includes/bootstrap.inc
@@ -2261,8 +2261,11 @@ function drupal_valid_test_ua($user_agent) {
+  // @todo - fix the curl redirect behavior so we can shorten this time window.

If I'd scan through bootstrap.inc and read this todo, I'd have no idea of what the author was trying to tell here.

Also, remove the leading hyphen and use proper capitalization/punctuation.

+++ includes/bootstrap.inc
@@ -2261,8 +2261,11 @@ function drupal_valid_test_ua($user_agent) {
+  return (($time_diff >= 0) && ($time_diff <= 30) && $hmac == drupal_hmac_base64($check_string, $key));

Parentheses around inner conditions ($time_diff >= 0) are needless.

40 critical left. Go review some!

in fact looks like that curl fix was already made, so let's try this with ~5 sec?

@sun - I find the parens are more readable (even if they are needless) - and they were in core before. Do we have a code style standard here?

+++ includes/bootstrap.inc
@@ -2261,8 +2261,10 @@ function drupal_valid_test_ua($user_agent) {
+  return (($time_diff >= 0) && ($time_diff <= 5) && $hmac == drupal_hmac_base64($check_string, $key));

If it's really more readable, then why isn't the last condition wrapped in parentheses? :)

EDIT: on a second read, all additional parentheses are needless on this line.

  return $time_diff >= 0 && $time_diff <= 5 && $hmac == drupal_hmac_base64($check_string, $key);

Sorry, I can't RTBC, not familiar enough with this code.

There seems to be no real standard on the use of parens - so I favor them if they add readability.

see:

http://api.drupal.org/api/function/drupal_valid_token/7
http://api.drupal.org/api/function/drupal_is_cli/7
http://api.drupal.org/api/function/drupal_page_is_cacheable/7

Given that this is essentially just rolling back a commit above , I think it's RTBC as long as the tests pass (which was the reason for this issue in any case).

Really sorry. :( I remember being in a bit of a desperate state trying to get testbot back on at the time this was committed, and didn't fully take in the ramifications of this patch.

Committed to HEAD!