Unhandling exception during dbstmt.fetchAll()

Didier68 commented 4 years ago

Hi,

When I execute an inconsistent SQL query, where for example, a string is divided by zero, I expected to get an error message. Unfortunately, this causes in dbstmt.fetchAll() an unhandled and no catchable exception, which violently stops the node process...

When going through a 5250 session, via STRSQL , the same query does not cause an error message, but displays this result to show that data are inconsistent:

My sample:

select 'XX' A, SEQ, 'XX' /SEQ from CLIENT c LIMIT 5 ` ....+....1....+....2....+....3....+....4....+....5....+....6....+. A SEQ 'XX' / SEQ
XX 0 +++++++++++++++++++++++++++++++++
XX 0 +++++++++++++++++++++++++++++++++
XX 0 +++++++++++++++++++++++++++++++++
XX 0 +++++++++++++++++++++++++++++++++
XX 0 +++++++++++++++++++++++++++++++++
**** End of data ****

My example is far-fetched, but I have similar errors when queries on tables with structural problems ...

My code: ` function execSql(parame, sqlOptions, onResult){ let libList; let sql; let dbconn, stmt; if (sqlOptions){ libList = sqlOptions.libList; sqlResult.sql = sql = sqlOptions.sql; }

try{  
parame.t(`execSql - START  ${JSON.stringify(sqlOptions)}  `);

dbconn = new  db.dbconn();  
dbconn.setConnAttr( db.SQL_ATTR_DBC_SYS_NAMING, db.SQL_TRUE);
dbconn.conn(sqlOptions.connParam.dbName, sqlOptions.connParam.userId, sqlOptions.connParam.passwd);

stmt = new db.dbstmt(dbconn);

stmt.exec(`CALL QSYS2/QCMDEXC('CHGLIBL LIBL(${libList})')`, function(resultSet, error){
  try{
    if (error){
      let err = {message: `...SQL -> Error 911.1 when 'CHGLIBL LIBL(${libList})': ${error.message}`};
      parame.e(err.message, error, {sql: sqlOptions.sql});
      __deallocCnx(dbconn, stmt);
      return onResult(err);
    }
    parame.t(`execSql: prepare()... `);

    stmt.prepare(sqlOptions.sql, function(error){
      try{
        if (error){
          let err = {message: `...SQL -> Error 911.2 when prepare(): ${error.message}`};
          parame.e(err.message, error, {sql: sqlOptions.sql});
          __deallocCnx(dbconn, stmt);
          return onResult(err);
        }  
        parame.t(`execSql: execute()... `);
        stmt.execute(function(outputParams, error){
          try{
            if (error){
              let err = {message: `ApiCnt10: Error SQL 911.3 when execute(): ${error.message}`};
              parame.e(err.message, error, {sql: sqlOptions.sql});
              __deallocCnx(dbconn, stmt);
              return onResult(err);
            }  

            parame.t(`execSql: fetchAll()... `);
            stmt.fetchAll( (rs, error) => {
              try{
                parame.t(`execSql: callback of fetchAll ... `); 
                if (error){
                  let err = {message: `Error SQL 911.4 when fetch(): ${error.message}`};
                  parame.e(err.message, error, {sql: sqlOptions.sql});
                  __deallocCnx(dbconn, stmt);
                  return onResult(err);
                }

                if (rs == null) {
                  parame.t("...execSql: stmt.fetchAll 911.5 return NULL");
                  rs = [];
                }
                parame.t(`...execSql done (${rs.length} rows) for: ${sqlOptions.sql.substr(0, 150)}`);
                __deallocCnx(dbconn, stmt); 

                try{
                  parame.t(`execSql: CALLBACK with resultSet... `);
                  onResult(null, rs);
                }
                catch(e){
                  let err = {message: `...SQL -> CallBack error 911.6: ${e.message} FOR \r\n${sqlOptions.sql.substr(0, 150)}\r\n...`};
                  parame.e(err.message, e, {sql: sqlOptions.sql});
                  return onResult(err);
                }
                return;
              }
              catch(e){
                let err = {message: `...SQL -> Error 911.4b after fetch(): ${e.message}`};
                parame.e(err.message, e, {sql: sqlOptions.sql});
                __deallocCnx(dbconn, stmt);
                return onResult(err);
              }
            });
            parame.t(`execSql: ...post fetchAll()... `);
          }
          catch(e){
            let err = {message: `...SQL -> Error 911.3b after execute(): ${e.message}`};
            parame.e(err.message, e, {sql: sqlOptions.sql});
            __deallocCnx(dbconn, stmt);
            return onResult(err);
          }
        });
      }
      catch(e){
        let err = {message: `...SQL -> Error 911.2b after prepare(): ${e.message}`};
        parame.e(err.message, e, {sql: sqlOptions.sql});
        __deallocCnx(dbconn, stmt);
        return onResult(err);
      }
    });
  }
  catch(e){
    let err = {message: `...SQL -> ApiCnt10: Error 911.1b after 'CHGLIBL LIBL(${libList})': ${e.message}`};
    parame.e(err.message, e, {sql: sqlOptions.sql});
    __deallocCnx(dbconn, stmt);
    return onResult(err);
  }
});

} catch(e){
let err = {message: ...SQL -> ApiCnt10: Error 911.1c during 'CHGLIBL LIBL(${libList})': ${e.message}}; parame.e(err.message, e, {sql: sqlOptions.sql}); __deallocCnx(dbconn, stmt); return onResult(err); } return; } module.exports.execSql = execSql; `

LOG DISPLAY: [4] TRACE 28/10/2019 20:38:59.714 portail400: execSql: prepare()...
[4] TRACE 28/10/2019 20:38:59.718 portail400: execSql: execute()...
[4] TRACE 28/10/2019 20:38:59.721 portail400: execSql: fetchAll()...
[4] TRACE 28/10/2019 20:38:59.721 portail400: execSql: ...post fetchAll()...

dmabupt commented 4 years ago

Hello @Didier68 , Because the API prepare(), execute() and fetchAll() are all asynchronous, it is recommended to retrieve the error messages from the output error parameter of the callback.

statement.fetchAll((resultSet, error) => {
  if(error) console.log(`post fetchAll: ${error}`);
});

Most of the database operations are executed in a separated thread where no exception thrown.

As for the inconsistent SQL query, if the error parameter is empty, you can enable debug mode to get more verbose trace --

dbconn.debug(true);

Or you can try the sync version of these API for debugging -- prepareSync(), executeSync() and fetchAllSync()

And would you tell me how to create such a table? That would be helpful for me to recreate and debug the problem.

Didier68 commented 4 years ago

Hello @dmabupt, Thanks for your reply.

I enable the debug, and obtain this result:

[4] TRACE 04/11/2019 10:19:39.706 portail400: execSql: prepare()... Prepare().

SQLPrepare(0): select 'XX' A, SEQ, 'XX' / SEQ from CLIENT c LIMIT 5
[4] TRACE 04/11/2019 10:19:39.720 portail400: execSql: execute()...

Execute().
SQLExecuteAsync(0):
SQLNUMRESULTSCOLS(0) Column Count = 3
SQLDescribeCol(0) index[0] sqlType[12] colScale[0] colPrecise[2]
SQLDescribeCol(0) index[1] sqlType[2] colScale[0] colPrecise[2]
SQLDescribeCol(0) index[2] sqlType[3] colScale[29] colPrecise[31]

[4] TRACE 04/11/2019 10:19:39.813 portail400: execSql: fetchAll()...
FetchAllAsync().

[4] TRACE 04/11/2019 10:19:39.814 portail400: execSql: ...post fetchAll()...
`

