java.sql.SQLRecoverableException: No more data to read from socket

I get the following error when running tests using utplsql-cli:

java.sql.SQLRecoverableException: No more data to read from socket
	at oracle.jdbc.driver.T4CMAREngineNIO.prepareForReading(T4CMAREngineNIO.java:119)
	at oracle.jdbc.driver.T4CMAREngineNIO.unmarshalUB1(T4CMAREngineNIO.java:534)
	at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:485)
	at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252)
	at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612)
	at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:223)
	at oracle.jdbc.driver.T4CCallableStatement.doOall8(T4CCallableStatement.java:56)
	at oracle.jdbc.driver.T4CCallableStatement.executeForRows(T4CCallableStatement.java:907)
	at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1119)
	at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3780)
	at oracle.jdbc.driver.T4CCallableStatement.executeInternal(T4CCallableStatement.java:1300)
	at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3887)
	at oracle.jdbc.driver.OracleCallableStatement.execute(OracleCallableStatement.java:4230)
	at oracle.jdbc.driver.OraclePreparedStatementWrapper.execute(OraclePreparedStatementWrapper.java:1079)
	at io.github.utplsql.api.TestRunner.run(TestRunner.java:144)
	at io.github.utplsql.cli.RunCommand.lambda$run$0(RunCommand.java:141)
	at io.github.utplsql.cli.RunCommand$$Lambda$7/1647809929.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

The trouble is, the utplsql-cli does not stop/throw.
It seems to be stuck, doing nothing.

This leads to two potential problems:

Exceptions are not handled properly and the cli is doing nothing
timeout for getting data from output buffer is set to a low (too low) value.
Single test can run for quite some time.

@jgebal

@jgebal experienced this issue at any time since 3.0.4 version?

We're using the most recent version 3.1.2 in a custom docker container (alpine based). About one in 25 calls (in a loop, each iteration using a freshly initialized container) get's blocked and only after waiting one full hour get's terminated eventually.

The utplsql command generates no output at all in these (rare) cases.

Furthermore, as already mentioned the exception/error exit code, due to the timeout seems to get lost on the way. Our call does get exit-code zero even after such a timeout. Therefore only the missing output (and the delay) can be used a indirect means of error handling...

Any progress avoiding this blockade and/or at least a proper error escalation in case it can't be avoided would be greatly appreciated.

@c0dw

Hi @c0dw ,

