Testbot reconfirmation fails: failed to retrieve [.patch] from [qa.drupal.org]

Only hints I see in the testbot watchdog logs are a couple of undefined index errors, which I opened at #1347588: Undefined index watchdog thrown on testbot if test['vcs']['dependencies'] not defined. and #1347590: Undefined index: debug error in testbot watchdog logs.

Happened on 659 tonight ...

Notice: Undefined index: debug in pifr_client_review_pifr_simpletest->get_result() (line 310 of /var/lib/drupaltestbot/sites/all/modules/project_issue_file_review/review/simpletest/pifr_simpletest.client.inc).

Notice: Undefined index: debug in pifr_client_review_pifr_simpletest->get_result() (line 310 of /var/lib/drupaltestbot/sites/all/modules/project_issue_file_review/review/simpletest/pifr_simpletest.client.inc).

Followed by ...

When sending result, server responded: Invalid server (client key may have been disabled)

Then ...

When requesting next test, server responded: Invalid server (client key may have been disabled)

And then ...

Test results successfully sent: (t: 135299).

When requesting next test, server responded: Invalid server (client key may have been disabled)

The last 6 logs were all on the same timestamp, which supports the suggestion that we have a race condition.

Logs from the qa.drupal.org side show that the confirmation failed on a complete test, with 1 failure, on test 198: String translate, search and validate (LocaleTranslationFunctionalTest) [Locale] :

Logs from the qa.d.o side:

18:42 - confirmation_check(): $status[stage]=8, result_op=fail, confirmation_op=fail

From http://qa.drupal.org/admin/reports/event/4334088:

[test_name] => String translate, search and validate (LocaleTranslationFunctionalTest) [Locale]
[pass] => 253
[fail] => 1
[exception] => 0
[assertions] => Array
    (
        [0] => Array
            (
                 [test_class] => LocaleTranslationFunctionalTest
                 [status] => fail
                 [message] => Language code not found.
                 [message_group] => Other
                 [function] => LocaleTranslationFunctionalTest->testStringTranslation()
                 [line] => 294
                 [file] => locale.test
            )
        )
    )

Followed by

19:19 - confirmation_check(): $status[stage]=10, result_op=fail, confirmation_op=

19:19 - confirmation_check(): Failing confirmation because confirmation_op() != result_op(fail)

19:19 - page not found (confirmation/.patch)

Received result from testbot client:

