search

IBM / JTOpen

IBM Toolbox for Java, an IBM i communications library
https://ibm.github.io/JTOpen/
Other
60 stars 28 forks source link

JDBC: execute query fails because of `java.net.SocketTimeoutException: Read timed out` #154

Closed NicolaIsotta closed 5 months ago

NicolaIsotta commented 8 months ago

Test code:

public static void main(String[] args) throws Exception {
    AS400JDBCDataSource ds = new AS400JDBCDataSource(
            "XXX.XXX.XXX.XXX",
            "[redacted]",
            "[redacted]");
    ds.setPrompt(false);
    ds.setLibraries("FILESDEMO");
    ds.setTrace(true);
    ds.setNaming("system");

    try (Connection conn = ds.getConnection()) {
        try (Statement st1 = conn.createStatement(); ResultSet rs1 = st1.executeQuery("select * from OBVAC00F where OBVACCOCOM = 'FREQ'");) {
            while (rs1.next()) {
                System.out.println(rs1.getString("OBVACCOCOM"));
            }
        }
    }
}
Exception stack trace 
Exception in thread "main" java.sql.SQLNonTransientConnectionException: Communication link failure. (Read timed out)
    at com.ibm.as400.access.JDError.createSQLExceptionSubClass(JDError.java:877)
    at com.ibm.as400.access.JDError.throwSQLException(JDError.java:605)
    at com.ibm.as400.access.JDError.throwSQLException(JDError.java:563)
    at com.ibm.as400.access.AS400JDBCConnectionImpl.sendAndReceive(AS400JDBCConnectionImpl.java:3173)
    at com.ibm.as400.access.AS400JDBCStatement.commonExecute(AS400JDBCStatement.java:976)
    at com.ibm.as400.access.AS400JDBCStatement.executeQuery(AS400JDBCStatement.java:2570)
    at ch.jsoft.ebanking.Test.main(Test.java:29)
    Suppressed: java.sql.SQLNonTransientConnectionException: The connection does not exist.
        at com.ibm.as400.access.JDError.createSQLExceptionSubClass(JDError.java:877)
        at com.ibm.as400.access.JDError.throwSQLException(JDError.java:431)
        at com.ibm.as400.access.AS400JDBCConnectionImpl.checkOpen(AS400JDBCConnectionImpl.java:504)
        at com.ibm.as400.access.AS400JDBCConnectionImpl.sendAndReceive(AS400JDBCConnectionImpl.java:3116)
        at com.ibm.as400.access.AS400JDBCStatement.close(AS400JDBCStatement.java:499)
        ... 1 more
Caused by: java.net.SocketTimeoutException: Read timed out
    at java.base/java.net.SocketInputStream.socketRead0(Native Method)
    at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at com.ibm.as400.access.DataStream.readFromStream(DataStream.java:54)
    at com.ibm.as400.access.ClientAccessDataStream.construct(ClientAccessDataStream.java:61)
    at com.ibm.as400.access.AS400ThreadedServer.run(AS400ThreadedServer.java:359)
    at java.base/java.lang.Thread.run(Thread.java:829)
