UTPLSQL CLI Error: Detected Oracle driver stuck during Statement initialization after 4 retries and Erro

[venkat-kasula]

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)"

`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:****/****@host: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)`

**Provide version info**

> 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!

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.

[pesse]

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.

#145

[PhilippSalvisberg]

@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.

[pesse]

Thanks for that information. Can you reach out to them and ask for their combination of jdbc driver/java version etc?

[PhilippSalvisberg]

I can find out next week. Will update this issue then.

[jgebal]

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

[pesse]

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'

[jgebal]

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.

[pesse]

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.

[venkat-kasula]

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

[pesse]

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...

[venkat-kasula]

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.

[pesse]

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

[venkat-kasula]

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``

[pesse]

ORACLE_HOME: C:\Users\a622231\Pictures\SQLPLUS\instantclient_19_9

That doesn't look like it's running on a linux system 🤔

[venkat-kasula]

i m using windows machine to run it on my local.. is this is the issue ?