are you using Oracle 11.2?
We have identified similar issues with a 11.2 setup (see #98)

Samuel

@pesse

Hi @pesse
No, we're running the utplsql Framework (serverside) on Oracle 12 (Enterprise Edition) and from using 'lsof' I know the utplsql cli uses a version 12 jdbc driver on client side as well:

/mnt/workspace # lsof -p 24
...
/opt/jdk1.8.0_141/bin/java	/opt/utPLSQL-cli/lib/ojdbc8-12.2.0.1.jar
...

I'll soon have a new version of cli ready with logging possibilities - I would then aks you to try it with this new version and provide the logs, if possible

Absolutely! I look forward to verify the new version, thanks!
BTW, in case you're still open to feature suggestions for the new version: IMHO it would also help if the timeout were not hardcoded to 60 minutes, but could be customized when invoking utplsql depending on the expected runtime of the test. Our unittests usually take no langer than 1 or 2 minutes.

That's a good point - want to make an issue for it?
It's actually not much work to include that.

OK, done! -> configurable timeout #124
... and many thanks for your swift response!

@c0dw

Hey @c0dw , can you try to reproduce it with this version of cli?
https://bintray.com/utplsql/utPLSQL-cli/download_file?file_path=utPLSQL-cli-develop-201902142127.zip

use
utplsql run user/pw@connectstring -d
for debug output

@pesse

Hi @pesse
I built a new Dockerimage with the utplsqlcli version 201902142127 you provided and tried to reproduce the bug while using the debug flag. It did not happen. After 100 successful iterations I broke out of the loop. For reference I include the debug output of the last iteration here anyway. And FYI, at the end I listed the invoking loop

iteration100.txt

After that, I tried to reproduce the error again with the official release Version 3.1.2 of utplsqlcli. It also took significantly more iterations until the error occured: More than 70 iterations in a first pass and 56 iterations in the second attempt. As you can see iteration 56 took one hour (3603 seconds) to timeout and it produced no log (zero lines in srqoauth2_doc.log). In the shebang of the script I set the '-e' flag to cause immediate termination in case of an error, which obviously never made it up the callstack...

15.02.2019 12:42:29 - Iteration 50, duration 6 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 12:42:37 - Iteration 51, duration 5 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 12:42:46 - Iteration 52, duration 6 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 12:42:54 - Iteration 53, duration 5 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 12:43:03 - Iteration 54, duration 6 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 12:43:11 - Iteration 55, duration 5 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 13:43:17 - Iteration 56, duration 3603 seconds, number of output-lines: 0 target/srqoauth2_doc.log
15.02.2019 13:43:26 - Iteration 57, duration 6 seconds, number of output-lines: 24 target/srqoauth2_doc.log
15.02.2019 13:43:34 - Iteration 58, duration 5 seconds, number of output-lines: 24 target/srqoauth2_doc.log

I managed to enter the running Docker container and took a threaddump with jstack, if this is any help understanding the problem:

jstack_threaddump.txt

I will try again to reproduce the failure and collect debugging info using your working version 201902142127. Next time I will be more patient and wait for more than 100 iterations just to be sure, the error does indeed not occur anymore.

@c0dw

thanks a lot for your thorough analysis, @c0dw
We did some tweaks in the newer version, too, so it might be that the main problem is resolved.

That's the least I can do!
Meanwhile I switched back to the utplsqlcli working version 201902142127 and started a new session expecting it to keep running smoothly all day and next night. (Note to self: Stop expecting!)

As a matter of fact, it happend already in Iteration 17, this time I can provide the full debug log and for comparison the one before (iteration16), where all was well:

Iteration16-16_DEBUG.txt

As you can see, the process is stuck while 'Initializing reporters'. I get one line of output every 30 seconds stating...
2019-02-15 14:25:23 [HikariPool-1 housekeeper] DEBUG com.zaxxer.hikari.pool.HikariPool - HikariPool-1 - Pool stats (total=3, active=3, idle=0, waiting=0)

...and here is the according jstack threaddump of the utplsqlcli again:
jstack_threaddump_utplsqlcli201902142127.txt

@pesse

Hi @pesse

Please let me know, if I can contribute anything else to resolve this blocking issue. Apparently it persists in the development snapshot 201902142127 you provided, as outlined in my last posting.

I'd also like to point out, we still face the additional problem, that the timeout does not trigger a proper error escalation. I still don't get an exitcode after a timeout. My java skills are slightly rusty - so correct me if I'm wrong, but from your code (lines 203-209) I understand you're using java.util.concurrent.ExecutorService.shutdown() which causes an orderly shutdown and after that in line 209 you return 'returnCode[0]' which I suppose is initialized to literally zero as well. Therefore an invoking process does not get notified, that an irregular termination (due to a timeout) occurred, which makes error handling cumbersome. IMHO a timeout should push an error/exception up the call-stack.
Update: I digged a little deeper and I think the solution is using the return Value of the awaitTermination Method to determine the returnValue of your own function, like ...

if (!executorService.awaitTermination(timeoutInMinutes, TimeUnit.MINUTES)) {
        returnCode[0] = 1; // or whatever exitcode you might assign a timeout - except zero!
}

According to the API doc awaitTermination() returns true if this executor terminated and false if the timeout elapsed before termination.

@c0dw

Hi @c0dw

Can you open a seperate issue for the timeout not causing an error? I agree that a timeout should throw an exception and be visible from the outside.

As for the other issue: The most problematic thing is that we were not able to reproduce the issue yet. What you could help with is to investigate (maybe together with your DBA) which SQL statement is executed (or was executed last) in the case of a block.
I suspect it's the same as in #98, which means that this problem is not limited to 11g.

I will probably add some more log messages, too and come back with a new version.

I'd also like to ask you for patience because utPLSQL is a 100% leisure time project, nobody gets anything paid for it and we do it in our free time on evenings besides our normal day jobs. Therefore complicated issues like this can be very challenging.

@c0dw

@c0dw @SebGt Could you please both try the following develop-version of cli?
https://bintray.com/utplsql/utPLSQL-cli/download_file?file_path=utPLSQL-cli-develop-201903142211.zip
There should be no stuck anymore.
In case of the previously stuck-situation, there should be now a log-message like
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)