==> "post fetchAll()" is called after the fetchAll(): in other words, there is no exception when fetchAll() is called ==> "callback of fetchAll" is not displayed: the callback function of fetchAll() is never called...

For the last question about the creation of the table: the table has been modified with a CHGPF, but applications that perform data changes have not been recompiled, causing inconsistent data to be written to the table.

The SQL request select 'XX' / 0 from CLIENT c LIMIT 5 seems to produce a result similar to my first problem.

Didier68 commented 4 years ago

Hi, I have the same problem with another query:

select * from SYSCOLUMNS2 where TABLE_NAME = 'ARTTOT' and TABLE_SCHEMA like 'EURO4' LIMIT 50

Prepare().
SQLPrepare(0):  select  * from SYSCOLUMNS2 where TABLE_NAME = 'ARTTOT' and TABLE_SCHEMA like 'EURO4' LIMIT 50 
[4] TRACE 05/11/2019 17:46:13.306 portail400: execSql: execute()...
Execute().
SQLExecuteAsync(0): 
SQLNUMRESULTSCOLS(0) Column Count = 49
SQLDescribeCol(0)       index[0]        sqlType[12]     colScale[0]     colPrecise[128] 
SQLDescribeCol(0)       index[1]        sqlType[12]     colScale[0]     colPrecise[128] 
SQLDescribeCol(0)       index[2]        sqlType[12]     colScale[0]     colPrecise[128] 
SQLDescribeCol(0)       index[3]        sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[4]        sqlType[12]     colScale[0]     colPrecise[8] 
SQLDescribeCol(0)       index[5]        sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[6]        sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[7]        sqlType[1]      colScale[0]     colPrecise[1] 
SQLDescribeCol(0)       index[8]        sqlType[1]      colScale[0]     colPrecise[1] 
SQLDescribeCol(0)       index[9]        sqlType[18]     colScale[0]     colPrecise[2000]
SQLDescribeCol(0)       index[10]       sqlType[1]      colScale[0]     colPrecise[1] 
SQLDescribeCol(0)       index[11]       sqlType[18]     colScale[0]     colPrecise[60]
SQLDescribeCol(0)       index[12]       sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[13]       sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[14]       sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[15]       sqlType[12]     colScale[0]     colPrecise[128] 
SQLDescribeCol(0)       index[16]       sqlType[18]     colScale[0]     colPrecise[2000]
SQLDescribeCol(0)       index[17]       sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[18]       sqlType[4]      colScale[0]     colPrecise[4] 
SQLDescribeCol(0)       index[19]       sqlType[4]      colScale[0]     colPrecise[4]
SQLDescribeCol(0)       index[20]       sqlType[4]      colScale[0]     colPrecise[4]
SQLDescribeCol(0)       index[21]       sqlType[18]     colScale[0]     colPrecise[50] 
SQLDescribeCol(0)       index[22]       sqlType[1]      colScale[0]     colPrecise[10] 
SQLDescribeCol(0)       index[23]       sqlType[1]      colScale[0]     colPrecise[10] 
SQLDescribeCol(0)       index[24]       sqlType[1]      colScale[0]     colPrecise[10] 
SQLDescribeCol(0)       index[25]       sqlType[12]     colScale[0]     colPrecise[128]
SQLDescribeCol(0)       index[26]       sqlType[12]     colScale[0]     colPrecise[128]
SQLDescribeCol(0)       index[27]       sqlType[12]     colScale[0]     colPrecise[3]
SQLDescribeCol(0)       index[28]       sqlType[12]     colScale[0]     colPrecise[10] 
SQLDescribeCol(0)       index[29]       sqlType[3]      colScale[0]     colPrecise[31] 
SQLDescribeCol(0)       index[30]       sqlType[3]      colScale[0]     colPrecise[31] 
SQLDescribeCol(0)       index[31]       sqlType[3]      colScale[0]     colPrecise[31] 
SQLDescribeCol(0)       index[32]       sqlType[3]      colScale[0]     colPrecise[31] 
SQLDescribeCol(0)       index[33]       sqlType[12]     colScale[0]     colPrecise[3]
SQLDescribeCol(0)       index[34]       sqlType[4]      colScale[0]     colPrecise[4]
SQLDescribeCol(0)       index[35]       sqlType[12]     colScale[0]     colPrecise[3]
SQLDescribeCol(0)       index[36]       sqlType[15]     colScale[0]     colPrecise[2097152]
SQLDescribeCol(0)       index[37]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[38]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[39]       sqlType[4]      colScale[0]     colPrecise[4]
SQLDescribeCol(0)       index[40]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[41]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[42]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[43]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[44]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[45]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[46]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[47]       sqlType[1]      colScale[0]     colPrecise[1]
SQLDescribeCol(0)       index[48]       sqlType[1]      colScale[0]     colPrecise[1]
bindColData < 0
[4] TRACE 05/11/2019 17:46:13.347 portail400: execSql: fetchAll()...
FetchAllAsync(). 
[4] TRACE 05/11/2019 17:46:13.347 portail400:execSql: ...post fetchAll()...

