Always skip randomly failing OCI8 extauth tests #9524

mvorisek · 2022-09-11T22:17:10Z

The issue is weird as it happends only sometimes in quite repeatable environment like GH Actions.

I guess the anything connection string is the problem, sometimes it is resolved immediatelly, sometimes the resolving (or the connection) to the hostname ends with a timeout. I was however not able to reproduce it locally.

These tests was marked as slow tests. There are not slow. There are either fast or hit the problem ;-)

mvorisek · 2022-09-11T23:43:58Z

ext/oci8/tests/extauth_01.phpt

@@ -70,7 +66,7 @@ var_dump($c);

 echo "Test 7\n";

-$c = oci_connect('/', '', 'anything', null, OCI_CRED_EXT);
+$c = oci_connect('/', '', 'localhost', null, OCI_CRED_EXT);


when localhost is used instead of anything, tests fail, so it cannot be really "anything".

CI https://github.com/php/php-src/runs/8295659688?check_suite_focus=true#step:10:1952

This reverts commit 1ed7cc9.

This reverts commit b2246cb.

mvorisek · 2022-09-12T07:53:47Z

.github/actions/test-linux/action.yml

@@ -30,4 +30,4 @@ runs:
          --offline \
          --show-diff \
          --show-slow 1000 \
-          --set-timeout 120
+          --set-timeout 1200


https://github.com/php/php-src/runs/8296934151?check_suite_focus=true#step:11:3157 shows when the issue is hit, there is no OCI8 timeout or the timeout is higher than 10 minutes.

based on:
https://github.com/mvorisek/php-src/runs/8302900173?check_suite_focus=true#step:15:108
https://github.com/mvorisek/php-src/runs/8302902211?check_suite_focus=true#step:10:117
(with elapsed time dump)

it seems "Test 7" - "Test 10" can take up ~200 seconds / "Test XX"

cmb69 · 2022-09-12T09:25:17Z

Thank you for working on this!

FWIW, I just learned that as of Oracle 19c it is possible to specify CONNECT_TIMEOUT and TRANSPORT_CONNECT_TIMEOUT in the connection string.

mvorisek · 2022-09-12T09:27:28Z

Hi, @cjbj, I am reaching you as you are the author of these extauth tests.

Can you please explain what resources

php-src/ext/oci8/tests/extauth_01.phpt

Line 83 in 4b93033

$c = oci_connect('/', '', 'x.cz', null, OCI_CRED_EXT);

the test is connecting to and why the elapsed time varies from a second to 10 minutes?

CI results:

https://github.com/mvorisek/php-src/runs/8301382524?check_suite_focus=true#step:9:115

 ========DIFF========
--
     Test 7
     
     Warning: oci_connect(): ORA-12154: %s in %s on line %d
040+ elapsed: 13 secs
040- elapsed: %c secs
     array(4) {
       ["code"]=>
       int(12154)
--
========DONE========
FAIL Test External Authentication errors with oci_connect [ext/oci8/tests/extauth_01.phpt]

cjbj · 2022-09-12T13:12:40Z

FWIW, I just learned that as of Oracle 19c it is possible to specify CONNECT_TIMEOUT and TRANSPORT_CONNECT_TIMEOUT in the connection string.

See Oracle Database 21c Easy Connect Plus

cjbj · 2022-09-12T13:18:08Z

Can you please explain what resources

php-src/ext/oci8/tests/extauth_01.phpt

Line 83 in 4b93033

$c = oci_connect('/', '', 'x.cz', null, OCI_CRED_EXT);

the test is connecting to and why the elapsed time varies from a second to 10 minutes?

These tests are supposed to fail to connect, so they were originally written with connection strings like 'anything'. Maybe with the closer-to-real connection string x.cz there is some DNS lookup that is taking time?

mvorisek · 2022-09-12T13:54:58Z

Can you please explain what resources

php-src/ext/oci8/tests/extauth_01.phpt

Line 83 in 4b93033

$c = oci_connect('/', '', 'x.cz', null, OCI_CRED_EXT);

the test is connecting to and why the elapsed time varies from a second to 10 minutes?

These tests are supposed to fail to connect, so they were originally written with connection strings like 'anything'. Maybe with the closer-to-real connection string x.cz there is some DNS lookup that is taking time?

What I see is random ~200s / connect timeout. I cannot explain these timeouts. I tried real x.cz domain, but the problem remained. The problem must be burried somewhere else and I would even say it is some burried bug. Therefore I am asking you if the external auth tries to connect to some other host as a fallback or if you can somehow help identifying/fixing the issue.

The only solution I have now is to change it to localhost which then returns ORA-01017: invalid username/password; logon denied or remove the "Test 7" - "Test 10" completely. Not sure if the tests makes sense then, also, it can fail in other CI environments then.

cmb69 · 2022-09-12T14:15:27Z

@mvorisek, have you tried something like anything?connect_timeout=60&transport_connect_timeout=30?

mvorisek · 2022-09-12T14:24:24Z

@mvorisek, have you tried something like anything?connect_timeout=60&transport_connect_timeout=30?

I will once the previous tests finish (they take like 3h / commit, later, I optimized them to test OCI8 ext only).

My question to you it, what shoult this solve?

a) the timeouts are random, shouldn't we first confirm if such insane behavior is valid, even with stable DNS names like x.cz (resolves to empty host).
b) if we will add timeout config, do we still test the same behaviour? with this, CI will be producing two type of results (can be adjusted), but the long random timeouts will be kept (to the configured timeout) :)

