Fix intermittent test failure on AppVeyor #5447

cmb69 · 2020-04-24T09:23:44Z

For several days this test case is often failing on AppVeyor, because
the table already exists. Thus, we add a cleanup step just before
creating the table.

I have no idea why this test suddenly started to fail that often. It seems that only happens on master, and might be caused by enabling JIT, although I can't see why that would cause just this test to fail. This fix is not nice; actually it's more a hacky workaround. I'm also not sure what to do with the error message numbering.

For several days this test case is often failing on AppVeyor, because the table already exists. Thus, we add a cleanup step just before creating the table.

nikic · 2020-04-24T14:39:28Z

Maybe try enabling printing of all tests (not just SKIP) so we see what runs before it? Just looking at alphabetical order of tests, I really don't see what would cause this.

The preceding test mysqli_insert_id_variation.phpt does not use the test table, and the one before that mysqli_insert_id.phpt uses the test table, but includes clean_table.inc in CLEAN.

cmb69 · 2020-04-27T12:58:49Z

Maybe try enabling printing of all tests (not just SKIP) so we see what runs before it?

That looks like the most promising approach. Done as 51dfba3.

alexdowad · 2020-04-27T19:53:03Z

I was just about to open a PR which attempts to fix the same problem, and then saw this...

...Let me open it anyhow, and you can look at it and see if it looks like a worthwhile approach.

nikic · 2020-04-27T20:02:46Z

PASS Bug #74099 Memory leak with openssl_encrypt() [C:\projects\php-src\ext\openssl\tests\bug74099.phpt] 
PASS mysqli_get_host_info() [C:\projects\php-src\ext\mysqli\tests\mysqli_get_host_info.phpt] 
PASS mysqli_get_proto_info() [C:\projects\php-src\ext\mysqli\tests\mysqli_get_proto_info.phpt] 
PASS mysqli_get_server_info() [C:\projects\php-src\ext\mysqli\tests\mysqli_get_server_info.phpt] 
PASS mysqli_get_server_version() [C:\projects\php-src\ext\mysqli\tests\mysqli_get_server_version.phpt] 
SKIP mysqli_get_warnings() - TODO [C:\projects\php-src\ext\mysqli\tests\mysqli_get_warnings.phpt] reason: - experimental (= unsupported) feature
PASS mysqli_info() [C:\projects\php-src\ext\mysqli\tests\mysqli_info.phpt] 
PASS mysqli_init() [C:\projects\php-src\ext\mysqli\tests\mysqli_init.phpt] 
PASS mysqli_insert_id() [C:\projects\php-src\ext\mysqli\tests\mysqli_insert_id.phpt] 
PASS Checking last_insert_id after different operations [C:\projects\php-src\ext\mysqli\tests\mysqli_insert_id_variation.phpt] 
PASS Bug #74159: Writing a large buffer to non-blocking encrypted streams fails [C:\projects\php-src\ext\openssl\tests\bug74159.phpt] 
PASS Bug #74341 (openssl_x509_parse fails to parse ASN.1 UTCTime without seconds) [C:\projects\php-src\ext\openssl\tests\bug74341.phpt] 
                                                      
========DIFF========
001+ [012] [1050] Table 'test' already exists
001- done!
002+ [013] max_allowed_packet = 67108864, strlen(query) = 16777214, [1054] Unknown column 'col_blob' in 'field list'
003+ [014] [1054] Unknown column 'col_blob' in 'field list'
004+ 
005+ Fatal error: Uncaught TypeError: mysqli_fetch_assoc(): Argument #1 ($mysql_result) must be of type mysqli_result, bool given in C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.php:70
006+ Stack trace:
007+ #0 C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.php(70): mysqli_fetch_assoc(false)
008+ #1 {main}
009+   thrown in C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.php on line 70
========DONE========
FAIL INSERT and packet overflow [C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.phpt] 
SKIP Bug #74402 (segfault on random_bytes, bin3hex, openssl_seal) [C:\projects\php-src\ext\openssl\tests\bug74402.phpt] 
PASS Bug #74651: negative-size-param (-1) in memcpy in zif_openssl_seal() [C:\projects\php-src\ext\openssl\tests\bug74651.phpt] 
PASS mysqli_kill() [C:\projects\php-src\ext\mysqli\tests\mysqli_kill.phpt] 
PASS Bug #74720 pkcs7_en/decrypt does not work if \x1a is used in content, variant 0 [C:\projects\php-src\ext\openssl\tests\bug74720_0.phpt] 
PASS Bug #74720 pkcs7_en/decrypt does not work if \x1a is used in content, variant 1 [C:\projects\php-src\ext\openssl\tests\bug74720_1.phpt] 
PASS API vs. SQL LAST_INSERT_ID() [C:\projects\php-src\ext\mysqli\tests\mysqli_last_insert_id.phpt]

