Feature/healthcheck improvements (#30)

* health check tests mysql and redis connectivity

* health check tests mysql and redis connectivity

* minor

.eslintrc.json

@@ -8,7 +8,7 @@
       "jsx": false,
       "modules": false
     },
-    "ecmaVersion": 2018
+    "ecmaVersion": 2020
   },
   "plugins": ["promise"],
   "rules": {

.husky/pre-commit

@@ -0,0 +1,4 @@
+#!/bin/sh
+. "$(dirname "$0")/_/husky.sh"
+
+npm run jslint

Dockerfile

@@ -1,7 +1,7 @@
-FROM node:17.4-slim
+FROM node:slim
 WORKDIR /opt/app/
-COPY package.json ./
-RUN npm install
+COPY package.json package-lock.json ./
+RUN npm ci
 RUN npm prune
 COPY . /opt/app
 ARG NODE_ENV

app.js

@@ -14,6 +14,7 @@ const opts = Object.assign({
 }, {level: process.env.JAMBONES_LOGLEVEL || 'info'});
 const logger = require('pino')(opts);
 const {
+  writeCallCount,
   queryCdrs,
   writeCdrs,
   writeAlerts,
@@ -26,7 +27,7 @@ const {
 });
 const StatsCollector = require('@jambonz/stats-collector');
 const stats = new StatsCollector(logger);
-const {equalsIgnoreOrder} = require('./lib/utils');
+const {equalsIgnoreOrder, createHealthCheckApp, systemHealth} = require('./lib/utils');
 const {LifeCycleEvents} = require('./lib/constants');
 const setNameRtp = `${(process.env.JAMBONES_CLUSTER_ID || 'default')}:active-rtp`;
 const rtpServers = [];
@@ -34,6 +35,7 @@ const setName = `${(process.env.JAMBONES_CLUSTER_ID || 'default')}:active-sip`;
 
 const {
   pool,
+  ping,
   lookupAuthHook,
   lookupSipGatewayBySignalingAddress,
   addSbcAddress,
@@ -49,7 +51,14 @@ const {
   database: process.env.JAMBONES_MYSQL_DATABASE,
   connectionLimit: process.env.JAMBONES_MYSQL_CONNECTION_LIMIT || 10
 }, logger);
-const {createSet, retrieveSet, addToSet, removeFromSet, incrKey, decrKey} = require('@jambonz/realtimedb-helpers')({
+const {
+  client: redisClient,
+  createSet,
+  retrieveSet,
+  addToSet,
+  removeFromSet,
+  incrKey,
+  decrKey} = require('@jambonz/realtimedb-helpers')({
   host: process.env.JAMBONES_REDIS_HOST || 'localhost',
   port: process.env.JAMBONES_REDIS_PORT || 6379
 }, logger);
@@ -61,6 +70,7 @@ const {getRtpEngine, setRtpEngines} = require('@jambonz/rtpengine-utils')([], lo
 });
 srf.locals = {...srf.locals,
   stats,
+  writeCallCount,
   queryCdrs,
   writeCdrs,
   writeAlerts,
@@ -69,6 +79,7 @@ srf.locals = {...srf.locals,
   getRtpEngine,
   dbHelpers: {
     pool,
+    ping,
     lookupAuthHook,
     lookupSipGatewayBySignalingAddress,
     lookupAccountByPhoneNumber,
@@ -138,7 +149,9 @@ if (process.env.DRACHTIO_HOST && !process.env.K8S) {
   });
 }
 else {
-  logger.info(`listening in outbound mode on port ${process.env.DRACHTIO_PORT}`);
+  srf.on('listening', () => {
+    logger.info(`listening in outbound mode on port ${process.env.DRACHTIO_PORT}`);
+  });
   srf.listen({port: process.env.DRACHTIO_PORT, secret: process.env.DRACHTIO_SECRET});
 }
 if (process.env.NODE_ENV === 'test') {
@@ -171,11 +184,31 @@ srf.use((req, res, next, err) => {
   res.send(500);
 });
 
-if (process.env.K8S) {
+if (process.env.K8S || process.env.HTTP_PORT) {
   const PORT = process.env.HTTP_PORT || 3000;
-  const getCount = () => activeCallIds.size;
   const healthCheck = require('@jambonz/http-health-check');
-  healthCheck({port: PORT, logger, path: '/', fn: getCount});
+
+  const getCount = () => srf.locals.activeCallIds.size;
+
+  createHealthCheckApp(PORT, logger)
+    .then((app) => {
+      healthCheck({
+        app,
+        logger,
+        path: '/',
+        fn: getCount
+      });
+      healthCheck({
+        app,
+        logger,
+        path: '/system-health',
+        fn: systemHealth.bind(null, redisClient, ping, getCount)
+      });
+      return;
+    })
+    .catch((err) => {
+      logger.error({err}, 'Error creating health check server');
+    });
 }
 if ('test' !== process.env.NODE_ENV) {
   /* update call stats periodically */

lib/call-session.js

@@ -171,7 +171,7 @@ class CallSession extends Emitter {
           '-Session-Expires',
           '-X-Subspace-Forwarded-For'
         ],
-        proxyResponseHeaders: ['all'],
+        proxyResponseHeaders: ['all', '-X-Trace-ID'],
         localSdpB: response.sdp,
         localSdpA: async(sdp, res) => {
           this.rtpEngineOpts.uac.tag = res.getParsedHeader('To').params.tag;
@@ -204,7 +204,7 @@ class CallSession extends Emitter {
         const tags = ['accepted:no', `sipStatus:${err.status}`, `originator:${this.req.locals.originator}`];
         this.stats.increment('sbc.terminations', tags);
         this.logger.info(`call failed to connect to feature server with ${err.status}`);
-        return this.emit('failed');
+        this.emit('failed');
       }
       else if (err.message !== 'call canceled') {
         this.logger.error(err, 'unexpected error routing inbound call');
@@ -241,22 +241,30 @@ class CallSession extends Emitter {
       this.req.locals.cdr = {
         ...this.req.locals.cdr,
         answered: true,
-        answered_at: callStart
+        answered_at: callStart,
+        trace_id: uac.res?.get('X-Trace-ID') || '00000000000000000000000000000000'
       };
     }
     this.uas = uas;
     this.uac = uac;
     [uas, uac].forEach((dlg) => {
-      dlg.on('destroy', () => {
-        this.logger.info('call ended with normal termination');
+      dlg.on('destroy', async() => {
+        const other = dlg.other;
         this.rtpEngineResource.destroy().catch((err) => {});
         this.activeCallIds.delete(this.req.get('Call-ID'));
-        dlg.other.destroy().catch((e) => {});
+        try {
+          await other.destroy();
+        } catch (err) {}
         this.unsubscribeDTMF(this.logger, this.req.get('Call-ID'), this.rtpEngineOpts.uas.tag);
-        if (process.env.JAMBONES_HOSTING) {
+        if (process.env.JAMBONES_HOSTING || process.env.JAMBONES_TRACK_ACCOUNT_CALLS) {
+          const {account_sid} = this.req.locals;
           this.decrKey(this.callCountKey)
-            .then((count) => this.logger.debug({key: this.callCountKey},
-              `after hangup there are ${count} active calls for this account`))
+            .then((count) => {
+              this.logger.info(
+                {key: this.callCountKey},
+                `after hangup there are ${count} active calls for this account`);
+              return this.req.srf.locals.writeCallCount({account_sid, calls_in_progress: count});
+            })
             .catch((err) => this.logger.error({err}, 'Error decrementing call count'));
         }
 
@@ -274,6 +282,13 @@ class CallSession extends Emitter {
             trunk
           }).catch((err) => this.logger.error({err}, 'Error writing cdr for completed call'));
         }
+        /* de-link the 2 Dialogs for GC */
+        dlg.removeAllListeners();
+        other.removeAllListeners();
+        dlg.other = null;
+        other.other = null;
+
+        this.logger.info(`call ended with normal termination, there are ${this.activeCallIds.size} active`);
         this.srf.endSession(this.req);
       });
     });
@@ -618,8 +633,20 @@ Duration=${payload.duration} `
       }
     }
     else {
-      // TODO: forward on to feature server
-      res.send(501);
+      /* REFER coming in from a sip device, forward to feature server */
+      try {
+        const response = await dlg.other.request({
+          method: 'REFER',
+          headers: {
+            'Refer-To': req.get('Refer-To'),
+            'Referred-By': req.get('Referred-By'),
+            'User-Agent': req.get('User-Agent')
+          }
+        });
+        res.send(response.status, response.reason);
+      } catch (err) {
+        this.logger.error({err}, 'CallSession:_onRefer: error handling incoming REFER');
+      }
     }
   }
 

lib/middleware.js

@@ -220,11 +220,11 @@ module.exports = function(srf, logger) {
   };
 
   const checkLimits = async(req, res, next) => {
-    if (!process.env.JAMBONES_HOSTING) return next(); // skip
+    if (!process.env.JAMBONES_HOSTING && !process.env.JAMBONES_TRACK_ACCOUNT_CALLS) return next(); // skip
 
     const {incrKey, decrKey} = req.srf.locals.realtimeDbHelpers;
     const {logger, account_sid} = req.locals;
-    const {writeAlerts, AlertType} = req.srf.locals;
+    const {writeCallCount, writeAlerts, AlertType} = req.srf.locals;
     assert(account_sid);
     const key = makeCallCountKey(account_sid);
 
@@ -233,10 +233,11 @@ module.exports = function(srf, logger) {
       if (status > 200) {
         decrKey(key)
           .then((count) => {
-            logger.debug({key}, `after rejection there are ${count} active calls for this account`);
+            logger.info({key}, `after rejection there are ${count} active calls for this account`);
             debug({key}, `after rejection there are ${count} active calls for this account`);
-            return;
+            return count;
           })
+          .then((count) => writeCallCount({account_sid, calls_in_progress: count}))
           .catch((err) => logger.error({err}, 'checkLimits: decrKey err'));
       }
     });
@@ -244,6 +245,10 @@ module.exports = function(srf, logger) {
     try {
       /* increment the call count */
       const calls = await incrKey(key);
+      writeCallCount({account_sid, calls_in_progress: calls})
+        .then(() => logger.info(`checkLimits: after incrementing there are ${calls} active calls for this account`))
+        .catch((err) => logger.error({err}, 'checkLimits: error writing call count'));
+      if (!process.env.JAMBONES_HOSTING) return next();
 
       /* compare to account's limit, though avoid db hit when call count is low */
       const minLimit = process.env.MIN_CALL_LIMIT ?

lib/utils.js

@@ -56,6 +56,26 @@ const equalsIgnoreOrder = (a, b) => {
   return true;
 };
 
+const  systemHealth = async(redisClient, ping, getCount) => {
+  await Promise.all([redisClient.ping(), ping()]);
+  return getCount();
+};
+
+const createHealthCheckApp = (port, logger) => {
+  const express = require('express');
+  const app = express();
+
+  app.use(express.urlencoded({ extended: true }));
+  app.use(express.json());
+
+  return new Promise((resolve) => {
+    app.listen(port, () => {
+      logger.info(`Health check server started at http://localhost:${port}`);
+      resolve(app);
+    });
+  });
+};
+
 module.exports = {
   isWSS,
   SdpWantsSrtp,
@@ -63,5 +83,7 @@ module.exports = {
   makeRtpEngineOpts,
   makeCallCountKey,
   normalizeDID,
-  equalsIgnoreOrder
+  equalsIgnoreOrder,
+  systemHealth,
+  createHealthCheckApp
 };

liveness.sh

@@ -0,0 +1,24 @@
+#!/bin/sh
+
+TCP_SERVER_PORT="${DRACHTIO_PORT:-4000}"
+nc -v -z localhost $TCP_SERVER_PORT
+
+# if last command exited with non zero
+if [ $? != 0 ]
+then
+    exit 1
+fi
+
+HTTP_SERVER_PORT="${HTTP_PORT:-3000}"
+
+printf 'GET /system-health HTTP/1.1\r\nHost: localhost\r\n\r\n' | nc -v localhost 3000 | grep calls
+
+# grep will automatically exit with 1 if string is not matched, however, will leave that call there in case 
+# we pivot to pipe to dev/null
+
+if [ $? != 0 ]
+then
+    exit 1
+fi
+
+exit 0

package.json

@@ -1,6 +1,6 @@
 {
   "name": "sbc-inbound",
-  "version": "v0.7.2",
+  "version": "v0.7.5",
   "main": "app.js",
   "engines": {
     "node": ">= 12.0.0"
@@ -20,25 +20,26 @@
   },
   "scripts": {
     "start": "node app",
-    "test": "NODE_ENV=test JAMBONES_NETWORK_CIDR='127.0.0.1/32' JAMBONES_HOSTING=1 SBC_ACCOUNT_SID=ed649e33-e771-403a-8c99-1780eabbc803 JAMBONES_TIME_SERIES_HOST=127.0.0.1 JAMBONES_MYSQL_HOST=127.0.0.1 JAMBONES_MYSQL_USER=jambones_test JAMBONES_MYSQL_PASSWORD=jambones_test JAMBONES_MYSQL_DATABASE=jambones_test JAMBONES_REDIS_HOST=localhost JAMBONES_REDIS_PORT=16379 JAMBONES_LOGLEVEL=error DRACHTIO_SECRET=cymru DRACHTIO_HOST=127.0.0.1 DRACHTIO_PORT=9060 JAMBONES_RTPENGINES=127.0.0.1:12222 JAMBONES_FEATURE_SERVERS=172.38.0.11 node test/ ",
+    "test": "NODE_ENV=test HTTP_PORT=3050 JAMBONES_NETWORK_CIDR='127.0.0.1/32' JAMBONES_HOSTING=1 SBC_ACCOUNT_SID=ed649e33-e771-403a-8c99-1780eabbc803 JAMBONES_TIME_SERIES_HOST=127.0.0.1 JAMBONES_MYSQL_HOST=127.0.0.1 JAMBONES_MYSQL_USER=jambones_test JAMBONES_MYSQL_PASSWORD=jambones_test JAMBONES_MYSQL_DATABASE=jambones_test JAMBONES_REDIS_HOST=localhost JAMBONES_REDIS_PORT=16379 JAMBONES_LOGLEVEL=info DRACHTIO_SECRET=cymru DRACHTIO_HOST=127.0.0.1 DRACHTIO_PORT=9060 JAMBONES_RTPENGINES=127.0.0.1:12222 JAMBONES_FEATURE_SERVERS=172.38.0.11 node test/ ",
     "coverage": "./node_modules/.bin/nyc --reporter html --report-dir ./coverage npm run test",
     "jslint": "eslint app.js lib"
   },
   "dependencies": {
-    "@jambonz/db-helpers": "^0.6.16",
+    "@jambonz/db-helpers": "^0.6.18",
     "@jambonz/http-authenticator": "^0.2.0",
     "@jambonz/http-health-check": "^0.0.1",
-    "@jambonz/realtimedb-helpers": "^0.4.9",
-    "@jambonz/rtpengine-utils": "^0.3.0-beta.3",
+    "@jambonz/realtimedb-helpers": "^0.4.24",
+    "@jambonz/rtpengine-utils": "^0.3.1",
     "@jambonz/stats-collector": "^0.1.6",
-    "@jambonz/time-series": "^0.1.6",
+    "@jambonz/time-series": "^0.1.9",
     "aws-sdk": "^2.1036.0",
     "bent": "^7.3.12",
     "cidr-matcher": "^2.1.1",
     "debug": "^4.3.3",
     "drachtio-fn-b2b-sugar": "0.0.12",
     "drachtio-srf": "^4.4.59",
-    "express": "^4.17.1",
+    "express": "^4.17.3",
+    "husky": "^7.0.4",
     "pino": "^7.4.1",
     "rtpengine-client": "^0.2.0",
     "verify-aws-sns-signature": "^0.0.6",

test/sip-tests.js

@@ -1,8 +1,7 @@
 const test = require('tape');
-const { output, sippUac } = require('./sipp')('test_sbc-inbound');
-const debug = require('debug')('drachtio:sbc-inbound');
-const clearModule = require('clear-module');
-const consoleLogger = {error: console.error, info: console.log, debug: console.log};
+const { sippUac } = require('./sipp')('test_sbc-inbound');
+const bent = require('bent');
+const getJSON = bent('json');
 
 process.on('unhandledRejection', (reason, p) => {
   console.log('Unhandled Rejection at: Promise', p, 'reason:', reason);
@@ -28,6 +27,12 @@ test('incoming call tests', async(t) => {
   
   try {
     await connect(srf);
+
+    let obj = await getJSON('http://127.0.0.1:3050/');
+    t.ok(obj.calls === 0, 'HTTP GET / works (current call count)')
+    obj = await getJSON('http://127.0.0.1:3050/system-health');
+    t.ok(obj.calls === 0, 'HTTP GET /system-health works (health check)')
+
     await sippUac('uac-pcap-carrier-success.xml', '172.38.0.20');
     t.pass('incoming call from carrier completed successfully');