So if we cannot find the real issue, I am more inclined to remove (comment out) these tests for now.

mvorisek · 2022-09-12T17:37:09Z

@mvorisek, have you tried something like anything?connect_timeout=60&transport_connect_timeout=30?

@cmb69 tried - https://github.com/php/php-src/actions/runs/3039225236/jobs/4893908509#step:11:224 - has no effect

This reverts commit 77663d2.

This reverts commit 0a9dc03.

mvorisek · 2022-09-12T20:35:45Z

I was able to reproduce the problem in CI /w strace: https://github.com/mvorisek/php-src/actions/runs/3039764841/jobs/4895065748

relevant logs:

strace-short-timeout.txt

strace-long-timeout.txt

@cjbj can you please check the snlinGetAddrInfo libclntsh.so code?

a) it seems the Oracle Instant Client is looping massively when resolving the host
b) in the 2nd log, search for first "Timeout" (l26855) and notice, the looping continues, but with ~5 secs delays - this is the cause of connect sometimes taking randomly ~200 secs (instead of < 1 sec, even for exactly the same host).

The Oracle Instant Client has probably some condition in the code wrong.

Code to reproduce: just php -r 'oci_new_connect("/", "", "anything", null, OCI_CRED_EXT);' and luck - rerun in loop until you hit the problem (the elapsed time is > 10 secs)

mvorisek · 2022-09-12T22:36:14Z

@cmb69 PR done, the 3 extauth tests cannot be fixed, they need to be skipped until the Oracle Instant Client is fixed. Tested with hundreds of CI runs, this PR fixes the random CI failures. Before merge, please squash the changes into one commit.

cmb69 · 2022-09-13T12:28:11Z

Thank you!

cjbj · 2022-09-16T07:32:59Z

@cjbj can you please check the snlinGetAddrInfo libclntsh.so code?

I'll point our network people at this and let the experts discuss it.

Thanks for all your work on this PR.

cjbj · 2022-09-19T02:01:48Z

@cjbj can you please check the snlinGetAddrInfo libclntsh.so code?

I'll point our network people at this and let the experts discuss it.

@mvorisek The reply is "The looping and timeout behavior would depend on the setting in /etc/resolv.conf. Here it looks like the default timeout is 5 seconds and there might be multiple DNS servers specified so after each timeout the next DNS host would be tried. The content of resolv.conf can be seen to verify the number of dns servers. All the looping would be inside getaddrinfo call."

mvorisek · 2022-09-19T22:16:37Z

5 second timeout is expected. But what I have experienced, and the logs shows it as well, is massive looping/retries with ~200 seconds timeout total.

According to the https://man7.org/linux/man-pages/man5/resolver.5.html there should be 2 retries per DNS server by default. With 3 DNS servers, this will imply 5 x 2 x 3 = 30 seconds timeout. Maybe GH Actions has some special configuration or resolv patched for less failures, but I doubt so.

@cjbj Is the Oracle Instant Client really calling the getaddrinfo no more than once?

cjbj · 2022-09-21T23:30:31Z

@mvorisek how long does nslookup take in that environment? You could turn on Oracle network tracing to check if snlinGetAddrInfo is being called multiple times. (Ping me if you need steps). Our net team say it's basically a DNS setup issue as DNS lookup shouldn't hang.

mvorisek added 3 commits September 11, 2022 23:45

unify tests before fix

a19447f

use real host to prevent timeouts

323e144

DEBUG run 2x 20 tests

1ed7cc9

mvorisek marked this pull request as draft September 11, 2022 22:17

DEBUG increase testing timeout

b2246cb

mvorisek commented Sep 11, 2022

View reviewed changes

mvorisek added 10 commits September 12, 2022 01:44