`

jasonclake commented 4 years ago

The following simple test using a local idb copy with more debug messages

console.log("node: ", process.version);
console.log('idb:', require("idb-connector/package.json").version);
//const { dbconn, dbstmt, SQL_ATTR_AUTOCOMMIT, SQL_FALSE } = require("idb-connector");
const { dbconn, dbstmt } = require('../idb/lib/db2a');

function runsqlp(sql, conn) {
    return new Promise((resolve) => {
        let statement = new dbstmt(conn);
        statement.exec(sql, (result, error) => {
            if (error) {
                statement.close();
                return resolve(err);
            }
            statement.close();
            resolve(result);
        });
    });
}

async function test() {
    console.log("```debug output");
    const connection = new dbconn();
    connection.debug(true);
    connection.conn("*LOCAL");
    console.log("---------------------------------------------");
    result = await runsqlp(
        `SELECT  
        'ABC'/ 10 AS DIVERR
    from sysibm.sysdummy1`,
        connection
    );
    console.log("```debug output \n");
    console.log(`\`\`\` result output \n ${JSON.stringify(result,null," ")} \n\`\`\``);
}

test();

fetchData is returning -2 for colLen on first col causing a segFault https://github.com/IBM/nodejs-idb-connector/blob/5e753bb69c9fbbd192b5f248def9e498bdb5a2d4/src/db2ia/dbstmt.cc#L2050