Toolbox trace output 
Toolbox for Java - JDBC 4.3 Open Source Software, JTOpen 20.0.6 codebase 5770-SS1 V7R5M0.00 built=2023-11-02 03:05:40 (GMT)
java.home=C:\Program Files\Eclipse Adoptium\jdk-11.0.17.8-hotspot java.vm.vendor=Eclipse Adoptium java.vm.info=mixed mode java.runtime.version=11.0.17+8 java.fullversion=null java.vm.version=11.0.17+8 java.version=11.0.17 os.name=Windows 10 os.version=10.0
gio gen 18 14:14:36:116 CET 2024  as400: DataSource  (1391942103) : trace: true.
gio gen 18 14:14:36:132 CET 2024  Class com.ibm.as400.access.AS400JDBCDriver was loaded from file:/C:/Users/Nicola%20Isotta/.m2/repository/net/sf/jt400/jt400/20.0.6/jt400-20.0.6-java11.jar!/com/ibm/as400/access/AS400JDBCDriver.class
gio gen 18 14:14:36:142 CET 2024  as400:  class com.ibm.as400.access.AS400JDBCDriver (532854629) : Missing resource [REMOVED].
gio gen 18 14:14:36:142 CET 2024  as400:  class com.ibm.as400.access.AS400JDBCDriver (532854629) : Missing resource [REMOVED].
gio gen 18 14:14:36:143 CET 2024  as400:  class com.ibm.as400.access.AS400JDBCDriver (532854629) : Missing resource [PORT_DESC].
gio gen 18 14:14:36:143 CET 2024  as400:  class com.ibm.as400.access.AS400JDBCDriver (532854629) : Missing resource [AFFINITYFAILBACKINTERVAL_DESC].
gio gen 18 14:14:36:143 CET 2024  as400@setString: Properties libraries=FILESDEMO;naming=system;prompt=false;trace=true; (963522361) : naming = "system".
gio gen 18 14:14:36:151 CET 2024  as400: DataSource  (1391942103) : naming: system.
gio gen 18 14:14:36:647 CET 2024  as400: ConnectionImpl null (70807318) : Calling DriverManager.getDrivers.
gio gen 18 14:14:36:662 CET 2024  as400: ConnectionImpl null (70807318) : ..found driver AS/400 Toolbox for Java JDBC Driver:1861781750 class:class com.ibm.as400.access.AS400JDBCDriver.
gio gen 18 14:14:36:662 CET 2024  as400: ConnectionImpl null (70807318) : done looking at drivers.
gio gen 18 14:14:36:666 CET 2024  as400@setString: Properties libraries=FILESDEMO;naming=system;prompt=false;trace=true;metadata source=1; (963522361) : metadata source = "1".
gio gen 18 14:14:36:670 CET 2024  as400: Toolbox for Java - Open Source Software, JTOpen 20.0.6 codebase 5770-SS1 V7R5M0.00 built=2023-11-02 03:05:40 (GMT)
gio gen 18 14:14:36:670 CET 2024  as400: JDBC Level: 40
gio gen 18 14:14:36:674 CET 2024  as400@setString: Properties libraries=FILESDEMO;naming=system;prompt=false;trace=true;metadata source=1; (963522361) : package ccsid = "13488".
gio gen 18 14:14:36:675 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Client CCSID = 13488.
gio gen 18 14:14:36:675 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Setting server NLV = 2932.
gio gen 18 14:14:36:675 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Client functional level = V7R2M01   .
gio gen 18 14:14:36:675 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Data compression = RLE.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : ROWID supported = true.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : True auto-commit supported = true.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : 128 byte column names supported = true.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : 128 length schema names supported = true.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : client support 0x04000000 set.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : client support 0x02000000 multiple SQLCAs.
gio gen 18 14:14:36:676 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Maximum decimal precision = 31.
gio gen 18 14:14:36:677 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Maximum decimal scale = 31.
gio gen 18 14:14:36:677 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Minimum divide scale = 0.
gio gen 18 14:14:36:677 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Translate hex = character.
gio gen 18 14:14:36:677 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : query optimize goal = 0.
gio gen 18 14:14:36:678 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : query storage limit = -1.
gio gen 18 14:14:36:678 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Using extended datastreams.
gio gen 18 14:14:36:710 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : JDBC driver major version = 13.
gio gen 18 14:14:36:714 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : IBM i VRM = V7R5M0.
gio gen 18 14:14:36:715 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Server CCSID = 280.
gio gen 18 14:14:36:719 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Server functional level = V7R5M00016 (16).
gio gen 18 14:14:36:719 CET 2024  as400: ConnectionImpl XXX.XXX.XXX.XXX:XXX.XXX.XXX.XXX (70807318) : Server job identifier = 073312/QUSER/QZDASOINIT.
gio gen 18 14:14:36:719 CET 2024  as400@setString: Properties decimal separator=.;libraries=FILESDEMO;naming=system;prompt=false;trace=true;metadata source=1; (963522361) : decimal separator = ".".
gio gen 18 14:14:36:720 CET 2024  as400@setString: Properties date format=dmy;decimal separator=.;libraries=FILESDEMO;naming=system;prompt=false;trace=true;metadata source=1; (963522361) : date format = "dmy".
gio gen 18 14:14:36:720 CET 2024  as400@setString: Properties date format=dmy;date separator=/;decimal separator=.;libraries=FILESDEMO;naming=system;prompt=false;trace=true;metadata source=1; (963522361) : date separator = "/".
gio gen 18 14:14:36:720 CET 2024  as400@setString: Properties date format=dmy;date separator=/;decimal separator=.;libraries=FILESDEMO;naming=system;prompt=false;time format=hms;trace=true;metadata source=1; (963522361) : time format = "hms".
gio gen 18 14:14:36:720 CET 2024  as400@setString: Properties date format=dmy;date separator=/;decimal separator=.;libraries=FILESDEMO;naming=system;prompt=false;time format=hms;time separator=:;trace=true;metadata source=1; (963522361) : time separator = ":".
gio gen 18 14:14:36:756 CET 2024  as400: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318)  open.
gio gen 18 14:14:36:756 CET 2024  as400@setProperties: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Auto commit = "true".
gio gen 18 14:14:36:756 CET 2024  as400@setProperties: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Read only = "false".
gio gen 18 14:14:36:756 CET 2024  as400@setProperties: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Transaction isolation = "1".
gio gen 18 14:14:36:757 CET 2024  as400: DataSource  (1391942103) : connection created.
gio gen 18 14:14:36:762 CET 2024  as400: Statement STMT0001 (1594199808)  open. Parent: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) .
gio gen 18 14:14:36:762 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Escape processing = "true".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Fetch direction = "1000".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Fetch size = "0".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Max field size = "0".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Max rows = "0".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Query timeout = "0".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Result set concurrency = "1007".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Result set holdability = "1".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Result set type = "1003".
gio gen 18 14:14:36:763 CET 2024  as400@AS400JDBCStatement.init: Statement STMT0001 (1594199808) : Behavior Override = "0".
gio gen 18 14:14:36:764 CET 2024  as400: Statement STMT0001 (1594199808) : Data to correlate statement with cursor Cursor CRSR0001 (422396878) .
gio gen 18 14:14:36:769 CET 2024  as400: Statement STMT0001 (1594199808) : Executing query, SQL Statement -->[select * from OBVAC00F where OBVACCOCOM = 'FREQ'].
gio gen 18 14:14:37:077 CET 2024  as400: Statement STMT0001 (1594199808) : Prepared STMT0001*, SQL Statement -->[select * from OBVAC00F where OBVACCOCOM = 'FREQ'].
gio gen 18 14:14:56:287 CET 2024  as400: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Throwing exception. Original exception: .java.net.SocketTimeoutException: Read timed out
    at java.base/java.net.SocketInputStream.socketRead0(Native Method)
    at java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at com.ibm.as400.access.DataStream.readFromStream(DataStream.java:54)
    at com.ibm.as400.access.ClientAccessDataStream.construct(ClientAccessDataStream.java:61)
    at com.ibm.as400.access.AS400ThreadedServer.run(AS400ThreadedServer.java:359)
    at java.base/java.lang.Thread.run(Thread.java:829)

