CODEWITHSUNDEEP
javascriptnode.jsmariadbcloud-foundry
rubio
rubio

Reputation: 966

Nodejs Mariadb on PCF timeout not triggering mariadb events

I have a nodejs application on PCF which connects to a mariadb instance. The instance wait_timeout is 600 so after inactivity it will disconnect after 10 minutes.

On my local machine running this application and connecting to a local instance of mariadb on docker (once timeout hits or when i kill the connection) i will get a MySQL Server has gone away then my application will reconnect and give me my database result. It does not crash locally.

When running this on PCF the mariadb error will crash the application or if the exception is caught it will crash and send a Headers already sent error

I believe that once MariaDB kills the connection somehow the mariadb driver in node is not notified that the connection was terminated even though i have event handlers on the connection. So once my application attempts to run the query it fails because the event was not triggered and its trying to run it on a closed connection.

My connection module

// Loading local .env vars
var route_helper = require("./route_helper");

route_helper.loadLocalEnvVars();

var Client = require('mariasql');
var moment = require('moment');

var connection = null;
try{
    connection = new Client({
    host: process.env.DB_MARIA_HOST,
    user: process.env.DB_MARIA_USER,
    password: process.env.DB_MARIA_PASS,
    db: process.env.DB_MARIA_SCHEMA,
    port: parseInt(process.env.DB_MARIA_PORT),
    connTimeout: 20,
    pingInterval: 1,
    compress: true
  });

  connection.connect(function(err){
      if(!err) {
          if(process.env.DEBUG == "true"){
            console.log("Database is connected");
          }
      } else {
          console.log("Error connecting database " + err.message);  
          console.log(err);
      }
  });

  connection.on('ready',function(){
    if(process.env.DEBUG == "true"){
         console.log("Connection ready " + moment().format('MMMM Do YYYY, h:mm:ss a') )
    }
  });

  connection.on('close',function(){
    if(process.env.DEBUG == "true"){
         console.log("Connection closed " + moment().format('MMMM Do YYYY, h:mm:ss a') )
    }
  });
  connection.on('error',function(err){
    if(process.env.DEBUG == "true"){
         console.log("Connection timeout... Reconnecting")
         console.log(err);
    }
    if(err.code == 2006 ){
      this.connect();
    }
    //this.connect();
  });

}catch(err){
  console.log("Maria_db error")
  console.log(err)
  throw err;
}

module.exports = connection;

Loading Server routers

var routes = require("./routes/application.js").appRouter(server);

var server = server.listen(process.env.PORT, function () {
    console.log("Listening on port %s...", server.address().port);
});

My Route

app.get("/applications", function (req, res) {
        try{
            var applications;       
            var dbConn = require("../util/db.js");

            dbConn.query('SELECT some stuff’, function (error, results) {
                if(!error) {
                    applications = {
                        "apps": results
                    }
                    return res.send(applications);
                } else {
                    return res.send({"status": "error", "message": error.code});
                }
            });
        }catch(err) {
            console.log(err)
        }
    });

MySql has gone away error

2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] OUT { Error: MySQL server has gone away
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] OUT     at /home/vcap/app/node_modules/mariasql/lib/Client.js:223:12
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at Client.<anonymous> (/home/vcap/app/util/dbHealth.js:14:9)
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at emitOne (events.js:101:20)
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at Client.emit (events.js:191:7)
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at Client._onerror (/home/vcap/app/node_modules/mariasql/lib/Client.js:395:10)
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at Client._processQueue (/home/vcap/app/node_modules/mariasql/lib/Client.js:614:18)
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at /home/vcap/app/node_modules/mariasql/lib/Client.js:223:12
   2017-12-20T09:03:55.29-0500 [APP/PROC/WEB/0] ERR     at process._tickCallback (internal/process/next_tick.js:104:9)
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR! Exit status 1
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR! Failed at the [email protected] start script 'node server.js'.
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR! not with npm itself.
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR! You can get information on how to open an issue for this project with:
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR!     npm bugs myapplication
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR! Or if that isn't available, you can get their info via:
   2017-12-20T09:03:55.31-0500 [APP/PROC/WEB/0] ERR npm ERR!     npm owner ls myapplication
   2017-12-20T09:03:55.33-0500 [APP/PROC/WEB/0] ERR npm ERR! Please include the following file with any support request:
   2017-12-20T09:03:55.33-0500 [APP/PROC/WEB/0] ERR npm ERR!     /home/vcap/app/.npm/_logs/2017-12-20T14_03_55_316Z-debug.log

