Hapijs and iToolkit async issue

Issue #8 new
Aaron Bartell created an issue

The following is a complete debug test of an issue encountered when trying to use Hapijs and iToolkit in async fashion. Using iToolkit in sync fashion works, and async doesn't.

Environment:

  • IBM i v7.2
  • Node v6.9.1 with latest SI64400 PTF installed.

Steps to recreate the issue:

$ export PATH=/QOpenSys/QIBM/ProdData/OPS/Node6/bin:$PATH
$ mkdir hapijs_itoolkit_bug && cd hapijs_itoolkit_bug
$ npm init
$ npm install hapi --save

Put the following in hapijs_itoolkit_bug/server.js

'use strict';

const Hapi = require('hapi');
const server = new Hapi.Server();
server.connection({ 
  host: '0.0.0.0', 
  port: process.env.PORT || 8000
});

server.route([
  {
    method: 'GET',
    path:'/itoolkit', 
    handler: function (request, reply) {
      var xt = require("/QOpenSys/QIBM/ProdData/OPS/Node6/os400/xstoolkit/lib/itoolkit");
      var conn = new xt.iConn("*LOCAL");
      var sysVal = "QCCSID";
      var outBuf = [
             [0, "10i0"],
             [0, "10i0"],
             ["", "10A"],
             ["", "1A"],
             ["", "1A"],
             [0, "10i0"],
             [0, "10i0"]
      ];
      var errno = [
             [0, "10i0"],
             [0, "10i0", {"setlen":"rec2"}],
             ["", "7A"],
             ["", "1A"]
      ];
      var pgm = new xt.iPgm("QWCRSVAL", {"lib":"QSYS"});
      pgm.addParam(outBuf, {"io":"out", "len":"rec1"});
      pgm.addParam(0, "10i0", {"setlen":"rec1"});
      pgm.addParam(1, "10i0");
      pgm.addParam(sysVal, "10A");
      pgm.addParam(errno, {"io":"both", "len" : "rec2"});
      conn.add(pgm);
      conn.run(function(str) {
        var results = xt.xmlToJson(str)
        reply({ results: results })
      });      
    }
  },
  {
    method: 'GET',
    path:'/clear', 
    handler: function (request, reply) {
      reply({name:'value'})
    }
  }
])

server.start((err) => {
  if (err) 
    throw err;
  console.log('Server running at:', server.info.uri);
});

Start the web server.

$ npm start                               

> hapijs_itoolkit_bug@1.0.0 start /home/USR707MS/hapijs_itoolkit_bug            
> node server.js                                                                

Server running at: http://0.0.0.0:8000 

Watch this video to see how I work to prove that hapijs hangs when iToolkit is involved. It stops hanging if I make an additional call to a different endpoint that doesn't involve the iToolkit.

In the video I show that the async DB2 driver isn't working as expected. I then change it to use the sync approach with the following code change. After making this change it works; it doesn't hang.

      conn.run(function(str) {
        var results = xt.xmlToJson(str)
        reply({ results: results })
      }, true);      // <------ true means set to synchronous

Below is an excerpt from istoredp.js (the part of nodejs-itoolkit that talks to DB2).

      var stmt = new db.dbstmt(conn);
      if(sync == true) {  // Sync Mode
        stmt.prepareSync(sql);
        stmt.bindParamSync([
          [xipc, db.SQL_PARAM_INPUT, 1],
          [xctl, db.SQL_PARAM_INPUT, 1],
          [xml_input_script, db.SQL_PARAM_INPUT, 0],
          [xmlOut, db.SQL_PARAM_OUTPUT, 0],
        ]);
        stmt.executeSync(function(outArray) {  //out is an array of the output parameters.
          if(outArray.length == 1)
            callback(outArray[0]);  // For XML service, there is always only one return XML output. So handle it directly.
          else
            callback(outArray);  // For multiple return result, caller should handle it as an array.
          stmt.close();
          conn.disconn();
          conn.close();
        });
      } else {  // Async Mode
        stmt.prepare(sql, function(){
          stmt.bindParam([
            [xipc, db.SQL_PARAM_INPUT, 1],
            [xctl, db.SQL_PARAM_INPUT, 1],
            [xml_input_script, db.SQL_PARAM_INPUT, 0],
            [xmlOut, db.SQL_PARAM_OUTPUT, 0],
          ], function(){
            stmt.execute(function(outArray) {  //out is an array of the output parameters.
              if(outArray.length == 1)
                callback(outArray[0]);  // For XML service, there is always only one return XML output. So handle it directly.
              else
                callback(outArray);  // For multiple return result, caller should handle it as an array.
              stmt.close();
              conn.disconn();
              conn.close();
            });
          });
        });
      }