Array
(
    [test_id] => 135299
    [code] => 2
    [details] => Array
        (
            [@reason] => failed to retrieve [.patch] from [qa.drupal.org]
        )

    [data] => Array
        (
        )

    [log] => [18:19:01] Log initialized (/var/lib/drupaltestbot/sites/default/files/review.test_135299.pifr_simpletest..patch.1325121541.log)
[18:19:01] Environment variables and review information initialized.
[18:19:01] core_url = [git://git.drupal.org/project/drupal.git];  Test repository = [git://git.drupal.org/project/drupal.git]
[18:19:01] Review started.
[18:19:01] Invoking operation [setup]...
[18:19:01] Command [rm -rf sites/default/files/checkout 2>&1] succeeded
  Duration: 0 seconds
  Directory: [/var/lib/drupaltestbot]
  Completion status: [0]
  Output: no output.
[18:19:01] Command [rm -rf sites/default/files/review 2>&1] succeeded
  Duration: 0 seconds
  Directory: [/var/lib/drupaltestbot]
  Completion status: [0]
  Output: no output.
[18:19:01] Database backend [mysql] loaded.
[18:19:02] Invoking operation [fetch]...
[18:19:02] Failed to fetch file [http://qa.drupal.org//confirmation/.patch], instead received response [404].
[18:19:02] Encountered error on [fetch], details:
array (
  '@reason' => 'failed to retrieve [.patch] from [qa.drupal.org]',
)
[18:19:02] Review complete. test_id=135299 result code=2 details=Array
(
    [@reason] => failed to retrieve [.patch] from [qa.drupal.org]
)

[18:19:02] Static variables reset.
)

Looks a bit like the simpletest failure may have been related to our unnamed 'confirmation.patch' request. Will be interesting to see if future occurances are also preceeded by a failed test.

Noted that after tonight's /tmpfs repairs, testbot 699 appeared to hang on 'install' during the reconfirmation for over an hour before I manually reset it ... may or may not be related to our other reconfirmation problems.

Okay ... more troubleshooting, this time on qa.scratch.

Confirmation Stage 8 passes, followed by a Watchdog warning:

User warning: Duplicate entry '160024-1' for key 'PRIMARY' query: INSERT INTO pifr_environment_status (environment_id, test_id, client_id) VALUES (1, 160024, 694) in _db_query() (line 141 of /var/www/qa.scratch.drupal.org/htdocs/includes/database.mysqli.inc).

followed by a 404 retrieving http://qa.scratch.drupal.org/confirmation/.patch. This is the testbot trying to download the file, but it has a bad filename.

The next log is what's returned from the testbot,
[@reason] => failed to retrieve [.patch] from [qa.scratch.drupal.org]
... but contains a vital clue: we the following in the $test array:

 [files] => Array
        (
            [0] => http://qa.scratch.drupal.org//confirmation/.patch
        )

Next steps: Determine what's writing that to the $test array, correct, and profit!

Edit: The primary key on that table is array(test_id, environment_id). The only other column is client_id.

Another confirmation failure:

[17:35:06] Invoking operation [check]...
[17:35:06] Encountered error on [check], details:
array (
  '@filename' => 'check.patch',
)

(http://qa.drupal.org/admin/reports/event/4430523)

More logs (from the testbot side):

Notice: Undefined index: dependencies in pifr_client_review_pifr_simpletest->is_core_test() (line 244 of /var/lib/drupaltestbot/sites/all/modules/project_issue_file_review/review/simpletest/pifr_simpletest.client.inc).

Warning: Invalid argument supplied for foreach() in pifr_client_review_pifr_simpletest->is_core_test() (line 244 of /var/lib/drupaltestbot/sites/all/modules/project_issue_file_review/review/simpletest/pifr_simpletest.client.inc).

Notice: Undefined index: debug in pifr_client_review_pifr_simpletest->get_result() (line 310 of /var/lib/drupaltestbot/sites/all/modules/project_issue_file_review/review/simpletest/pifr_simpletest.client.inc).

Notice: Undefined index: debug in pifr_client_review_pifr_simpletest->get_result() (line 310 of /var/lib/drupaltestbot/sites/all/modules/project_issue_file_review/review/simpletest/pifr_simpletest.client.inc).

Also from testbot side:
When sending result, server responded: Denied
Attemt to start review while already running.
Test results successfully sent: (t: 178979).

And just to throw a completely unrelated wrench into things:

Notice: Undefined index: in update_xml_parser->end() (line 256 of /var/lib/drupaltestbot/modules/update/update.fetch.inc). Repeated multiple times.

Okay ... as far as I can tell, this is caused by a race condition where the testbot's next() test request puts everything out of sync. I believe this may be happening due to the next() request being sent when it sends the previous test response to qa.d.o, and cron invoking a next() request within a small window of time where the 'pifr_client_test' variable is still not set ... i.e. in between the xmlrpc request being sent, and the response being received.

If this is correct, the attached patch introduces a 'pifr_client_request_next_lock' variable, which should prevent cron from invoking the xmlrpc_request_next() call a second time, while there is an existing one outstanding.

699 failed today, where it sent a next() request before actually sending the previous result.

I believe the next() was triggered by the cron run; and based on the code, that next() could potentially occur right in the middle of an existing send_result() call, if the send_result communication was somehow delayed.

To address this, I'd suggest moving the pifr_client_cron_clear_variables() call within pifr_client_review_run() so that it occurs after the send_result(), but before the request_next() ... this way, we ensure that if cron tries to runs during the xmlrpc send_result() call, pift_client_cron_is_busy() will still return true.

Patch in 11 commited to 6.x-2.x (f6c9733).

Deployed to testbots ... leaving in rtbc for now, to monitor for a few weeks before closing.

This appears to have done the trick.