@pesse

@pesse, thanks. I will test it today and I give my feedback asap.

@pesse

@pesse, All my tests (around 30 different set of tests) were all passing this morning.
Thank you very much to have fixed this issue.

I will see the next days if it is confirmed but I have no doubt

Great! Thanks for the feedback.
Did you see this line?
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)

No but I did not check all outputs. I will if it can help you.

If you could check it would be great because it means the (suspected) Oracle bug still occurs but is caught reliably (which is a far better message than the Oracle bug we tried to catch didn't occur for whatever reason during x runs)

@pesse

@pesse, none of my executions (~20 Jenkins jobs) displayed a warning.
They are all like that :

Successfully connected to database. UtPLSQL core: v3.1.3.2402
Oracle-Version: 11.2.0.4.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.3.2402
Initializing reporters
Running tests
Running tests finished.
--------------------------------------

I will check next week.

@pesse

Hi @pesse, most of my tests ran without any issues today. Only one had the warning message twice time. Between the 2 runs with the warning I had other runs of the test without issues

First one:

##################### utPLSQL cli #####################
#                                                     #
#   utPLSQL-cli 3.1.3-SNAPSHOT.local                  #
#   utPLSQL-java-api 3.1.3-SNAPSHOT.390               #
#   Java-Version: 1.8.0_191                           #
#   ORACLE_HOME: \\Programs\ORACLE                    #
#   NLS_LANG: null                                    #
#                                                     #
#   Thanks for testing!                               #
#                                                     #
#######################################################

Use connection string jdbc:oracle:thin:****/****@dev_xxx.WORLD
Successfully connected to database. UtPLSQL core: v3.1.3.2402
Oracle-Version: 11.2.0.4.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.3.2402
Initializing reporters
Detected Oracle driver stuck during Statement initialization
HikariPool-1 - Connection oracle.jdbc.driver.T4CConnection@6c49835d marked as broken because of SQLSTATE(08003), ErrorCode(17008)
java.sql.SQLRecoverableException: Closed Connection
	at oracle.jdbc.driver.PhysicalConnection.clearWarnings(PhysicalConnection.java:2573)
	at com.zaxxer.hikari.pool.ProxyConnection.close(ProxyConnection.java:249)
	at org.utplsql.cli.ReporterManager.lambda$startReporterGatherers$0(ReporterManager.java:130)
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
HikariPool-1 - Connection oracle.jdbc.driver.T4CConnection@7d523fbc marked as broken because of SQLSTATE(08003), ErrorCode(17008)
java.sql.SQLRecoverableException: Closed Connection
	at oracle.jdbc.driver.PhysicalConnection.clearWarnings(PhysicalConnection.java:2573)
	at com.zaxxer.hikari.pool.ProxyConnection.close(ProxyConnection.java:249)
	at org.utplsql.cli.ReporterManager.lambda$startReporterGatherers$0(ReporterManager.java:130)
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
HikariPool-1 - Connection oracle.jdbc.driver.T4CConnection@5081ad32 marked as broken because of SQLSTATE(08003), ErrorCode(17008)
java.sql.SQLRecoverableException: Closed Connection
	at oracle.jdbc.driver.PhysicalConnection.prepareCall(PhysicalConnection.java:1708)
	at oracle.jdbc.driver.PhysicalConnection.prepareCall(PhysicalConnection.java:1677)
	at oracle.jdbc.oracore.OracleTypeADT.initMetadata11_2(OracleTypeADT.java:741)
	at oracle.jdbc.oracore.OracleTypeADT.initMetadata(OracleTypeADT.java:479)
	at oracle.jdbc.oracore.OracleTypeADT.init(OracleTypeADT.java:443)
	at oracle.sql.ArrayDescriptor.initPickler(ArrayDescriptor.java:1499)
	at oracle.sql.ArrayDescriptor.<init>(ArrayDescriptor.java:274)
	at oracle.sql.ArrayDescriptor.createDescriptor(ArrayDescriptor.java:127)
	at oracle.sql.ArrayDescriptor.createDescriptor(ArrayDescriptor.java:79)
	at oracle.jdbc.driver.OraclePreparedStatement.setNullCritical(OraclePreparedStatement.java:4359)
	at oracle.jdbc.driver.OraclePreparedStatement.setNullInternal(OraclePreparedStatement.java:4321)
	at oracle.jdbc.driver.OraclePreparedStatement.setNull(OraclePreparedStatement.java:4299)
	at oracle.jdbc.driver.OraclePreparedStatementWrapper.setNull(OraclePreparedStatementWrapper.java:1013)
	at com.zaxxer.hikari.pool.HikariProxyCallableStatement.setNull(HikariProxyCallableStatement.java)
	at org.utplsql.api.testRunner.AbstractTestRunnerStatement.createStatement(AbstractTestRunnerStatement.java:58)
	at org.utplsql.api.testRunner.ActualTestRunnerStatement.createStatement(ActualTestRunnerStatement.java:44)
	at org.utplsql.api.testRunner.AbstractTestRunnerStatement.<init>(AbstractTestRunnerStatement.java:33)
	at org.utplsql.api.testRunner.ActualTestRunnerStatement.<init>(ActualTestRunnerStatement.java:17)
	at org.utplsql.api.testRunner.TestRunnerStatementProvider.getCompatibleTestRunnerStatement(TestRunnerStatementProvider.java:44)
	at org.utplsql.api.compatibility.CompatibilityProxy.getTestRunnerStatement(CompatibilityProxy.java:157)
	at org.utplsql.api.TestRunner.lambda$initStatementWithTimeout$0(TestRunner.java:199)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)
##################### utPLSQL cli #####################
#                                                     #
#   utPLSQL-cli 3.1.3-SNAPSHOT.local                  #
#   utPLSQL-java-api 3.1.3-SNAPSHOT.390               #
#   Java-Version: 1.8.0_191                           #
#   ORACLE_HOME: \\Programs\ORACLE                    #
#   NLS_LANG: null                                    #
#                                                     #
#   Thanks for testing!                               #
#                                                     #
#######################################################

Use connection string jdbc:oracle:thin:****/****@dev_xxx.WORLD
Successfully connected to database. UtPLSQL core: v3.1.3.2402
Oracle-Version: 11.2.0.4.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.3.2402
Initializing reporters
Running tests
Running tests finished.
--------------------------------------
All tests done.

Second one:

##################### utPLSQL cli #####################
#                                                     #
#   utPLSQL-cli 3.1.3-SNAPSHOT.local                  #
#   utPLSQL-java-api 3.1.3-SNAPSHOT.390               #
#   Java-Version: 1.8.0_191                           #
#   ORACLE_HOME: \\Programs\ORACLE                    #
#   NLS_LANG: null                                    #
#                                                     #
#   Thanks for testing!                               #
#                                                     #
#######################################################

Use connection string jdbc:oracle:thin:****/****@dev_xxx.WORLD
Successfully connected to database. UtPLSQL core: v3.1.3.2402
Oracle-Version: 11.2.0.4.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.3.2402
Initializing reporters
Detected Oracle driver stuck during Statement initialization
HikariPool-1 - Connection oracle.jdbc.driver.T4CConnection@6c49835d marked as broken because of SQLSTATE(08003), ErrorCode(17008)
java.sql.SQLRecoverableException: Closed Connection
	at oracle.jdbc.driver.PhysicalConnection.clearWarnings(PhysicalConnection.java:2573)
	at com.zaxxer.hikari.pool.ProxyConnection.close(ProxyConnection.java:249)
	at org.utplsql.cli.ReporterManager.lambda$startReporterGatherers$0(ReporterManager.java:130)
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
HikariPool-1 - Connection oracle.jdbc.driver.T4CConnection@2b370e4b marked as broken because of SQLSTATE(08003), ErrorCode(17008)
java.sql.SQLRecoverableException: Closed Connection
	at oracle.jdbc.driver.PhysicalConnection.clearWarnings(PhysicalConnection.java:2573)
	at com.zaxxer.hikari.pool.ProxyConnection.close(ProxyConnection.java:249)
	at org.utplsql.cli.ReporterManager.lambda$startReporterGatherers$0(ReporterManager.java:130)
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.util.concurrent.FutureTask.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.lang.Thread.run(Unknown Source)
WARNING: Caught Oracle stuck during creation of Runner-Statement. Retrying (1)
##################### utPLSQL cli #####################
#                                                     #
#   utPLSQL-cli 3.1.3-SNAPSHOT.local                  #
#   utPLSQL-java-api 3.1.3-SNAPSHOT.390               #
#   Java-Version: 1.8.0_191                           #
#   ORACLE_HOME: \\Programs\ORACLE                    #
#   NLS_LANG: null                                    #
#                                                     #
#   Thanks for testing!                               #
#                                                     #
#######################################################

Use connection string jdbc:oracle:thin:****/****@dev_xxx.WORLD
Successfully connected to database. UtPLSQL core: v3.1.3.2402
Oracle-Version: 11.2.0.4.0
Running tests now.
--------------------------------------
TestRunner initialized
Running on utPLSQL v3.1.3.2402
Initializing reporters
Running tests
Running tests finished.
--------------------------------------
All tests done.

Don't hesitate if you need more details.

@SebGt

Thank you very much @SebGt !
The log proves that the bug is caught and dealt with :)