Tests seems to be running in expected order, and the parellel tests are OpenSSL tests, which shouldn't interfere.

cmb69 · 2020-04-28T10:05:04Z

[…], and the one before that mysqli_insert_id.phpt uses the test table, but includes clean_table.inc in CLEAN.

I wonder whether this cleaning fails (for whatever reason); AIUI, this would not be reported by run-tests.php.

nikic · 2020-04-28T10:06:40Z

[…], and the one before that mysqli_insert_id.phpt uses the test table, but includes clean_table.inc in CLEAN.

I wonder whether this cleaning fails (for whatever reason); AIUI, this would not be reported by run-tests.php.

That seems plausible. Maybe we can hack in something to print out the output of CLEAN?

cmb69 · 2020-04-28T10:55:26Z

@nikic, very hacky, but should do for now:

 run-tests.php | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/run-tests.php b/run-tests.php
index ffdb72a00e..93d84cc73f 100755
--- a/run-tests.php
+++ b/run-tests.php
@@ -2497,7 +2497,10 @@ COMMAND $cmd
                 $clean_params = settings2params($clean_params);
                 $extra = !IS_WINDOWS ?
                     "unset REQUEST_METHOD; unset QUERY_STRING; unset PATH_TRANSLATED; unset SCRIPT_FILENAME; unset REQUEST_METHOD;" : "";
