Closed venkat-kasula closed 2 years ago
Seems like there is a general problem with Oracle on AWS. This is very hard to test, because I don't have an Oracle on AWS instance.
@pesse I don't think it's a general AWS related issue. I have a customer who's using the utPLSQL CLI connecting to AWS instances. No issues AFAIK.
Thanks for that information. Can you reach out to them and ask for their combination of jdbc driver/java version etc?
I can find out next week. Will update this issue then.
I've seen similar issues in AWS and we managed to get around them. It's related to java and connection security I think. Not sure if this is exactly same issue but can you try those solutions? https://stackoverflow.com/a/49775784
Oh, this is an awesome hint, @jgebal ! A timeout is exactly what's happening, we are just aborting after 2 seconds.
@venkat-kasula can you access the file $JAVA_HOME/jre/lib/security/java.security
and change securerandom.source=file:/dev/random
to securerandom.source=file:/dev/urandom
?
Alternatively it should be possible to pass the necessary JVM arguments with setting the following environment variable:
export JAVA_TOOL_OPTIONS='-Djava.security.egd=file:/dev/./urandom -Dsecurerandom.source=file:/dev/./urandom'
The error we saw was:
Caused by: java.sql.SQLException: Unable to start the Universal Connection Pool: oracle.ucp.UniversalConnectionPoolException: Cannot get Connection from Datasource: java.sql.SQLRecoverableException: IO Error: Connection reset by peer, Authentication lapse 185481 ms.
This kind of error would result in the "Detected Oracle driver stuck" generic error in CLI, because we abort the connection before we hit the timeout.
I tried to add a User env variable JAVA_TOOL_OPTIONS and tried to re-exeute.
i did face below issue
2021-01-28 15:29:06 [main] INFO org.utplsql.cli.RunAction -
2021-01-28 15:29:13 [main] INFO o.u.c.d.TestedDataSourceProvider - Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
2021-01-28 15:29:18 [main] INFO org.utplsql.cli.RunAction - Successfully connected to database. UtPLSQL core: v3.1.10.3349
2021-01-28 15:29:19 [main] INFO org.utplsql.cli.RunAction - Oracle-Version: 18.0.0.0.0
2021-01-28 15:30:49 [main] DEBUG org.utplsql.api.reporter.Reporter - Database-reporter initialized, Type: UT_COVERAGE_HTML_REPORTER, ID: B9F3F5BFBF7B0958E0530100007F432E
java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation
at oracle.jdbc.driver.T2CConnection.checkError(T2CConnection.java:1168)
at oracle.jdbc.driver.T2CConnection.checkError(T2CConnection.java:1065)
at oracle.jdbc.driver.T2CCallableStatement.executeForDescribe(T2CCallableStatement.java:764)
at oracle.jdbc.driver.T2CCallableStatement.executeForRows(T2CCallableStatement.java:1007)
at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1205)
at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3666)
at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3778)
at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4251)
at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1081)
at org.utplsql.api.outputBuffer.OutputBufferProvider.hasOutput(OutputBufferProvider.java:67)
at org.utplsql.api.outputBuffer.OutputBufferProvider.getCompatibleOutputBuffer(OutputBufferProvider.java:33)
at org.utplsql.api.compatibility.CompatibilityProxy.getOutputBuffer(CompatibilityProxy.java:187)
at org.utplsql.api.reporter.DefaultReporter.initOutputBuffer(DefaultReporter.java:21)
at org.utplsql.api.reporter.Reporter.init(Reporter.java:50)
at org.utplsql.cli.reporters.LocalAssetsCoverageHTMLReporter.init(LocalAssetsCoverageHTMLReporter.java:30)
at org.utplsql.cli.ReporterManager.initReporters(ReporterManager.java:95)
at org.utplsql.cli.RunAction.initReporters(RunAction.java:219)
at org.utplsql.cli.RunAction.doRun(RunAction.java:70)
at org.utplsql.cli.RunAction.run(RunAction.java:121)
at org.utplsql.cli.RunPicocliCommand.run(RunPicocliCommand.java:254)
at org.utplsql.cli.Cli.runPicocliWithExitCode(Cli.java:44)
at org.utplsql.cli.Cli.main(Cli.java:13)
Caused by: Error : 1013, Position : 0, Sql = declare l_result int;begin begin execute immediate ' begin :x := case ' || dbms_assert.simple_sql_name( :1 ) || '() is of (ut_output_reporter_base) when true then 1 else 0 end; end;' using out l_result; end; :2 := l_result;end;, OriginalSql = declare l_result int;begin begin execute immediate ' begin :x := case ' || dbms_assert.simple_sql_name( ? ) || '() is of (ut_output_reporter_base) when true then 1 else 0 end; end;' using out l_result; end; ? := l_result;end;, Error Msg = ORA-01013: user requested cancel of current operation
at oracle.jdbc.driver.T2CConnection.checkError(T2CConnection.java:1181)
... 21 more
Did you try it with a different (non-coverage) reporter? Also - there should be a message of JVM picking up the JAVA_TOOL_OPTIONS values...
i did not try with any other non - coverage reporter tool . Any specific report you want to run and verify???
After setting up the Variable, i ran in debug mode and shared the complete log here. But one thing i observed is it did not go into retry loop 4 times. That's the difference i observed when i executed after setting up the JAVA_TOOL_OPTIONS.
UT_DOCUMENTATION_REPORTER would be a good start
utplsql run /@host:1521/ORCL -p=venkat.ut_add_contestant -f=ut_documentation_reporter -o=run.log -s
I tried and got below connection error.
Picked up JAVA_TOOL_OPTIONS: -Djava.security.egd=file:/dev/./urandom -Dsecurerandom.source=file:/dev/./urandom
############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
jdbc:oracle:oci8:****/****@host:1521/ORCL: ORA-12546: TNS:permission denied
`jdbc:oracle:thin:****/****@10.114.97.90:1521/ORCL:` IO Error: The Network Adapter could not establish the connection
Could not establish connection to database. Reason: IO Error: The Network Adapter could not establish the connection``
ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9
That doesn't look like it's running on a linux system 🤔
i m using windows machine to run it on my local.. is this is the issue ?
You have AWS RDS instance on your local machine? Setting Java's secureRandomFile to /dev/urandom on a Windows machine will not work - I thought you were experiencing the problems on an AWS instance (which I think runs on RH Linux, but I can be wrong)
But one thing i observed is it did not go into retry loop 4 times. That's the difference i observed when i executed after setting up the JAVA_TOOL_OPTIONS.
Unfortunately the "User requested cancel operation" happened before we would even get to the Stuck handling (during reporter initialization), so this looks like a new, probably unrelated issue and doesn't tell us anything about the retry/stuck problem.
It would be very helpful if you could state as precisely as possible what you do, whether something is reproducable and on which system environment you are experiencing it.
I dont hvae AWS RDS Instance on my local. It was provided by my manager for testing purpose. so i got the user access to it & connecting it via SQL developer (18.4.0.376) like any other oracle instance using user name and password.
Note: i was using the windows 10 machine
Below are the ones which i have done.
Okay, so you are connecting from a windows 10 machine to the AWS instance. Thanks for clarifying :) In that case, drop the JAVA_TOOL_OPTIONS - they will not help, on windows even prevent connection (because there is no /dev/urandom on windows). Can you provide the log of the following run against your AWS instance (without JAVA_TOOL_OPTIONS)?
utplsql run /@host:1521/ORCL -p=venkat.ut_add_contestant -d -f=ut_documentation_reporter -o=run.log -s
You have no space between "ORCL" and "-p=venkat"...
I have the executed the script and below are the logs generated.
Note:
############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
Successfully connected to database. UtPLSQL core: v3.1.10.3349
Oracle-Version: 18.0.0.0.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.10.3349
Initializing reporters
Detected Oracle driver stuck during Statement initialization
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)
############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
Successfully connected to database. UtPLSQL core: v3.1.10.3349
Oracle-Version: 18.0.0.0.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.10.3349
Initializing reporters
Detected Oracle driver stuck during Statement initialization
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (2)
############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
Successfully connected to database. UtPLSQL core: v3.1.10.3349
Oracle-Version: 18.0.0.0.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.10.3349
Initializing reporters
Detected Oracle driver stuck during Statement initialization
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (3)
############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
Successfully connected to database. UtPLSQL core: v3.1.10.3349
Oracle-Version: 18.0.0.0.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.10.3349
Initializing reporters
Detected Oracle driver stuck during Statement initialization
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (4)
Hey @venkat-kasula , it seems like you didn't add the -d
for debug. What I'm trying to see is what happens before the statement, therefore I need the logs with debug information.
Please find the execution logs of the command "utplsql run -d /@10.114.97.90:1521/ORCL -p=venkat.ut_add_contestant -f=ut_documentation_reporter -o=run.log -s"
2021-01-29 14:38:26 [main] INFO org.utplsql.cli.RunAction - ############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
2021-01-29 14:38:26 [main] INFO org.utplsql.cli.RunAction -
2021-01-29 14:38:29 [main] INFO o.u.c.d.TestedDataSourceProvider - Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
2021-01-29 14:38:33 [main] INFO org.utplsql.cli.RunAction - Successfully connected to database. UtPLSQL core: v3.1.10.3349
2021-01-29 14:38:34 [main] INFO org.utplsql.cli.RunAction - Oracle-Version: 18.0.0.0.0
2021-01-29 14:39:00 [main] DEBUG org.utplsql.api.reporter.Reporter - Database-reporter initialized, Type: UT_DOCUMENTATION_REPORTER, ID: BA075AA9169A190AE0530100007FF3CF
2021-01-29 14:39:02 [pool-1-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - Running tests now.
2021-01-29 14:39:02 [pool-1-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - --------------------------------------
2021-01-29 14:39:02 [pool-1-thread-1] INFO org.utplsql.api.TestRunner - TestRunner initialized
2021-01-29 14:39:03 [pool-1-thread-1] INFO org.utplsql.api.TestRunner - Running on utPLSQL v3.1.10.3349
2021-01-29 14:39:03 [pool-1-thread-1] INFO org.utplsql.api.TestRunner - Initializing reporters
2021-01-29 14:39:05 [pool-1-thread-1] ERROR org.utplsql.api.TestRunner - Detected Oracle driver stuck during Statement initialization
2021-01-29 14:40:12 [main] WARN org.utplsql.cli.RunAction - WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)
2021-01-29 14:40:12 [main] INFO org.utplsql.cli.RunAction - ############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
2021-01-29 14:40:12 [main] INFO org.utplsql.cli.RunAction -
2021-01-29 14:40:14 [main] INFO o.u.c.d.TestedDataSourceProvider - Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
2021-01-29 14:40:17 [main] INFO org.utplsql.cli.RunAction - Successfully connected to database. UtPLSQL core: v3.1.10.3349
2021-01-29 14:40:18 [main] INFO org.utplsql.cli.RunAction - Oracle-Version: 18.0.0.0.0
2021-01-29 14:40:44 [main] DEBUG org.utplsql.api.reporter.Reporter - Database-reporter initialized, Type: UT_DOCUMENTATION_REPORTER, ID: BA0760DF49321A97E0530100007F0970
2021-01-29 14:40:47 [pool-4-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - Running tests now.
2021-01-29 14:40:47 [pool-4-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - --------------------------------------
2021-01-29 14:40:47 [pool-4-thread-1] INFO org.utplsql.api.TestRunner - TestRunner initialized
2021-01-29 14:40:47 [pool-4-thread-1] INFO org.utplsql.api.TestRunner - Running on utPLSQL v3.1.10.3349
2021-01-29 14:40:47 [pool-4-thread-1] INFO org.utplsql.api.TestRunner - Initializing reporters
2021-01-29 14:40:49 [pool-4-thread-1] ERROR org.utplsql.api.TestRunner - Detected Oracle driver stuck during Statement initialization
2021-01-29 14:41:58 [main] WARN org.utplsql.cli.RunAction - WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (2)
2021-01-29 14:41:58 [main] INFO org.utplsql.cli.RunAction - ############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
2021-01-29 14:41:58 [main] INFO org.utplsql.cli.RunAction -
2021-01-29 14:42:00 [main] INFO o.u.c.d.TestedDataSourceProvider - Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
2021-01-29 14:42:03 [main] INFO org.utplsql.cli.RunAction - Successfully connected to database. UtPLSQL core: v3.1.10.3349
2021-01-29 14:42:04 [main] INFO org.utplsql.cli.RunAction - Oracle-Version: 18.0.0.0.0
2021-01-29 14:42:29 [main] DEBUG org.utplsql.api.reporter.Reporter - Database-reporter initialized, Type: UT_DOCUMENTATION_REPORTER, ID: BA07672AC0C21B3BE0530100007F45D2
2021-01-29 14:42:35 [pool-7-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - Running tests now.
2021-01-29 14:42:35 [pool-7-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - --------------------------------------
2021-01-29 14:42:35 [pool-7-thread-1] INFO org.utplsql.api.TestRunner - TestRunner initialized
2021-01-29 14:42:39 [pool-7-thread-1] INFO org.utplsql.api.TestRunner - Running on utPLSQL v3.1.10.3349
2021-01-29 14:42:39 [pool-7-thread-1] INFO org.utplsql.api.TestRunner - Initializing reporters
2021-01-29 14:42:41 [pool-7-thread-1] ERROR org.utplsql.api.TestRunner - Detected Oracle driver stuck during Statement initialization
2021-01-29 14:43:48 [main] WARN org.utplsql.cli.RunAction - WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (3)
2021-01-29 14:43:48 [main] INFO org.utplsql.cli.RunAction - ############################## utPLSQL cli ##############################
# #
# utPLSQL-cli 3.1.8-SNAPSHOT.local #
# utPLSQL-java-api 3.1.8.546 #
# Java-Version: 1.8.0_121 #
# ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9 #
# NLS_LANG: null #
# #
# Thanks for testing! #
# #
#########################################################################
2021-01-29 14:43:48 [main] INFO org.utplsql.cli.RunAction -
2021-01-29 14:43:51 [main] INFO o.u.c.d.TestedDataSourceProvider - Use connection string jdbc:oracle:oci8:****/****@10.114.97.90:1521/ORCL
2021-01-29 14:43:56 [main] INFO org.utplsql.cli.RunAction - Successfully connected to database. UtPLSQL core: v3.1.10.3349
2021-01-29 14:43:57 [main] INFO org.utplsql.cli.RunAction - Oracle-Version: 18.0.0.0.0
2021-01-29 14:44:27 [main] DEBUG org.utplsql.api.reporter.Reporter - Database-reporter initialized, Type: UT_DOCUMENTATION_REPORTER, ID: BA076E2E81371C3EE0530100007F8974
2021-01-29 14:44:34 [pool-10-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - Running tests now.
2021-01-29 14:44:34 [pool-10-thread-1] INFO org.utplsql.cli.RunTestRunnerTask - --------------------------------------
2021-01-29 14:44:34 [pool-10-thread-1] INFO org.utplsql.api.TestRunner - TestRunner initialized
2021-01-29 14:44:35 [pool-10-thread-1] INFO org.utplsql.api.TestRunner - Running on utPLSQL v3.1.10.3349
2021-01-29 14:44:35 [pool-10-thread-1] INFO org.utplsql.api.TestRunner - Initializing reporters
2021-01-29 14:44:37 [pool-10-thread-1] ERROR org.utplsql.api.TestRunner - Detected Oracle driver stuck during Statement initialization
2021-01-29 14:45:43 [main] WARN org.utplsql.cli.RunAction - WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (4)
Thanks. This is strange, because it happens at a totally different place. The reporters don't even get initialized. I'll try to prepare an updated version of CLI with more detailed reporting and would be glad if you could try it again and share information.
Sure .. please let me know when i can try again , so that i can give it a shot.
I will move this to the utPLSQL-cli project
@pesse Sure, once done committing, please do let me know, so that i can try again and share the result
Hi. I reproduce randomly this problem against AWS server. I reproduce this using both utPLSQL-cli and utplsql-maven-plugin.
I have found that TestRunner.initStatementWithTimeout method in utPLSQL-java-api has a hardcoded timeout of 2 seconds.
If I increase the timeout, the problem dissapears and all works right.
Could I parameterize that timeout and open a pull-request?
Absolutely!
Works fine for me too! :-) Thank you.
Is there any update on this issue . We are also facing the same issue of time out. The solution what ever is given of changing the parameter TestRunner.initStatementWithTimeout to more than 2 , we could not do as it is a jar file java-api. Where do we give this value ?
@pesse - is there a chance to make a new release of cli and java-api, where we:L
@pesse - is there a chance to make a new release of cli and java-api, where we:L
- increase default timeout
- make the timeout a parameter
I'm on it
I will work on java-api and cli tonight, trying to create a new Release.
The timeout was originally introduced to work around a problem with Oracle 11g. I will leave it in, but as an opt-in option via parameter (where you can also set the time). New Default-behaviour will be without that timeout.
@francisco-palma-m sorry if that interrupts your efforts. If you'd like to, it would be awesome if you could step into development of java-api and cli, since my focus and time budget keep being very limited.
I will work on java-api and cli tonight, trying to create a new Release.
The timeout was originally introduced to work around a problem with Oracle 11g. I will leave it in, but as an opt-in option via parameter (where you can also set the time). New Default-behaviour will be without that timeout.
@francisco-palma-m sorry if that interrupts your efforts. If you'd like to, it would be awesome if you could step into development of java-api and cli, since my focus and time budget keep being very limited.
Ok. No problem, but it's necessary create a new release on utplsql-maven-plugin that use the new timeout parameter.
Ok. No problem, but it's necessary create a new release on utplsql-maven-plugin that use the new timeout parameter.
@francisco-palma-m can you take care of the maven-plugin after I change java-api?
Ok. No problem, but it's necessary create a new release on utplsql-maven-plugin that use the new timeout parameter.
@francisco-palma-m can you take care of the maven-plugin after I change java-api?
@pesse Of course
Thanks for the release . the timeout issue is gone now .
Describe the bug Hi All, I m using the AWS RDS oracle instance currently for trying out the UTPLSQL POC demo. When i m trying out in the UTPLSQL CLI, using command "utplsql run/@host:1521/ORCL -p=venkat.ut_add_contestant -f=ut_coverage_html_reporter -o=run.log -s -f=ut_coverage_html_reporter -o=coverage1.html"
while generating report, my execution is terminated after 4 retries. I m getting error as "Detected Oracle driver stuck during Statement initialization
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)"
Information about client software I m using the UTPLSQL CLI for execution and using odjbc8.jar and orai18n.jar 19.9.0.0
Kindly help me in resolving the issue.