Headers already sent error. They also seem to be out of order which is weird. During this test i am sending 3 http requests to 3 different services and getting this error.

   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at _combinedTickCallback (internal/process/next_tick.js:131:7)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at Client._processQueue (/home/vcap/app/node_modules/mariasql/lib/Client.js:614:18)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at process._tickCallback (internal/process/next_tick.js:180:9) code: 2006 }
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR _http_outgoing.js:494
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at validateHeader (_http_outgoing.js:494:11)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at ServerResponse.send (/home/vcap/app/node_modules/express/lib/response.js:158:21)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at Object.cb (/home/vcap/app/routes/application.js:474:29)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at Client._processQueue (/home/vcap/app/node_modules/mariasql/lib/Client.js:614:18)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at _combinedTickCallback (internal/process/next_tick.js:131:7)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at process._tickCallback (internal/process/next_tick.js:180:9) code: 2006 }
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     throw new Error('Can\'t set headers after they are sent.');
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR Error: Can't set headers after they are sent.
   2017-12-27T11:07:46.41-0500 [APP/PROC/WEB/0] OUT Connection timeout... Reconnecting
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at /home/vcap/app/node_modules/mariasql/lib/Client.js:223:12
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT { Error: MySQL server has gone away
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT { Error: MySQL server has gone away
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at _combinedTickCallback (internal/process/next_tick.js:131:7)
   2017-12-27T11:07:46.41-0500 [APP/PROC/WEB/0] OUT Route: /applications
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT { Error: MySQL server has gone away
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at Client._processQueue (/home/vcap/app/node_modules/mariasql/lib/Client.js:614:18)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at /home/vcap/app/node_modules/mariasql/lib/Client.js:223:12
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at ServerResponse.setHeader (_http_outgoing.js:501:3)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at ServerResponse.header (/home/vcap/app/node_modules/express/lib/response.js:767:10)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at process._tickCallback (internal/process/next_tick.js:180:9) code: 2006 }
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] OUT     at /home/vcap/app/node_modules/mariasql/lib/Client.js:223:12
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     ^
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at ServerResponse.send (/home/vcap/app/node_modules/express/lib/response.js:170:12)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at ServerResponse.json (/home/vcap/app/node_modules/express/lib/response.js:267:15)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at cleanupReqs (/home/vcap/app/node_modules/mariasql/lib/Client.js:744:11)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at Client._onclose (/home/vcap/app/node_modules/mariasql/lib/Client.js:574:5)
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR     at Client._onerror (/home/vcap/app/node_modules/mariasql/lib/Client.js:396:10)
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! Failed at the [email protected] start script.
   2017-12-27T11:07:46.42-0500 [APP/PROC/WEB/0] ERR npm ERR! code ELIFECYCLE
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! 
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! [email protected] start: `node server.js`
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! This is probably not a problem with npm. There is likely additional logging output above.
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! Exit status 1
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! errno 1
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR! A complete log of this run can be found in:
   2017-12-27T11:07:46.43-0500 [APP/PROC/WEB/0] ERR npm ERR!     /home/vcap/app/.npm/_logs/2017-12-27T16_07_46_432Z-debug.log

edit: This application structure was generated by swagger

Upvotes: 0

Views: 288

Answers (1)

rubio
rubio

Reputation: 966

I switch from only mariasql npm driver to knex driver. Even though knex dependancies had mariasql: '^0.2.3' it worked right out of the box with no problems.

Upvotes: 0

Related Questions