@SebGt

Thank you very much @SebGt !
The log proves that the bug is caught and dealt with :)

You're welcome.
I don't have stuck execution anymore.
Thank you for taking the time to solve this problem related to the 11g.

@c0dw

@c0dw and @PhilippSalvisberg did some extensive testing and analysis yesterday (on Oracle 12.2) which they shared with me afterward. The findings:

Watchdog catches the stuck situation reliably (appeared 5 times in 200 runs)
In one case the stuck situation happened two times in a row but was resolved in the 3rd try
The reported results were correct

The I/O exception caused by aborting the connection might be a bit irritating, so I'll try to only show it in debug-mode.
I think we can finally close that issue now 🍾
Thanks for all your help (also @SebGt and @jgebal) - I wouldn't have found the source without you!

Navigation Menu

Repository navigation

java.sql.SQLRecoverableException: No more data to read from socket #20

19 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

java.sql.SQLRecoverableException: No more data to read from socket #20

Description

Activity

pesse commented on May 17, 2018

c0dw commented on Feb 14, 2019

pesse commented on Feb 14, 2019

c0dw commented on Feb 14, 2019

pesse commented on Feb 14, 2019

c0dw commented on Feb 14, 2019

pesse commented on Feb 14, 2019

c0dw commented on Feb 14, 2019

pesse commented on Feb 14, 2019

c0dw commented on Feb 15, 2019

pesse commented on Feb 15, 2019

c0dw commented on Feb 15, 2019

c0dw commented on Feb 19, 2019

pesse commented on Feb 19, 2019

19 remaining items

pesse commented on Mar 14, 2019

SebGt commented on Mar 15, 2019

SebGt commented on Mar 15, 2019

pesse commented on Mar 15, 2019

SebGt commented on Mar 15, 2019

pesse commented on Mar 15, 2019

SebGt commented on Mar 15, 2019

SebGt commented on Mar 18, 2019

pesse commented on Mar 18, 2019

SebGt commented on Mar 18, 2019

pesse commented on Mar 19, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions