The benefits of ODBC trace are still there when debugging UBEs especially.
So this was the problem. There was a main section with a SQL statement that was based on a VIEW (this is important) and should have processed 20000 rows. The SQL was good and tidy, but the batch job would stop after 10 rows on the 400 and 271 on the client. Yep, that is weird. The problem was kind of intermittent, but consistent… (Even that is a bad description).
The developers were saying the server was rubbish and fix it. This is a tough situation, as CNC is generally at the bottom of these types of problems that are in the nether regions of peoples responsibilities.
So we ran it with logging, nothing really.
Mar 21 13:31:36.701864 dbdrvsql.c1362 - 1087/139 MAIN_THREAD >>>Start - FetchSQLRow QxdaProcessExtDynEDRS
Mar 21 13:31:36.805392 dbdrvsql.c1373 - 1087/139 MAIN_THREAD >>>End - FetchSQLRow QxdaProcessExtDynEDRS
Mar 21 13:31:36.805432 dbdrvag.c1143 - 1087/139 MAIN_THREAD Exiting PerformRequest, result=-1
Mar 21 13:31:36.805448 jdb_exef.c4618 - 1087/139 MAIN_THREAD No More Data found
--UBE--[2]-- End of Records for the section with Return Code (-2147483648) after fetching 0 records.
The above message is a funny one, as this is 2^31 negative. I think this is the return of an unsigned int if it gets a negative.
Good info, but not helpful enough.
Next level of logging was tracing the job on the 400 and ODBC trace.
ODBC trace turn out to solve the problem quickly. The ODBC trace has great information about warnings and things that JDE logs ignore. The ODBC trace shows you accurate handle associates and cursors etc.
What actually was occurring was that there was an update to a parent table in the parent child relationship that the view was based upon.
So the main loop had a cursor open and that value had been updated with a separate table i/o to the parent record.
This eventually caught up with the code and the report crapped out. The ODBC trace shows the handles that the errors are reported on. The different colours show the continuity of the handles.
activConsole 13cc-1e0 EXIT SQLPrepareW with return code 0 (SQL_SUCCESS)
HSTMT 03AC92F0
WCHAR * 0x1BD95F80 [ 766] "SELECT T0.AFEDBT, T0.AFEDTN, T0.AFEDLN, T0.AFEDSP, T0.AF57PRID, T0.AF57PRDESC, T0.AFITM, T0.AF57STCD, T0.AFLITM, T0.AF57STDESC, T0.AFAN8, T0.AFALKY, T0.AFTRDJ, T0.AF57ACD, T0.AF57ACOOP, T0.AFAID, T0.AFAID2, T0.AFAID3, T0.AFAID4, T0.AFUSER, T0.AFPID, T0.AFJOBN, T0.AFUPMJ, T0.AFUPMT, T1.BHEDBT, T1.BH57INTF, T1.BHEDCT, T1.BH57SEQ, T1.BH57BSTS, T1.BH57RECC, T1.BH57TOT1, T1.BH57TOT2, T1.BH57TOT3, T1.BH57TOT4, T1.BH57SUM1, T1.BH57SUM2, T1.BH57FDAT, T1.BH57FTIM, T1.BH57TDAT, T1.BH57TTIM, T1.BH57CDAT, T1.BH57CTIM, T1.BH57MDAT, T1.BHUSER, T1.BHPID, T1.BHJOBN, T1.BHUPMJ, T1.BHUPMT, T1.BH57MTIM, T1.BH57EDBT FROM UADTA/F570911F T0,UADTA/F570001 T1 WHERE ( ( T1.BH57INTF = ? AND T1.BH57BSTS = ? ) ) AND ( T0.AFEDBT=T1.BHEDBT ) ORDER BY T0.AFEDBT ASC,T0.AF57PRID ASC"
SDWORD 766
activConsole 13cc-1e0 ENTER SQLExecute
HSTMT 03AC92F0
activConsole 13cc-1e0 EXIT SQLExecute with return code 0 (SQL_SUCCESS)
HSTMT 03AC92F0
activConsole 13cc-1e0 ENTER SQLFetch
HSTMT 03AC92F0
activConsole 13cc-1e0 ENTER SQLPrepareW
HSTMT 03ACAC40
WCHAR * 0x2665CF90 [ 59] "UPDATE UADTA/F570001 SET BH57BSTS=? WHERE ( BHEDBT = ? ) "
SDWORD 59
activConsole 13cc-1e0 EXIT SQLPrepareW with return code 0 (SQL_SUCCESS)
HSTMT 03ACAC40
WCHAR * 0x2665CF90 [ 59] "UPDATE UADTA/F570001 SET BH57BSTS=? WHERE ( BHEDBT = ? ) "
SDWORD 59
activConsole 13cc-1e0 ENTER SQLExecute
HSTMT 03ACAC40
activConsole 13cc-1e0 EXIT SQLExecute with return code 0 (SQL_SUCCESS)
HSTMT 03ACAC40
...
activConsole 13cc-1e0 EXIT SQLFetch with return code 100 (SQL_NO_DATA_FOUND)
HSTMT 03AC92F0
activConsole 13cc-1e0 ENTER SQLCloseCursor
SQLHSTMT 03ACB078
activConsole 13cc-1e0 EXIT SQLCloseCursor with return code 0 (SQL_SUCCESS)
SQLHSTMT 03ACB078
activConsole 13cc-1e0 ENTER SQLCloseCursor
SQLHSTMT 03AC92F0
activConsole 13cc-1e0 EXIT SQLCloseCursor with return code 0 (SQL_SUCCESS)
SQLHSTMT 03AC92F0
activConsole 13cc-1e0 ENTER SQLCloseCursor
SQLHSTMT 03ACA3D0
activConsole 13cc-1e0 EXIT SQLCloseCursor with return code 0 (SQL_SUCCESS)
SQLHSTMT 03ACA3D0
activConsole 13cc-1e0 ENTER SQLCloseCursor
SQLHSTMT 03ACA808
activConsole 13cc-1e0 EXIT SQLCloseCursor with return code 0 (SQL_SUCCESS)
SQLHSTMT 03ACA808
activConsole 13cc-1e0 ENTER SQLCloseCursor
SQLHSTMT 03ACAC40
activConsole 13cc-1e0 EXIT SQLCloseCursor with return code -1 (SQL_ERROR)
SQLHSTMT 03ACAC40
DIAG [24000] [IBM][System i Access ODBC Driver]Invalid cursor state. (30022)
activConsole 13cc-1e0 ENTER SQLGetDiagRecW
SQLSMALLINT 1
SQLHANDLE 03AB1540
SQLSMALLINT 1
SQLWCHAR * 0x2657EEF0 (NYI)
SQLINTEGER * 0x2657EEFC
SQLWCHAR * 0x2657EF00 (NYI)
SQLSMALLINT 256
SQLSMALLINT * 0x2657EEE8