gio gen 18 14:14:56:288 CET 2024  as400: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Throwing exception.  Actual exception: Communication link failure. (Read timed out) sqlState: 08S01 vendor code -99999.java.sql.SQLNonTransientConnectionException: Communication link failure. (Read timed out)
    at com.ibm.as400.access.JDError.createSQLExceptionSubClass(JDError.java:877)
    at com.ibm.as400.access.JDError.throwSQLException(JDError.java:605)
    at com.ibm.as400.access.JDError.throwSQLException(JDError.java:563)
    at com.ibm.as400.access.AS400JDBCConnectionImpl.sendAndReceive(AS400JDBCConnectionImpl.java:3173)
    at com.ibm.as400.access.AS400JDBCStatement.commonExecute(AS400JDBCStatement.java:976)
    at com.ibm.as400.access.AS400JDBCStatement.executeQuery(AS400JDBCStatement.java:2570)
    at ch.jsoft.ebanking.Test.main(Test.java:29)

gio gen 18 14:14:56:289 CET 2024  as400: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Throwing exception, sqlState: 08003 reason: The connection does not exist. vendor code -99999.java.sql.SQLNonTransientConnectionException: The connection does not exist.
    at com.ibm.as400.access.JDError.createSQLExceptionSubClass(JDError.java:877)
    at com.ibm.as400.access.JDError.throwSQLException(JDError.java:431)
    at com.ibm.as400.access.AS400JDBCConnectionImpl.checkOpen(AS400JDBCConnectionImpl.java:504)
    at com.ibm.as400.access.AS400JDBCConnectionImpl.sendAndReceive(AS400JDBCConnectionImpl.java:3116)
    at com.ibm.as400.access.AS400JDBCStatement.close(AS400JDBCStatement.java:499)
    at ch.jsoft.ebanking.Test.main(Test.java:29)
