Reputation: 1273
I'm using JDBC for connecting to DB2 and executing an SQL statement. Running a simple:
SELECT * FROM myview
I'm getting a:
State : 24501
Message: [SQL0501] Cursor CRSR0001 not open. Cause . . . . . : The cursor CRSR0001 was specified in a FETCH or CLOSE statement, but the cursor is not open. Cursor CRSR0001 has one of the following conditions: -- Cursor CRSR0001 was never opened. -- The cursor CRSR0001 was opened in another program or another call of this program and the program was created with CLOSQLCSR(*ENDPGM). -- The cursor CRSR0001 was opened in another module or another call of this module and the module was created with CLOSQLCSR(*ENDMOD). -- The cursor CRSR0001 was opened in another call of this program and programs which have run SQL statements have ended and the program was created with CLOSQLCSR(*ENDSQL). -- The cursor CRSR0001 was opened in another call of this module and the activation group ended between calls. The module was created with CLOSQLCSR(*ENDACTGRP). -- The cursor was closed by a CLOSE, COMMIT, or ROLLBACK statement. -- The cursor CRSR0001 was opened under a transaction which is different than the current transaction. Recovery . . . : Do one of the following and precompile again: -- Make certain that cursor CRSR0001 is opened in the same program or module call prior to using the cursor in an FETCH or CLOSE statement. -- Specify either CLOSQLCSR(*ENDSQL), CLOSQLCSR(*ENDJOB), or CLOSQLCSR(*ENDACTGRP) when precompiling the application. -- If the cursor was closed by a COMMIT or ROLLBACK, specify HOLD on the COMMIT or ROLLBACK statement to preserve any open cursors, prepared statements, and locks on tables.
Error : -501
This happens after I fetch the very last row from the resultset when I call
rs.next()
If I add a where clause to the select statement, it may or may not work with the same error (depends on what I'm filtering on). Does not seem to be related to any specific row though.
I have been able to circumvent the problem by e.g.: * changing the "block size" parameter in the connection string to any power of two, except 32 (which is the default)
or by changing how the statement is initially created:
// Get a statement from the connection
stmt = conn.createStatement(); // doesn't work
stmt = conn.createStatement(ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_READ_ONLY); // doesn't work
stmt = conn.createStatement(ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_UPDATABLE); // works
stmt = conn.createStatement(ResultSet.TYPE_SCROLL_SENSITIVE, ResultSet.CONCUR_UPDATABLE, ResultSet.CLOSE_CURSORS_AT_COMMIT); // works
stmt = conn.createStatement(ResultSet.TYPE_SCROLL_SENSITIVE, ResultSet.CONCUR_UPDATABLE, ResultSet.HOLD_CURSORS_OVER_COMMIT); // works
stmt = conn.createStatement(ResultSet.TYPE_SCROLL_SENSITIVE, ResultSet.CONCUR_READ_ONLY); // works
stmt = conn.createStatement(ResultSet.TYPE_SCROLL_INSENSITIVE, ResultSet.CONCUR_READ_ONLY); // works
stmt = conn.createStatement(ResultSet.TYPE_SCROLL_INSENSITIVE, ResultSet.CONCUR_UPDATABLE); // works
stmt = conn.createStatement(ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_READ_ONLY, ResultSet.CLOSE_CURSORS_AT_COMMIT); // doesn't work
stmt = conn.createStatement(ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_READ_ONLY, ResultSet.HOLD_CURSORS_OVER_COMMIT); // doesn't work
I've tested various JDBC versions of JT Open (6.4, 6.6, 7.4). All show the same problem so it's probably not a driver issue.
Also, probably the weirdest part is that if I create another view (different name) with identical underlying SQL, then it works fine every time. Dropping the old view and recreating it does not fix the problem.
And finally, the AS400 machines were patched recently (about the time when we started noticing the problem). This code has been working fine for a long time previously.
Any ideas?
PS. The code:
Driver d = new com.ibm.as400.access.AS400JDBCDriver();
DriverManager.registerDriver(d);
conn = DriverManager.getConnection("jdbc:as400://1.1.1.1/MYLIB;prompt=false;keep alive=true;errors=full", "user", "pass");
stmt = conn.createStatement();
rs = stmt.executeQuery(sql);
while (rs.next()) {
System.out.println(rs.getString(1));
}
PS: output of the trace:
Toolbox for Java - Open Source Software, JTOpen 7.4, codebase 5770-SS1 V7R1M0.05 2011/04/25 @CA
java.home=C:\Program Files\Java\jdk1.6.0_27\jre java.vm.version=20.2-b06 java.version=1.6.0_27 os.name=Windows 7 os.version=6.1
Thread[main,5,main] on maj 2 14:48:05:287 CEST 2012 as400: Properties (1026683572) : access = "all".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : block size = "32".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : block criteria = "2".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : date format = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : date separator = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : decimal separator = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : errors = "full".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : extended dynamic = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : libraries = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : naming = "sql".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package add = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package cache = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package clear = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package error = "warning".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package library = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : password = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : prefetch = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : prompt = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : remarks = "system".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : sort = "hex".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : sort language = "ENU".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : sort table = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : sort weight = "shared".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : time format = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : time separator = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : trace = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : transaction isolation = "read uncommitted".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : translate binary = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : user = "myuser".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package criteria = "default".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : lob threshold = "32768".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : secure = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : data truncation = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : proxy server = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : secondary URL = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : data compression = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : big decimal = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : thread used = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : cursor hold = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : lazy close = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : driver = "toolbox".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : bidi string type = "5".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : key ring name = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : key ring password = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : full open = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : server trace = "2".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : database name = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : extended metadata = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : cursor sensitivity = "asensitive".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : behavior override = "0".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : package ccsid = "13488".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : minimum divide scale = "0".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : maximum precision = "31".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : maximum scale = "31".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : translate hex = "character".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : toolbox trace = "all".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : qaqqinilib = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : login timeout = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : true autocommit = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : bidi implicit reordering = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : bidi numeric ordering = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : hold input locators = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : hold statements = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : rollback cursor hold = "false".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : variable field compression = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : query optimize goal = "0".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : keep alive = "true".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : receive buffer size = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : send buffer size = "".
Thread[main,5,main] on maj 2 14:48:05:303 CEST 2012 as400: Properties (1026683572) : XA loosely coupled support = "0".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : translate boolean = "true".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : metadata source = "-1".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : query storage limit = "-1".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : decfloat rounding mode = "half even".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : autocommit exception = "false".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : auto commit = "true".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : ignore warnings = "".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : secure current user = "true".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : concurrent access resolution = "0".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : jvm16 synchronize = "false".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : socket timeout = "".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : use block update = "false".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Properties (1026683572) : maximum blocked input rows = "32000".
Thread[main,5,main] on maj 2 14:48:05:318 CEST 2012 as400: Driver AS/400 Toolbox for Java JDBC Driver (493939748) : Using IBM Toolbox for Java JDBC driver implementation.
...
Thread[main,5,main] on maj 2 14:48:07:050 CEST 2012 as400: static method Connection VPAASXXX (1241535332) : Throwing exception, id: 1 error class: 1 return code: -501 reason: [SQL0501] Cursor CRSR0001 not open. Cause . . . . . : The cursor CRSR0001 was specified in a FETCH or CLOSE statement, but the cursor is not open. Cursor CRSR0001 has one of the following conditions: -- Cursor CRSR0001 was never opened. -- The cursor CRSR0001 was opened in another program or another call of this program and the program was created with CLOSQLCSR(*ENDPGM). -- The cursor CRSR0001 was opened in another module or another call of this module and the module was created with CLOSQLCSR(*ENDMOD). -- The cursor CRSR0001 was opened in another call of this program and programs which have run SQL statements have ended and the program was created with CLOSQLCSR(*ENDSQL). -- The cursor CRSR0001 was opened in another call of this module and the activation group ended between calls. The module was created with CLOSQLCSR(*ENDACTGRP). -- The cursor was closed by a CLOSE, COMMIT, or ROLLBACK statement. -- The cursor CRSR0001 was opened under a transaction which is different than the current transaction. Recovery . . . : Do one of the following and precompile again: -- Make certain that cursor CRSR0001 is opened in the same program or module call prior to using the cursor in an FETCH or CLOSE statement. -- Specify either CLOSQLCSR(*ENDSQL), CLOSQLCSR(*ENDJOB), or CLOSQLCSR(*ENDACTGRP) when precompiling the application. -- If the cursor was closed by a COMMIT or ROLLBACK, specify HOLD on the COMMIT or ROLLBACK statement to preserve any open cursors, prepared statements, and locks on tables. state: 24501.java.sql.SQLException: [SQL0501] Cursor CRSR0001 not open. Cause . . . . . : The cursor CRSR0001 was specified in a FETCH or CLOSE statement, but the cursor is not open. Cursor CRSR0001 has one of the following conditions: -- Cursor CRSR0001 was never opened. -- The cursor CRSR0001 was opened in another program or another call of this program and the program was created with CLOSQLCSR(*ENDPGM). -- The cursor CRSR0001 was opened in another module or another call of this module and the module was created with CLOSQLCSR(*ENDMOD). -- The cursor CRSR0001 was opened in another call of this program and programs which have run SQL statements have ended and the program was created with CLOSQLCSR(*ENDSQL). -- The cursor CRSR0001 was opened in another call of this module and the activation group ended between calls. The module was created with CLOSQLCSR(*ENDACTGRP). -- The cursor was closed by a CLOSE, COMMIT, or ROLLBACK statement. -- The cursor CRSR0001 was opened under a transaction which is different than the current transaction. Recovery . . . : Do one of the following and precompile again: -- Make certain that cursor CRSR0001 is opened in the same program or module call prior to using the cursor in an FETCH or CLOSE statement. -- Specify either CLOSQLCSR(*ENDSQL), CLOSQLCSR(*ENDJOB), or CLOSQLCSR(*ENDACTGRP) when precompiling the application. -- If the cursor was closed by a COMMIT or ROLLBACK, specify HOLD on the COMMIT or ROLLBACK statement to preserve any open cursors, prepared statements, and locks on tables.
at com.ibm.as400.access.JDError.createSQLExceptionSubClass(JDError.java:819)
at com.ibm.as400.access.JDError.throwSQLException(JDError.java:699)
at com.ibm.as400.access.JDError.throwSQLException(JDError.java:669)
at com.ibm.as400.access.JDServerRowCache.fetch(JDServerRowCache.java:358)
at com.ibm.as400.access.JDServerRowCache.fetch(JDServerRowCache.java:269)
at com.ibm.as400.access.JDServerRowCache.next(JDServerRowCache.java:792)
at com.ibm.as400.access.AS400JDBCResultSet.next(AS400JDBCResultSet.java:1830)
at com.mycompany.jdbctest.Main.runsql(Main.java:65)
at com.mycompany.jdbctest.Main.main(Main.java:20)
SQL Exception:
SQL : SELECT * FROM transfersearchview where status in (1, 4)
State : 24501
Message: [SQL0501] Cursor CRSR0001 not open. Cause . . . . . : The cursor CRSR0001 was specified in a FETCH or CLOSE statement, but the cursor is not open. Cursor CRSR0001 has one of the following conditions: -- Cursor CRSR0001 was never opened. -- The cursor CRSR0001 was opened in another program or another call of this program and the program was created with CLOSQLCSR(*ENDPGM). -- The cursor CRSR0001 was opened in another module or another call of this module and the module was created with CLOSQLCSR(*ENDMOD). -- The cursor CRSR0001 was opened in another call of this program and programs which have run SQL statements have ended and the program was created with CLOSQLCSR(*ENDSQL). -- The cursor CRSR0001 was opened in another call of this module and the activation group ended between calls. The module was created with CLOSQLCSR(*ENDACTGRP). -- The cursor was closed by a CLOSE, COMMIT, or ROLLBACK statement. -- The cursor CRSR0001 was opened under a transaction which is different than the current transaction. Recovery . . . : Do one of the following and precompile again: -- Make certain that cursor CRSR0001 is opened in the same program or module call prior to using the cursor in an FETCH or CLOSE statement. -- Specify either CLOSQLCSR(*ENDSQL), CLOSQLCSR(*ENDJOB), or CLOSQLCSR(*ENDACTGRP) when precompiling the application. -- If the cursor was closed by a COMMIT or ROLLBACK, specify HOLD on the COMMIT or ROLLBACK statement to preserve any open cursors, prepared statements, and locks on tables.
Error : -501
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 send(): send request...
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Cursor CRSR0001 (1338396376) : Closing with reuse flag = 241.
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Cursor CRSR0001 (1338396376) closed.
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: ResultSet CRSR0001 (1242359702) closed.
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 send and receive(): ...
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 send(): send request...
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 Data stream sent (connID=1399560387) ...
00 00 00 28 00 00 E0 04 00 00 00 00 00 00 00 34
00 14 1D 02 80 04 00 00 00 00 00 00 00 01 00 01
00 00 00 01 00 00 00 00
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 AS400Server.receive
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 receive(): Reply not found. Waiting...
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:065 CEST 2012 Data stream data received (connID=1399560387) ...
00 00 00 28 00 00 E0 04 00 00 00 00 00 00 00 34
00 14 28 00
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:065 CEST 2012 Data stream data received (connID=1399560387) ...
80 04 00 00 00 00 00 00 00 01 1D 02 1D 02 00 00
00 00 00 00
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:065 CEST 2012 run(): Adding reply: 52
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:065 CEST 2012 run(): Notifying threads.
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:065 CEST 2012 run(): Threads notified.
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:065 CEST 2012 run(): Waiting for reply...
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 receive(): Valid reply found: 52
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 send(): send request...
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 Data stream sent (connID=1399560387) ...
00 00 00 28 00 00 E0 04 00 00 00 00 00 00 00 35
00 14 1F 01 00 04 00 00 00 00 00 00 00 01 00 01
00 00 00 01 00 00 00 00
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (1091981526) closed.
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) open. Parent: Connection VPAASXXX (1241535332) .
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Escape processing = "true".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Fetch direction = "1000".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Fetch size = "0".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Max field size = "0".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Max rows = "0".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Query timeout = "0".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Result set concurrency = "1007".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Result set holdability = "1".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Result set type = "1003".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Behavior Override = "0".
Thread[main,5,main] on maj 2 14:48:07:065 CEST 2012 as400: Statement STMT0001 (2142386190) : Data to correlate statement with cursor Cursor CRSR0001 (226386081) .
...
Thread[main,5,main] on maj 2 14:48:07:096 CEST 2012 as400: Statement STMT0001 (2142386190) : Executed immediately STMT0001*, SQL Statement -->[CALL QSYS.QCMDEXC('QSYS/ENDDBMON', 0000000013.00000)].
Thread[main,5,main] on maj 2 14:48:07:096 CEST 2012 as400: Statement STMT0001 (2142386190) : Update count = 0.
Thread[main,5,main] on maj 2 14:48:07:096 CEST 2012 as400: Statement STMT0001 (2142386190) : Result set = false.
Thread[main,5,main] on maj 2 14:48:07:096 CEST 2012 as400: Statement STMT0001 (2142386190) : Number of result sets = 0.
Thread[main,5,main] on maj 2 14:48:07:096 CEST 2012 send and receive(): ...
Thread[main,5,main] on maj 2 14:48:07:096 CEST 2012 send(): send request...
...
Thread[main,5,main] on maj 2 14:48:07:112 CEST 2012 as400: Statement STMT0001 (2142386190) closed.
Thread[main,5,main] on maj 2 14:48:07:112 CEST 2012 Sending end job request...
...
Thread[main,5,main] on maj 2 14:48:07:112 CEST 2012 forceDisconnect calling readDaemon_.interrupt
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:112 CEST 2012 run(): Caught SocketException during disconnect:
java.net.SocketException: socket closed
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.ibm.as400.access.DataStream.readFromStream(DataStream.java:52)
at com.ibm.as400.access.ClientAccessDataStream.construct(ClientAccessDataStream.java:52)
at com.ibm.as400.access.AS400ThreadedServer.run(AS400ThreadedServer.java:357)
at java.lang.Thread.run(Thread.java:662)
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:112 CEST 2012 run(): Notifying threads after IOException.
Thread[AS400 Read Daemon [system:10.20.28.2;job:564820/QUSER/QZDASOINIT],5,main] on maj 2 14:48:07:112 CEST 2012 run(): Threads notified after IOException.
Thread[main,5,main] on maj 2 14:48:07:112 CEST 2012 Server disconnected
Thread[main,5,main] on maj 2 14:48:07:112 CEST 2012 as400: Connection VPAASXXX (1241535332) closed.
Output of WRKPTFGRP:
PTF-grupp Nivå Status
SF99626 6 Installerad
SF99626 7 Installerad
SF99616 8 Installerad
SF99616 11 Installerad
SF99610 10215 Installerad
SF99610 11256 Installerad
SF99609 102 Installerad
SF99609 114 Installerad
SF99608 23 Installerad
SF99608 28 Installerad
SF99601 21 Installerad
SF99601 24 Installerad
SF99562 17 Installerad
SF99562 18 Installerad
SF99356 21 Installerad
SF99356 22 Installerad
SF99354 8 Installerad
SF99354 13 Installerad
SF99350 6 Installerad
SF99350 9 Installerad
SF99349 14 Installerad
SF99187 23 Installerad
SF99187 24 Installerad
SF99144 3 Installerad
SF99144 4 Installerad
SF99115 22 Installerad
SF99115 23 Installerad
Upvotes: 1
Views: 9213
Reputation: 11
In our scenario, the '[SQL0501] Cursor CRSR0001 not open'
error, was caused by the underlying AS400 job being closed by another thread. We were able to prove this by creating a ConcurrentHashMap that keeps track of the AS400 job number associated with each thread, then hitting the server real hard with multiple threads...
This is our log extract...
CONNECTION SHARING DETECTED
Connection with jobNumber [QZDASOINITQUSER 198049] given to threads [124] and [11616]
Current connection info [job=QZDASOINITQUSER 198049, threadId=124, connHashCode=11404926]
Previous connection info[job=QZDASOINITQUSER 198049, threadId=11616, connHashCode=11404926]
Upon analysis of the log it became clear that as soon as the 2nd thread tries to use the connection (with same underlying JobNumber) that was closed by the 1st thread it fails with SQL0501
.
To reduce the likelihood of this error, we found the following helps on Glassfish Application Server 2.1.1 [with DB2 Connection Pool using JT400 6.7 (jdbc driver version 8.11)]:
Upvotes: 1
Reputation: 41148
I suggest running a trace to get more information.
See the IBM Software Technical Document: The All-In-One Toolbox Tracing Guide.
Also check the connection job log for diagnostic messages. You can get the job number, user, and name from the trace or using the getServerJobIdentifier() method on the connection object.
String serverJobIdentifier =
((AS400JDBCConnection)conn).getServerJobIdentifier();
Some additional information that may be helpful:
WRKPTFGRP
command?Upvotes: 2