After reviewing the code it appears the issue is somewhere within the closed source components of the stmt object, so I can't debug further.

Comments (15)

  1. Former user Account Deleted

    After reviewing the code it appears the issue is somewhere within the closed source components of the stmt object, so I can't debug further.

    Two actions come to mind for debug:

    1) Switch your itoolkit test to REST to eliminate 'toolkit' (and xmlservice).

    2) Use new db2sock libdb400.a with TRACE=on to trace offending node db2 driver.

    Do you understand these actions?

  2. Aaron Bartell reporter

    I determined to not focus on iToolkit and instead on db2a.js. After some further testing I believe the issue is either with my lack of understanding of how the IBM's Node.js DB2 async driver works, or there is a bug.

    Below is a small program (db.js) and it doesn't produce two result sets as expected.

    var db = require('/QOpenSys/QIBM/ProdData/OPS/Node6/os400/db2i/lib/db2a');
    var dbconn = new db.dbconn();  
    dbconn.conn("*LOCAL");  
    var stmt = new db.dbstmt(dbconn);
    
    var sql = "SELECT STATE,LSTNAM FROM QIWS.QCUSTCDT LIMIT 1";
    stmt.exec(sql, function(result1, err1) {
      console.log("Result1: %s", JSON.stringify(result1));
    
      stmt.exec(sql, function(result2, err2) {
        console.log("Result2: %s", JSON.stringify(result2));
    
        stmt.close();  
        dbconn.disconn();
        dbconn.close();  
      });
    });
    
    $ node db.js
    Result1: [{"STATE":"TX","LSTNAM":"Henning "}]
    Result2: []
    

    If I pull the second call from the callback and put it at the top level then I get even more interesting results:

    var db = require('/QOpenSys/QIBM/ProdData/OPS/Node6/os400/db2i/lib/db2a');
    var dbconn = new db.dbconn();  
    dbconn.conn("*LOCAL");  
    var stmt = new db.dbstmt(dbconn);
    
    var sql = "SELECT STATE,LSTNAM FROM QIWS.QCUSTCDT LIMIT 1";
    stmt.exec(sql, function(result1, err1) {
      console.log("Result1: %s", JSON.stringify(result1));
    });
    
    stmt.exec(sql, function(result2, err2) {
      console.log("Result2: %s", JSON.stringify(result2));
    });
    

    I expect Result1 and Result2 to alternate finishing first, but the last invocation is missing the STATE column name. Yikes!

    $ node db.js
    Result1: [{"STATE":"TX","LSTNAM":"Henning "}]
    Result2: []
    $ node db.js
    Result2: [{"STATE":"TX","LSTNAM":"Henning "}]
    Result1: []
    $ node db.js
    Result2: []
    Result1: [{"":"TX","LSTNAM":"Henning "}]
    

    The IBM Node.js db2a.js documentation does have an example for concurrent statements**, and that worries me because the other queries in the docs should also be concurrent capable, right?

    ** The example in the documentation was incomplete (didn't have sql variable defined).

    var dba = require('/QOpenSys/QIBM/ProdData/OPS/Node6/os400/db2i/lib/db2a');
    var dbconn = new dba.dbconn();
    dbconn.conn("*LOCAL");
    
    var sqlA = new dba.dbstmt(dbconn);
    var sqlB = new dba.dbstmt(dbconn);
    
    var sql = "SELECT STATE,LSTNAM FROM QIWS.QCUSTCDT LIMIT 1";
    
    sqlA.exec(sql, function(result,err) {
      console.log("sqlA: %s", JSON.stringify(result));
      sqlA.close();
    });
    
    sqlB.exec(sql, function(result,err) {
      console.log("sqlB: %s", JSON.stringify(result));
      sqlB.close();
    });
    
    setTimeout(function(){
      dbconn.disconn();
      dbconn.close();
    },1000);  //Sleep for 1 second to wait for both queries done.
    

    That does reliably produce the correct results:

    $ node db_concurrent.js
    sqlB: [{"STATE":"TX","LSTNAM":"Henning "}]
    sqlA: [{"STATE":"TX","LSTNAM":"Henning "}]
    

    But this is a problem - it only worked because I had separately named SQL statement variable. When I write a web app I don't create a newly named SQL statement variable for each request.

    FWIW, I haven't (yet) put the db2sock libdb400.a in place. I first need to determine if the base db2a.js is broke.

  3. Former user Account Deleted

    So, yes, problems with db2a async ... mmm ... ignore for moment ...

    More important is problem with human Aaron ...

    The golden rule of DB2 is never share a resource across threads (connection,statement, any resource, etc.).

    Guess what? When you evoke two stmt.exec(), they MAY be running in separate threads. Boom!!! You, human named Aaron broke db2 golden rule and shared the connection across two threads. Correction is create two connections each with a statement (connection pool like bears example).

  4. Former user Account Deleted

    And it gets worse ... last example may be running just 'lucky' because you are still sharing the same connection. And ... now it gets really creepy ... and ... depending on the sql action maybe it works, maybe it does not work. Again, DB2 does not 'promise' sharing a connection across threads will work, even though in this case you have two different statements.

  5. Former user Account Deleted

    Do you understand (and believe) what i am telling you about DB2 resource 'sharing'?

  6. Former user Account Deleted

    BTW - More help to believe the rule.

    The golden rule of DB2 is never share a resource across threads (connection,statement, any resource, etc.).

    Perhaps obvious, but worth mentioning historical, 'server mode', aka, QSQSRVR proxy jobs where created specifically to allow multiple threads each with separate transactions all running at the same time for Java. Wherein, 'good Java applications', most often runs as a single process with many threads handling actions (like db2 statements, etc.). The same is true for node 'asnyc' db2a, where 'asynchronous threads handling i/o' are exception 'no threads' node narrative ('a little white lie').

    Also ... sadly ... there exist DB2 experts inside and outside, who do not understand/believe 'do not share across threads' issue. Unfortunately, human observations make matters worse, that is, sometimes, sql action dependent, timing dependent, alignment of stars, fortune teller smiling, sharing db2 resource across threads will actually work. Yikes! Try explain that to the unbeliever.

  7. Former user Account Deleted

    Last post (sorry for rambling, just trying to help with 'db2 side') ...

    Summary.

    Correction for your db2 non-toolkit tests is create two connections each with a statement (connection pool like bears example).

    Correction for your toolkit test 'async path' is not understood (by me). Code istoredp.js appears new connection created every call to db2Call. Should work (slow). Mmmm ... we probably need a TRACE libdb400.a. I would do myself, but i do not know anything about Hapi.Server (odd name for a sad problem).

    var db2Call = function(callback,xlib,xdatabase,xuser,xpassword,xipc,xctl,xml_input_script,xbuf,debug,sync) {
    :
        else {  // Node.js v4 and above.
          db = require('../../db2i/lib/db2a');
          var conn = new db.dbconn();
          conn.setConnAttr(db.SQL_ATTR_DBC_SYS_NAMING , db.SQL_FALSE);
          if(__getClass(debug) == "Boolean")
            conn.debug(debug);
          if(xuser && xuser.length > 0 && xpassword && xpassword.length > 0)
            conn.conn(xdatabase, xuser, xpassword);
          else
            conn.conn(xdatabase);
    

    BTW -- I believe REST from nodejs is default 'async', so calling Apache toolkit via rest interface may shed some light on 'toolkit problem'.

  8. Aaron Bartell reporter

    Try explain that to the unbeliever.

    Well, you've made me a believer :-) (of course, I believed you before, I just didn't understand how things were implemented under the covers, because, well, it's still closed source)

    Correction is create two connections each with a statement (connection pool like bears example).

    I think we need to bring your bears code to the forefront and have connection pooling be a formal addition to the needs-to-be-open-sourced-sooner-than-later Node.js DB2 driver.

    Again, DB2 does not 'promise' sharing a connection across threads will work, even though in this case you have two different statements.

    I need to clarify this to make sure I understand, because I believe it goes against the current IBM developerWorks docs. Are you saying the existing concurrent example** isn't guaranteed to always work because there should always be a one-to-one relationship between connections and statements?

    **

    var dba = require('/QOpenSys/QIBM/ProdData/OPS/Node6/os400/db2i/lib/db2a');
    var dbconn = new dba.dbconn();
    dbconn.conn("*LOCAL");
    
    var sqlA = new dba.dbstmt(dbconn);
    var sqlB = new dba.dbstmt(dbconn);
    
    var sql = "SELECT STATE,LSTNAM FROM QIWS.QCUSTCDT LIMIT 1";
    
    sqlA.exec(sql, function(result,err) {
      console.log("sqlA: %s", JSON.stringify(result));
      sqlA.close();
    });
    
    sqlB.exec(sql, function(result,err) {
      console.log("sqlB: %s", JSON.stringify(result));
      sqlB.close();
    });
    
    setTimeout(function(){
      dbconn.disconn();
      dbconn.close();
    },1000); 
    
  9. Former user Account Deleted

    Are you saying the existing concurrent example** isn't guaranteed to always work because there should always be a one-to-one relationship between connections and statements?

    Yes.

    BTW -- If there is a 'async' example documented sharing a connection it wrong!

  10. Former user Account Deleted

    Not to confuse (ignore if already) ... Technically, could be many statements for one connection, but only one statement running at a time. That is, your QSQSRVR job run one thing at a time (not thread safe).

    Practically speaking, your node application would have to sync statements manually so that only one statement ran, then the next statement, etc. I suspect collecting the result sets could even alternate (if db2a provided fetch 'async'), but only one 'record' at a time. Aka, some people refer to this 'force sync' as 'taming node callback' (personally ... makes me feel sick to think of corrupting such a nice callback language).

  11. Former user Account Deleted

    Search for "Concurrent Query" on the following IBM developerWorks URL: http://bit.ly/dw-nodejs-async

    Yep... wrong! Probably works most of the time (place your bets before the wheel spins).

    var sqlA = new dba.dbstmt(dbconn);
    var sqlB = new dba.dbstmt(dbconn);
    
  12. Aaron Bartell reporter

    Yep... wrong! Probably works most of the time (place your bets before the wheel spins).

    ouch. Ok, well, I am off to create some form of reusable module from your bear.js so I can get that into my customer's hands that have Node.js in production.

  13. Aaron Bartell reporter

    Ok, I do realize we're way off topic conversing about Node.js DB2 connection pools in the Node.js iToolkit, but I wanted to round off the conversation with the efforts of the last few hours.

    I've put together what I believe is a generic DB2 pool for Node.js based on your bear approach. I stripped out a number of things on purpose so I can incrementally introduce this to the community. Specifically, I like the caching and the callback message decorations (i.e. adding 'ok' and stuff).

    db.js

    // Connection
    // =============================================================================
    Conn = function(idx, database) {
      this.db = require('/QOpenSys/QIBM/ProdData/OPS/Node6/os400/db2i/lib/db2a');
      this.conn = new this.db.dbconn();
      this.conn.conn(database);
      this.inuse = false;
      this.idx = idx;
      this.stmt = new this.db.dbstmt(this.conn);
    }
    Conn.prototype.free = function() {
      var newstmt = new this.db.dbstmt(this.conn); 
      if (this.stmt) {
        delete this.stmt;
      }
      this.stmt = newstmt;
    }
    Conn.prototype.detach = function() {
      var newstmt = new this.db.dbstmt(this.conn); 
      if (this.stmt) {
        delete this.stmt;
      }
      this.stmt = newstmt;
      this.inuse = false;
    }
    Conn.prototype.getInUse = function() {
      return this.inuse;
    }
    Conn.prototype.setInUse = function() {
      this.inuse = true;
    }
    
    // Connection pool
    // =============================================================================
    Pool = function(opt) {
      opt = opt || {};
      this.pool = [];
      this.pmax = 0;
      this.pool_conn_incr_size = 8;
      this.database = opt.database || "*LOCAL";
    }
    Pool.prototype.attach = function(callback) {
      var valid_conn = false;
      while (!valid_conn) {
        // find available connection
        for(var i = 0; i < this.pmax; i++) {
          var inuse = this.pool[i].getInUse();
          if (!inuse) {
            this.pool[i].setInUse();
            callback(this.pool[i]);        
            return;
          }
        }
        // expand the connection pool
        var j = this.pmax;
        for(var i = 0; i < this.pool_conn_incr_size; i++) {
          this.pool[j] = new Conn(j, this.database);
          j++;
        }
        this.pmax += this.pool_conn_incr_size;
      }
    }
    
    Pool.prototype.easy = function(sql, callback){
      this.attach( (conn) => {  
        conn.stmt.exec(sql, function (query) {
          callback(query);
          conn.detach();
        });
      });
    }
    
    exports.Pool = Pool;
    

    pool_test.js

    var db = require('./models/db')
    pool = new db.Pool();
    
    var sql = "SELECT LSTNAM FROM QIWS.QCUSTCDT LIMIT 2";
    pool.attach( (conn) => {
      conn.stmt.exec(sql, function (query) {
        conn.detach();
        console.log(`query1: ${JSON.stringify(query,null,2)}`);
      });
    });
    
    pool.easy(sql, (query) => {  
      console.log(`easy: ${JSON.stringify(query,null,2)}`);
    });
    

    To invoke:

    % node pool_test.js
    easy:[
      {
        "LSTNAM": "Henning "
      },
      {
        "LSTNAM": "Jones   "
      }
    ]
    query1:[
      {
        "LSTNAM": "Henning "
      },
      {
        "LSTNAM": "Jones   "
      }
    ]
    

    Do you see anything in db.js that will cause heartache?

  14. Former user Account Deleted

    Do you see anything in db.js that will cause heartache?

    Looks good.

    Minor -- maybe call thing db2pool.js to avoid 'which database' ambiguity.

    Optional (future): This class is essentially a 'persistent connection' pool ... what a day this will be ...

    private connection -- maybe 'key' names to identify various connect<>profile(bob, aaron, tony, lilly). Node applications usually run one process, wherein 'async' worker threads acquire a connection. If the connection is 'key', this allows a http requester to get back to the same connection many times, aka, 'private connection'.

    node toolkit -- Also becomes more useful to node itoolkit of db2Call as a passed 'connect' parameter (move connect outside db2Call). In fact, very good odds toolkiit using connection pool will cure your 'hang' problem with async (but just a guess).

    garbage collect -- maybe needs close recycle counts, timeout, etc. (practical waste management)

    Anyway ... you get the idea. Once started maybe this should be its own litmis/node-db2pool project.

  15. Log in to comment