-                system_with_timeout("$extra $php $pass_options $extra_options -q $clean_params $no_file_cache \"$test_clean\"", $env);
+                $clean_output = system_with_timeout("$extra $php $pass_options $extra_options -q $clean_params $no_file_cache \"$test_clean\"", $env);
+                if (trim($clean_output) != '') {
+                    echo "\nCLEAN OUTPUT: $file: $clean_output\n";
+                }
             }
 
             if (!$cfg['keep']['clean']) {

alexdowad · 2020-04-28T11:07:09Z

Please see the approach in #5479.

cmb69 · 2020-04-28T13:55:20Z

@alexdowad, that is basically the same approach as this PR + using another name for the table. Actually, neither should be necessary.

nikic · 2020-04-28T13:57:08Z

@cmb69 Let's temporarily land the run-tests patch and see if anything turns up.

This is a hack to investigate why mysqli_insert_packet_overflow.phpt intermittently fails on AppVeyor, and will be reverted in due time. See <#5447 (comment)>.

cmb69 · 2020-04-28T14:08:43Z

Done as 5eb4ab0.

alexdowad · 2020-04-28T14:25:27Z

@alexdowad, that is basically the same approach as this PR + using another name for the table. Actually, neither should be necessary.

OK. Thanks for reviewing.

cmb69 · 2020-04-28T16:44:43Z

@alexdowad, to be clear, I'd prefer your PR over this one, but still like to fix the root cause of the test failure.

cmb69 · 2020-04-28T17:02:08Z

Nope, apparently no issues with the former cleanups: https://ci.appveyor.com/project/php/php-src/builds/32504539/job/6eq2d84d1o8auhlx?fullLog=true#L11242

alexdowad · 2020-04-28T19:33:22Z

Ahem.

AppVeyor test environment:

Environment: THREAD_SAFE=1, OPCACHE=1, PARALLEL=-j2, INTRINSICS=AVX

Do you see that PARALLEL argument? That is actually why I wanted to change the name of the table to something that is not used in any other test...

Deleting PARALLEL=-j2 would be a good way to confirm whether I am onto something here, or just blowing hot air.

nikic · 2020-04-28T19:51:09Z

@alexdowad All tests using MySQL declare mysql as the conflict key (see https://github.com/php/php-src/blob/master/ext/mysqli/tests/CONFLICTS), so they are not executed in parallel.

alexdowad · 2020-04-28T19:53:30Z

@alexdowad All tests using MySQL declare mysql as the conflict key (see https://github.com/php/php-src/blob/master/ext/mysqli/tests/CONFLICTS), so they are not executed in parallel.

Thanks. I learned something here.

nikic · 2020-04-28T19:58:04Z

The ini handling code in run-tests is pretty hard to follow, but could it be that the opcache cache_id for Windows is not getting passed down to the clean invocation?

nikic · 2020-04-28T20:06:47Z

So yes, it looks like we're only passing the ini overrides for the clean command, not anything else. I don't quite remember what exactly goes wrong if we share opcache instances across parallel jobs, is it plausible that the cleanup script crashes in that case?

cmb69 · 2020-04-29T07:53:05Z

@nikic, ah, good catch! We must not share OPcache instances between processes with different memory layout, but a different set of loaded extensions may easily cause different memory layout. I'll see to it that the worker ID is passed to the clean up scripts.

nikic · 2020-04-29T08:05:41Z

From https://ci.appveyor.com/project/php/php-src/builds/32519626/job/1cykafd58wy6hpbi?fullLog=true:

PASS mysqli_insert_id() [C:\projects\php-src\ext\mysqli\tests\mysqli_insert_id.phpt] 
PASS Checking last_insert_id after different operations [C:\projects\php-src\ext\mysqli\tests\mysqli_insert_id_variation.phpt] 
PASS Bug #74159: Writing a large buffer to non-blocking encrypted streams fails [C:\projects\php-src\ext\openssl\tests\bug74159.phpt] 
                                                      
CLEAN OUTPUT: C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.phpt: Cleaned successfully
========DIFF========
001+ [012] [1050] Table 'test' already exists
001- done!
002+ [013] max_allowed_packet = 67108864, strlen(query) = 16777214, [1054] Unknown column 'col_blob' in 'field list'
003+ [014] [1054] Unknown column 'col_blob' in 'field list'
004+ 
005+ Fatal error: Uncaught TypeError: mysqli_fetch_assoc(): Argument #1 ($mysql_result) must be of type mysqli_result, bool given in C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.php:70
006+ Stack trace:
007+ #0 C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.php(70): mysqli_fetch_assoc(false)
008+ #1 {main}
009+   thrown in C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.php on line 70
========DONE========
FAIL INSERT and packet overflow [C:\projects\php-src\ext\mysqli\tests\mysqli_insert_packet_overflow.phpt]

This is missing the "Cleaned successfully" output on the mysqli_insert_id.phpt test, so it does indeed look like the clean script is crashing. Hopefully it's the opcache cache_id and not something else.

alexdowad · 2020-04-29T17:55:39Z

Congratulations! This was a tricky one!

cmb69 · 2020-04-29T20:57:59Z

Yes, that was indeed a tricky one. Thanks @nikic!

Fix intermittent test failure on AppVeyor

c2e90c6

For several days this test case is often failing on AppVeyor, because the table already exists. Thus, we add a cleanup step just before creating the table.

cmb69 marked this pull request as draft April 27, 2020 12:59

php-pulls pushed a commit that referenced this pull request Apr 28, 2020

Show eventual output of clean sections

5eb4ab0

This is a hack to investigate why mysqli_insert_packet_overflow.phpt intermittently fails on AppVeyor, and will be reverted in due time. See <#5447 (comment)>.

carusogabriel mentioned this pull request Apr 29, 2020

Fix #79539: during CI, drop table if it exists #5493

Closed

nikic mentioned this pull request Apr 29, 2020

Fix flaky tests (1) #5479

Closed

cmb69 closed this Apr 29, 2020

cmb69 deleted the cmb/mysqli_insert_packet_overflow branch April 29, 2020 20:59

Fix intermittent test failure on AppVeyor #5447

Fix intermittent test failure on AppVeyor #5447

Uh oh!

Conversation

cmb69 commented Apr 24, 2020

Uh oh!

nikic commented Apr 24, 2020

Uh oh!

cmb69 commented Apr 27, 2020

Uh oh!

alexdowad commented Apr 27, 2020

Uh oh!

nikic commented Apr 27, 2020

Uh oh!

cmb69 commented Apr 28, 2020

Uh oh!

nikic commented Apr 28, 2020

Uh oh!

cmb69 commented Apr 28, 2020

Uh oh!

alexdowad commented Apr 28, 2020

Uh oh!

cmb69 commented Apr 28, 2020

Uh oh!

nikic commented Apr 28, 2020

Uh oh!

cmb69 commented Apr 28, 2020

Uh oh!

alexdowad commented Apr 28, 2020

Uh oh!

cmb69 commented Apr 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cmb69 commented Apr 28, 2020

Uh oh!

alexdowad commented Apr 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

nikic commented Apr 28, 2020

Uh oh!

alexdowad commented Apr 28, 2020

Uh oh!

nikic commented Apr 28, 2020

Uh oh!

nikic commented Apr 28, 2020

Uh oh!

cmb69 commented Apr 29, 2020

Uh oh!

nikic commented Apr 29, 2020

Uh oh!

alexdowad commented Apr 29, 2020

Uh oh!

cmb69 commented Apr 29, 2020

Uh oh!

Uh oh!

cmb69 commented Apr 28, 2020 •

edited

Loading

alexdowad commented Apr 28, 2020 •

edited

Loading