Revert "DEBUG run 2x 20 tests"

ef6ce31

This reverts commit 1ed7cc9.

use "mysql" host instead

f1544b0

use "anything.invalid" host

c131cc6

Revert "DEBUG increase testing timeout"

76af0fc

This reverts commit b2246cb.

DEBUG run 2x 20 tests

77663d2

DEBUG increase testing timeout

9e74767

DEBUG verify original issue is reproducible

9c2b696

use "mysql" host instead

7904827

use "sql1" host (MSSQL docker) everywhere

015bdb7

use "x.cz" host (domain must be at least 2 chars) everywhere

8af58b0

mvorisek commented Sep 12, 2022

View reviewed changes

mvorisek added 4 commits September 12, 2022 10:00

DEBUG test only 'bcmath', 'oci8', 'pdo_oci' ext tests and 1 proc only

466ba80

DEBUG dump individual times, rm slow tests

e2147d4

DEBUG run all tests 4x

8ca49a6

DEBUG fail + dump delay on 10+ secs

4b93033

use "sql1" host (MSSQL docker) everywhere

a11bf80

anything?connect_timeout=60&transport_connect_timeout=30

d86f02b

mvorisek added 5 commits September 12, 2022 19:43

anything?connect_timeout=6&transport_connect_timeout=3

30786fe

Revert "DEBUG run 2x 20 tests"

0a9dc03

This reverts commit 77663d2.

strace extauth test

6e2bb7e

Revert "Revert "DEBUG run 2x 20 tests""

f509e38

This reverts commit 0a9dc03.

ltrace -fS

a0ab112

mvorisek force-pushed the fix_extauth_tests branch from 549248d to a0ab112 Compare September 12, 2022 18:46

strace -k

a5fc4e9

mvorisek added 2 commits September 12, 2022 22:45

revert all

bad6503

skip the problematic extauth_xx.phpt tests

474c6d7

mvorisek marked this pull request as ready for review September 12, 2022 20:49

the tests are not slow

7f5a754

mvorisek changed the title ~~Fix OCI8 extauth tests~~ Always skip randomly failing OCI8 extauth tests Sep 12, 2022

cmb69 closed this in 9a73ec0 Sep 13, 2022

mvorisek deleted the fix_extauth_tests branch September 13, 2022 13:59

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Always skip randomly failing OCI8 extauth tests #9524

Always skip randomly failing OCI8 extauth tests #9524

mvorisek commented Sep 11, 2022

mvorisek Sep 11, 2022 •

edited

Loading

mvorisek Sep 12, 2022

mvorisek Sep 12, 2022

cmb69 commented Sep 12, 2022

mvorisek commented Sep 12, 2022 •

edited

Loading

cjbj commented Sep 12, 2022

cjbj commented Sep 12, 2022

mvorisek commented Sep 12, 2022

cmb69 commented Sep 12, 2022

mvorisek commented Sep 12, 2022

mvorisek commented Sep 12, 2022

mvorisek commented Sep 12, 2022 •

edited

Loading

mvorisek commented Sep 12, 2022 •

edited

Loading

cmb69 commented Sep 13, 2022

cjbj commented Sep 16, 2022

cjbj commented Sep 19, 2022

mvorisek commented Sep 19, 2022

cjbj commented Sep 21, 2022

Always skip randomly failing OCI8 extauth tests #9524

Always skip randomly failing OCI8 extauth tests #9524

Conversation

mvorisek commented Sep 11, 2022

mvorisek Sep 11, 2022 • edited Loading

Choose a reason for hiding this comment

mvorisek Sep 12, 2022

Choose a reason for hiding this comment

mvorisek Sep 12, 2022

Choose a reason for hiding this comment

cmb69 commented Sep 12, 2022

mvorisek commented Sep 12, 2022 • edited Loading

cjbj commented Sep 12, 2022

cjbj commented Sep 12, 2022

mvorisek commented Sep 12, 2022

cmb69 commented Sep 12, 2022

mvorisek commented Sep 12, 2022

mvorisek commented Sep 12, 2022

mvorisek commented Sep 12, 2022 • edited Loading

mvorisek commented Sep 12, 2022 • edited Loading

cmb69 commented Sep 13, 2022

cjbj commented Sep 16, 2022

cjbj commented Sep 19, 2022

mvorisek commented Sep 19, 2022

cjbj commented Sep 21, 2022

mvorisek Sep 11, 2022 •

edited

Loading

mvorisek commented Sep 12, 2022 •

edited

Loading

mvorisek commented Sep 12, 2022 •

edited

Loading

mvorisek commented Sep 12, 2022 •

edited

Loading