node:  v10.15.3
idb: 1.2.3
SQLConnect(0): conn obj [180345510] handler [2]
---------------------------------------------
SQLExecDirect(0): SELECT
        'ABC'/ 10 AS DIVERR
    from sysibm.sysdummy1
SQLNUMRESULTSCOLS(0) Column Count = 1
SQLDescribeCol(0)       index[0]        sqlType[4]      colScale[0]     colPrecise[4]
SQLFetch(1)
SQLFetch col(col: [0].rlength)=-2
Segmentation fault (core dumped)

dmabupt commented 4 years ago

Thanks @jasonclake and @Didier68 for the detailed information. I will deliver a fix for it.

dmabupt commented 4 years ago

I would like to keep the same behavior of STRSQL and ACS, which means --

the inconsistent data will not terminate the query process
it will not generate error messages but warning messages
the inconsistent data will be replaced with a special character (- in ACS and + in STRSQL)

Commit 807eba0 is ready. It changes the API fetch and fetchAll. The essential code changes are -- https://github.com/IBM/nodejs-idb-connector/commit/807eba062039ed0fb3fbedd089d349a4c9346ecd#diff-b307b5c576890c839b53066078db965cR1072 https://github.com/IBM/nodejs-idb-connector/commit/807eba062039ed0fb3fbedd089d349a4c9346ecd#diff-b307b5c576890c839b53066078db965cR1269

Test code snippet for SQL SELECT 'ABC'/10 AS DIVERR from sysibm.sysdummy1

        // statement.fetch((resultSet, err) => {
        statement.fetchAll((resultSet, err) => {
            if(err) console.error(err);
            console.log(JSON.stringify(resultSet));
        });

output:

-bash-4.4$ node exception.js 
SQLSTATE=01565 SQLCODE=420 Character in CAST argument not valid.
{"DIVERR":"-"}
-bash-4.4$ node exception.js 
SQLSTATE=02000 SQLCODE=100 Row not found for C46024600002000003.
[{"DIVERR":"-"}]

I may need more time the verify the code change. But you can try the patch now if you have the build/test environment.

dmabupt commented 4 years ago

Hello @jasonclake and @Didier68 , I just have updated idb-connector to v1.2.4. Would you upgrade and verify this issue please?

Didier68 commented 4 years ago

Hello @dmabupt , I tested this new version, and it seems good. Thanks for your help.

IBM / nodejs-idb-connector

Unhandling exception during dbstmt.fetchAll() #94