First message on the job log 
                     Ulteriori informazioni sui messaggi                       

ID messaggio . . . . . :   CPE3426       Gravità  . . . . . . . :   10         
Tipo di messaggio  . . :   Diagnostica                                         
Data invio . . . . . . :   18/01/24      Ora invio  . . . . . . :   11:54:24   

Messaggio . . . :   Un collegamento con socket remoto è stato da esso          
  ripristinato.
Second message on the job log 
                     Ulteriori informazioni sui messaggi                     

ID messaggio . . . . . :   CPIAD08       Gravità  . . . . . . . :   40       
Tipo di messaggio  . . :   Diagnostica                                       
Data invio . . . . . . :   18/01/24      Ora invio  . . . . . . :   11:54:24 

Messaggio . . . :   Si è verificato un errore delle comunicazioni del server 
  dell'host in recv() - length.                                              
Causa . . . . . :   Durante l'elaborazione della funzione recv() - length per
  le comunicazioni del server di rete dell'host è stato ricevuto il codice di
  errore 3426.                                                               
Correzione  . . : Per individuare la causa dell'errore, esaminare gli        
  eventuali messaggi precedentemente elencati; se necessario, correggere     
  l'errore ed immettere nuovamente la richiesta.
jeber-ibm commented 8 months ago

Looks like the server isn't responding in time. This error is occurring at the socket level.

gio gen 18 14:14:37:077 CET 2024 as400: Statement STMT0001 (1594199808) : Prepared STMT0001, SQL Statement -->[select from OBVAC00F where OBVACCOCOM = 'FREQ']. gio gen 18 14:14:56:287 CET 2024 as400: ConnectionImpl [redacted]:XXX.XXX.XXX.XXX (70807318) : Throwing exception. Original exception: .java.net.SocketTimeoutException: Read timed out at java.base/java.net.SocketInputStream.socketRead0(Native Method)

I find it odd that there is only a 20 second timeout. Is there a setting on your OS that is limiting a read timeout to 20 seconds?

NicolaIsotta commented 8 months ago

Some additional notes:

Maybe it's a bug at the DB2 level?

jeber-ibm commented 8 months ago

Weird, it could be that the job on the "IBM i" is ending. Are you able to find the joblog for the QZDASOINIT job used by the connection? The joblog should show the cause of the job ending and you could contact IBM to resolve the problem.

jeber-ibm commented 5 months ago

Closing because of inactivity.

NicolaIsotta commented 5 months ago

The job log is in the first post. Anyway, I applied some PTFs, I'll test again, maybe it had already been fixed.

jeber-ibm commented 5 months ago

It would be nice to see the entire job log. This should be a joblog from a QZDASOINIT job.

jeber-ibm commented 5 months ago

Is there an "intelligent" firewall between the client and the server? I've seen cases where a firewall drops connections because it thinks there is some type of network attack taking place. You may want to check with the network administrator to see if the firewall is dropping the connection.