DrupalCI SQLite random failures

@basic nice to see improvements in drupalCI testing :) I'm currently maintaining the bots at *.erwanderbar.de and yes the exceptions happen all over. I see the random exceptions also on PostgreSQL and MySQL too. So I think the problem here is that the exceptions may be caused by SQLite as results storage backend?
I think this is at least major, if not critical because of broken testing, so changing priority.

Adding a tag.

Its great to have those problems uncovered as early as possible.

I would really to like to help to fix this problem. The problem is that there is very little debug information to really know what is going wrong. Is there any way to get more debug information when there is an exception?

@daffie for the bots set the DCI_Verbose='true' variable. But that isn't very helpful because the output is always cut off :(

I notice also random fails (not exceptions) in the Installer test group (happens every 2 or 3 days or so). Very bad and hard to debug :(

Nice! I finally managed to capture one random exception message. This is with SQLite as DB backend, here's what I got:

    <error type="exception" message="Uncaught exception">&lt;em class="placeholder"&gt;Drupal\Core\Database\SchemaObjectExistsException&lt;/em&gt;: Table file_usage already exists. in &lt;em class="placeholder"&gt;Drupal\Core\Database\Schema-&amp;gt;createTable()&lt;/em&gt; (line &lt;em class="placeholder"&gt;518&lt;/em&gt; of &lt;em class="placeholder"&gt;/var/www/html/core/lib/Drupal/Core/Database/Schema.php&lt;/em&gt;). &lt;pre class="backtrace"&gt;Drupal\Core\Database\Schema-&gt;createTable('file_usage', Array)
Drupal\simpletest\KernelTestBase-&gt;installSchema('file', Array)
Drupal\file\Tests\FileManagedUnitTestBase-&gt;setUp()
Drupal\file\Tests\SpaceUsedTest-&gt;setUp()
Drupal\simpletest\TestBase-&gt;run(Array)
simpletest_script_run_one_test('55', 'Drupal\file\Tests\SpaceUsedTest')
&lt;/pre&gt;

line: 518
file: /var/www/html/core/lib/Drupal/Core/Database/Schema.php</error>

So the randoms seem to be cause by already existing table exceptions...

EDIT: I remember that we had to work around the exactly same problem in one of the failing PostgreSQL tests. Wish we had more progress within #2371709: Move the on-demand-table creation into the database API ;)

Related to #1551132: When trying to create a table that already exists but is empty, recreate the table rather than throwing a DatabaseSchemaObjectExistsException?

@basic now that XML output seems to work, can you please verify the random exceptions and see if they all fail for the same reason, e.g. schemaObjectExistsException?

And another one, this is with PostgreSQL as database backed:

<?xml version="1.0"?>
<testsuite><testcase classname="Drupal\system\Tests\System\PageNotFoundTest" name="testPageNotFound()"><failure type="failure" message="Completion check">The test did not complete due to a fatal error.</failure></testcase><testcase classname="Drupal\system\Tests\System\PageNotFoundTest" name="install_begin_request()"><error type="exception" message="Uncaught exception">&lt;em class="placeholder"&gt;Drupal\Core\Installer\Exception\AlreadyInstalledException&lt;/em&gt;: &amp;lt;ul&amp;gt;
&amp;lt;li&amp;gt;To start over, you must empty your existing database and copy &amp;lt;em&amp;gt;default.settings.php&amp;lt;/em&amp;gt; over &amp;lt;em&amp;gt;settings.php&amp;lt;/em&amp;gt;.&amp;lt;/li&amp;gt;
&amp;lt;li&amp;gt;To upgrade an existing installation, proceed to the &amp;lt;a href=&amp;quot;/update.php&amp;quot;&amp;gt;update script&amp;lt;/a&amp;gt;.&amp;lt;/li&amp;gt;
&amp;lt;li&amp;gt;View your &amp;lt;a href=&amp;quot;http://localhost&amp;quot;&amp;gt;existing site&amp;lt;/a&amp;gt;.&amp;lt;/li&amp;gt;
&amp;lt;/ul&amp;gt; in &lt;em class="placeholder"&gt;install_begin_request()&lt;/em&gt; (line &lt;em class="placeholder"&gt;482&lt;/em&gt; of &lt;em class="placeholder"&gt;/var/www/html/core/includes/install.core.inc&lt;/em&gt;). &lt;pre class="backtrace"&gt;install_begin_request(Object, Array)
install_drupal(Object, Array)
Drupal\simpletest\WebTestBase-&gt;doInstall(Array)
Drupal\simpletest\WebTestBase-&gt;setUp()
Drupal\system\Tests\System\PageNotFoundTest-&gt;setUp()
Drupal\simpletest\TestBase-&gt;run(Array)
simpletest_script_run_one_test('1389', 'Drupal\system\Tests\System\PageNotFoundTest')
&lt;/pre&gt;

line: 482
file: /var/www/html/core/includes/install.core.inc</error></testcase></testsuite>

I just posted a patch in #1120020-48: SQLite database locking errors cause fatal errors that I hope will help with these random fails on DrupalCI. @basic or @bzrudi71, do you think we can try a DrupalCI test run with that patch applied? I would do it locally but it takes around ~2h :/

@amateescu, PostgreSQL bot just finished and there are still random exceptions around :( Also a complete new fatal shows up:

zend_mm_heap corrupted
FATAL Drupal\migrate_drupal\Tests\d6\MigrateDrupal6Test: test runner returned a non-zero error code (1).
Drupal\migrate_drupal\Tests\d6\MigrateNodeTypeTest            22 passes                                      
Drupal\migrate_drupal\Tests\d6\MigrateNodeTest                25 passes                                      
Drupal\migrate_drupal\Tests\d6\MigrateSearchConfigsTest        8 passes                                      
- Found database prefix 'simpletest987617' for test ID 639.
- Removed test site directory.
- Removed 302 leftover tables.

Unfortunately I don't have more time to start an SQLite run today, sorry ;)

SQLite bot is running but I already seen an exception :( I had a look at the latest runs on dispatcher.drupalci.org and there are many more exceptions than on my bot. I think the higher the concurrency, the higher the number of exceptions. DrupalCI runs with a concurrency of 27 while my bot runs with a concurrency of 6. What we learned so far is that all exceptions are caused by: already installed, already exist problems...

EDIT: Bot completed and here are the two exceptions:

<failure type="failure" message="Completion check">The test did not complete due to a fatal error.</failure></testcase><testcase classname="Drupal\user\Tests\UserAdminLanguageTest" name="install_verify_database_ready()"><error type="exception" message="Uncaught exception">&lt;em class="placeholder"&gt;Drupal\Core\Installer\Exception\AlreadyInstalledException&lt;/em&gt;: &amp;lt;ul&amp;gt;
&amp;lt;li&amp;gt;To start over, you must empty your existing database and copy &amp;lt;em&amp;gt;default.settings.php&amp;lt;/em&amp;gt; over &amp;lt;em&amp;gt;settings.php&amp;lt;/em&amp;gt;.&amp;lt;/li&amp;gt;
&amp;lt;li&amp;gt;To upgrade an existing installation, proceed to the &amp;lt;a href=&amp;quot;/update.php&amp;quot;&amp;gt;update script&amp;lt;/a&amp;gt;.&amp;lt;/li&amp;gt;
&amp;lt;li&amp;gt;View your &amp;lt;a href=&amp;quot;http://localhost&amp;quot;&amp;gt;existing site&amp;lt;/a&amp;gt;.&amp;lt;/li&amp;gt;
&amp;lt;/ul&amp;gt; in &lt;em class="placeholder"&gt;install_verify_database_ready()&lt;/em&gt; (line &lt;em class="placeholder"&gt;1109&lt;/em&gt; of &lt;em class="placeholder"&gt;/var/www/html/core/includes/install.core.inc&lt;/em&gt;). &lt;pre class="backtrace"&gt;install_verify_database_ready(Array)
install_run_task(Array, Array)
install_run_tasks(Array)
install_drupal(Object, Array)
Drupal\simpletest\WebTestBase-&gt;doInstall(Array)
Drupal\simpletest\WebTestBase-&gt;setUp()
Drupal\user\Tests\UserAdminLanguageTest-&gt;setUp()
Drupal\simpletest\TestBase-&gt;run(Array)
simpletest_script_run_one_test('1505', 'Drupal\user\Tests\UserAdminLanguageTest')

and

<?xml version="1.0"?>
<testsuite><testcase classname="Drupal\system\Tests\Field\FieldModuleUninstallValidatorTest" name="testUninstallingModule()"><failure type="failure" message="Completion check">The test did not complete due to a fatal error.</failure></testcase><testcase classname="Drupal\system\Tests\Field\FieldModuleUninstallValidatorTest" name="setUp()"/><testcase classname="Drupal\system\Tests\Field\FieldModuleUninstallValidatorTest" name="Drupal\Core\Database\Schema-&gt;createTable()"><error type="exception" message="Uncaught exception">&lt;em class="placeholder"&gt;Drupal\Core\Database\SchemaObjectExistsException&lt;/em&gt;: Table sequences already exists. in &lt;em class="placeholder"&gt;Drupal\Core\Database\Schema-&amp;gt;createTable()&lt;/em&gt; (line &lt;em class="placeholder"&gt;518&lt;/em&gt; of &lt;em class="placeholder"&gt;/var/www/html/core/lib/Drupal/Core/Database/Schema.php&lt;/em&gt;). &lt;pre class="backtrace"&gt;Drupal\Core\Database\Schema-&gt;createTable('sequences', Array)
Drupal\simpletest\KernelTestBase-&gt;installSchema('system', 'sequences')
Drupal\system\Tests\Entity\EntityUnitTestBase-&gt;setUp()
Drupal\system\Tests\Field\FieldModuleUninstallValidatorTest-&gt;setUp()
Drupal\simpletest\TestBase-&gt;run(Array)
simpletest_script_run_one_test('384', 'Drupal\system\Tests\Field\FieldModuleUninstallValidatorTest')
&lt;/pre&gt;

line: 518
file: /var/www/html/core/lib/Drupal/Core/Database/Schema.php</error></testcase></testsuite>

I posted another patch at #1713332-40: The SQLite database driver fails to drop simpletest tables which should fix the fails from #14. @bzrudi71, would you mind giving it another try with both patches applied? :)

HURRAY! I just finished a full test run on DrupalCI locally (PHP 5.5 + SQLite) with 100% pass rate!

Marking as 'needs review' for the two patches that were applied for the test run:

#1120020-48: SQLite database locking errors cause fatal errors
#1713332-40: The SQLite database driver fails to drop simpletest tables

GREAT! Nice work @amateescu, especially #1713332: The SQLite database driver fails to drop simpletest tables makes totally sense! Bot is running with both patches applied. I'm out for a beer now and will report later or tomorrow :)

Well, bot finished and there is not a single exception :) However, there seems to be a performance problem with the patches, as the test runtime doubled from 1h to 2h. Maybe my box was busy with some background work but we should at least do another run to make sure. Will do that later on today and report. @amateescu can start a run with just a single test group and check if the runtime differs as well for you?

I was going to create a sister issue for PostgreSQL, but @isntall already opened #2524426: [meta] DrupalCI pgsql Random exceptions, fails, testbot issues.

The runtime was the same for both runs I did locally, one with the patch from #1120020-48: SQLite database locking errors cause fatal errors and the second with both patches applied: 2h 50m :)

Yup, I just think you missed to test against HEAD without any patch applied :) To quickly confirm, I just ran the node test group and here are the results:

HEAD no patch:

Test run duration: 4 min 29 sec

HEAD with patch #1120020: SQLite database locking errors cause fatal errors applied:

Test run duration: 9 min 15 sec

So #1120020: SQLite database locking errors cause fatal errors seems to be problematic. Can you confirm :)

Hm, I can't reproduce that performance problem..

HEAD no patch:

Test run duration: 10 min 9 sec

HEAD with #1120020-48: SQLite database locking errors cause fatal errors:

Test run duration: 10 min 24 sec

There is a slight increase but this is on my local and I was also doing other things while running the tests.

Can you also do a bot run with just #1713332-40: The SQLite database driver fails to drop simpletest tables applied and see if that one is enough to fix the random exceptions?

Bot just finished with patch #1713332: The SQLite database driver fails to drop simpletest tables applied only (seems we need both):

Drupal\system\Tests\System\UncaughtExceptionTest 27 passes 1 fails 3 exceptions

I really like to investigate the problem with #1120020: SQLite database locking errors cause fatal errors but sadly I don't have much time. So if it works for you let's get both in and see I think :)

As a last action for today I looked at the build stats of drupalCI and the UncaughtExceptionTest() seems to fail completely on drupalCI (Introduced by #2509898: Additional uncaught exception thrown while handling exception after service changes). So it seems we should only get #1713332: The SQLite database driver fails to drop simpletest tables in as a first step?

BTW @basic/@isntall it seems drupalCI does not catch/count exceptions, all/most builds are listed with 'SUCCESS' status even if there are exceptions around.

@bzrudi71, that sounds like a good plan, get #1713332: The SQLite database driver fails to drop simpletest tables in and then do more benchmarks with the other one and see if it's really needed or not :) Of course.. someone still needs to review/RTBC it though :P

I ran the patch from #1120020-48: SQLite database locking errors cause fatal errors twice on a DCI testrunner and it took about 3 hours each time.

Here are the
https://dispatcher.drupalci.org/job/php5.5_sqlite3.8/16/
https://dispatcher.drupalci.org/job/php5.5_sqlite3.8/17/

Run 17 says that there were no failures, but there was a failure at the 17:43:10 time marker
https://dispatcher.drupalci.org/job/php5.5_sqlite3.8/17/consoleFull

@isntall, yeah, 3h is a long time given that a recent DrupalCI run finished in 32 minutes for MySQL (https://dispatcher.drupalci.org/job/php5.5_mysql5.5/20/console).

Anyway, the patch that is supposed to fix the random exceptions is #1713332-40: The SQLite database driver fails to drop simpletest tables, could you run that one as well a couple of times?

@amateescu that patch, #1713332-40: The SQLite database driver fails to drop simpletest tables, seemed to work well.

• https://dispatcher.drupalci.org/job/php5.5_sqlite3.8/23/
• https://dispatcher.drupalci.org/job/php5.5_sqlite3.8/27/
• https://dispatcher.drupalci.org/job/php5.5_sqlite3.8/29/

36 minutes is a much better time.

@catch suggested we might be able to work around this and #2524426: [meta] DrupalCI pgsql Random exceptions, fails, testbot issues by at least temporarily using single concurrency for the SQLite and Postgres builds, which could be acceptable since these test suites mostly only run nightly. Is that an option to get more reliable results from DrupalCI until any other issues are resolved?

Tagging.

@xjm I can dial both of the daily branch test jenkins jobs' concurrency down to 1, however patches will still run against the multi concurrent bots as those are not separated out by environment. So if a regression *does* happen, it'll be difficult to fix that regression as the random failures will return.

Concurrency is not the problem for SQLite, the issue is poor randomness of simpletest test ids, as proven by #1713332: The SQLite database driver fails to drop simpletest tables.

In fact, since we already know what the problem is and we have a patch that works but needs a bit more work, I think we can just postpone this issue on the one mentioned above.

That one got committed, but looks like we still have SQLite fails: https://www.drupal.org/pift-ci-job/19661 (Not sure if they're random or not.)

That's because the patch was committed *after* the daily branch test run on sqlite. I'm pretty sure I'm going to lose my mind if the test results from today are not fully green :)

There we go, first green result!! https://www.drupal.org/pift-ci-job/20095

AWESOME! Thanks, amateescu!