AtliB
AtliB

Reputation: 1273

Selecting from DB2 gives [SQL0501] Cursor CRSR0001 not open

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

Answers (2)

Jacques
Jacques

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)]:

  • Increasing the connection pool size
  • Reducing the amount of connection reuse times

Upvotes: 1

James Allman
James Allman

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:

  • Is this running natively or remotely?
  • Which JVM are you using?
  • Have you checked cume and group PTF levels?
  • Can you include the output of the WRKPTFGRP command?

Upvotes: 2

Related Questions