support sip recording from a siprec call (#190)

* support sip recording from a siprec call

* update srsClient version

app.js

@@ -68,6 +68,7 @@ const {
 const {
   client: redisClient,
   addKey,
+  deleteKey,
   retrieveKey,
   createSet,
   retrieveSet,
@@ -111,6 +112,7 @@ srf.locals = {...srf.locals,
   },
   realtimeDbHelpers: {
     addKey,
+    deleteKey,
     retrieveKey,
     createSet,
     incrKey,

lib/call-session.js

@@ -347,7 +347,16 @@ class CallSession extends Emitter {
         this.emit('failed');
       }
       else if (err.message !== 'call canceled') {
+        const {writeCallCount, writeCallCountSP, writeCallCountApp} = this.req.srf.locals;
         this.logger.error(err, 'unexpected error routing inbound call');
+        nudgeCallCounts(this.req, 'failure', {
+          service_provider_sid: this.service_provider_sid,
+          account_sid: this.account_sid,
+          application_sid: this.application_sid,
+          callId: this.req.locals.callId
+        }, this.decrKey, {writeCallCountSP, writeCallCount, writeCallCountApp})
+          .catch((err) => this.logger.error(err, 'Error decrementing call counts'));
+
       }
       this.srf.endSession(this.req);
     }
@@ -456,10 +465,11 @@ class CallSession extends Emitter {
           if (!this.req.locals.callCountNudged) {
             this.req.locals.callCountNudged = true;
             this.logger.debug('decrementing call count at end of call');
-            await nudgeCallCounts(this.logger, {
+            await nudgeCallCounts(this.req, 'complete', {
               service_provider_sid: this.service_provider_sid,
               account_sid: this.account_sid,
-              application_sid: this.application_sid
+              application_sid: this.application_sid,
+              callId: this.req.locals.callId
             }, this.decrKey, {writeCallCountSP, writeCallCount, writeCallCountApp})
               .catch((err) => this.logger.error(err, 'Error decrementing call counts'));
           }
@@ -854,7 +864,8 @@ Duration=${payload.duration} `
               blockMedia: this.blockMedia,
               unblockMedia: this.unblockMedia,
               unsubscribe: this.unsubscribe,
-              headers
+              headers,
+              isSipRecCall: Array.isArray(this.req.payload) && this.req.payload.length > 1
             }));
             try {
               this._startRecordingNoAnswerTimer(res);

lib/middleware.js

@@ -35,6 +35,7 @@ module.exports = function(srf, logger) {
   const initLocals = (req, res, next) => {
     const callId = req.get('Call-ID');
     req.locals = req.locals || {callId};
+    req.locals.nudge = 0;
 
     /* check if forwarded by a proxy that applied an X-Forwarded-For Header */
     if (req.has('X-Forwarded-For') || req.has('X-Subspace-Forwarded-For')) {
@@ -267,14 +268,12 @@ module.exports = function(srf, logger) {
 
     /* decrement count if INVITE is later rejected */
     res.once('end', async({status}) => {
-      if (status > 200 && !req.locals.callCountNudged) {
-        req.locals.callCountNudged = true;
-        logger.info('decrementing call count due to call rejection');
-
-        nudgeCallCounts(logger, {
+      if (status > 200) {
+        nudgeCallCounts(req, 'failure', {
           service_provider_sid,
           account_sid,
-          application_sid
+          application_sid,
+          callId: req.locals.callId
         }, decrKey, {writeCallCountSP, writeCallCount, writeCallCountApp})
           .catch((err) => logger.error(err, 'Error decrementing call counts'));
       }
@@ -282,10 +281,11 @@ module.exports = function(srf, logger) {
 
     try {
       /* increment the call count */
-      const  {callsSP, calls} = await nudgeCallCounts(logger, {
+      const  {callsSP, calls} = await nudgeCallCounts(req, 'init', {
         service_provider_sid,
         account_sid,
-        application_sid
+        application_sid,
+        callId: req.locals.callId
       }, incrKey, {writeCallCountSP, writeCallCount, writeCallCountApp});
 
       /* compare to account's limit, though avoid db hit when call count is low */

lib/utils.js

@@ -117,12 +117,97 @@ const createHealthCheckApp = (port, logger) => {
   });
 };
 
-const nudgeCallCounts = async(logger, sids, nudgeOperator, writers) => {
-  const { service_provider_sid, account_sid, application_sid } = sids;
-  const { writeCallCount, writeCallCountSP, writeCallCountApp } = writers;
+/**
+ * nudgeCallCounts - increment or decrement call counts in redis
+ *
+ *              current nudge value
+ * -----------------------------------------
+ *  why    |     -1     |    0    |    1    |
+ * -----------------------------------------
+ *  init   |    no-op   |    +1   |    N/A  |
+ * failure |    N/A     |    -1   |    -1   |
+ * complete|    N/A     |    N/A  |    -1   |
+ *
+ *
+ */
+
+const shouldNudge = (why, req) => {
+  const {nudge, logger} = req.locals;
+  let modifyCount = false;
+  const originalNudge = nudge;
+
+  switch (why) {
+    case 'init':
+      if (nudge === 0) {
+        // normal case: new call, increment call count
+        req.locals.nudge = 1;
+        modifyCount = true;
+      }
+      else if (nudge === -1) {
+        // extremely quick cancel, don't increment call count
+        req.locals.nudge = 0;
+      }
+      else {
+        logger.info(`shouldNudge: unexpected nudge value ${nudge} for ${why}`);
+      }
+      break;
+    case 'failure':
+      if (nudge === 1) {
+        // normal case of call failed for any reason, decrement call count
+        req.locals.nudge = 0;
+        modifyCount = true;
+      }
+      else if (nudge === 0) {
+        // very quick failure dont decrement call count
+        req.locals.nudge = -1;
+      }
+      else {
+        logger.info(`shouldNudge: unexpected nudge value ${nudge} for ${why}`);
+      }
+      break;
+    case 'complete':
+      if (nudge === 1) {
+        // normal case of call completed, decrement call count
+        req.locals.nudge = 0;
+        modifyCount = true;
+      }
+      else {
+        logger.info(`shouldNudge: unexpected nudge value ${nudge} for ${why}`);
+      }
+      break;
+    default:
+      logger.info(`shouldNudge: unexpected why value ${why}`);
+      break;
+  }
+
+  logger.info(`shouldNudge: '${why}': updating count: ${modifyCount}, nudge: ${originalNudge} -> ${req.locals.nudge}`);
+  return modifyCount;
+};
+
+const nudgeCallCounts = async(req, why, sids, nudgeOperator, writers) => {
+  const {logger} = req.locals;
+  const {service_provider_sid, account_sid, application_sid, callId} = sids;
+  const {writeCallCount, writeCallCountSP, writeCallCountApp} = writers;
   const nudges = [];
   const writes = [];
 
+  if (!shouldNudge(why, req)) {
+    return {callsSP: null, calls: null, callsApp: null};
+  }
+
+  if (process.env.JAMBONES_DEBUG_CALL_COUNTS) {
+    const {srf} = require('..');
+    const {addKey, deleteKey} = srf.locals.realtimeDbHelpers;
+
+    if (why === 'init') {
+      // save for 3 days
+      await addKey(`debug:incalls:${account_sid}:${callId}`, new Date().toISOString(), 259200);
+    }
+    else {
+      await deleteKey(`debug:incalls:${account_sid}:${callId}`);
+    }
+  }
+
   if (process.env.JAMBONES_TRACK_SP_CALLS) {
     const key = makeSPCallCountKey(service_provider_sid);
     nudges.push(nudgeOperator(key));
@@ -151,33 +236,28 @@ const nudgeCallCounts = async(logger, sids, nudgeOperator, writers) => {
     const [callsSP, calls, callsApp] = await Promise.all(nudges);
     logger.debug({
       calls, callsSP, callsApp,
-      service_provider_sid, account_sid, application_sid
-    }, 'call counts after adjustment');
+      service_provider_sid, account_sid, application_sid}, 'call counts after adjustment');
     if (process.env.JAMBONES_TRACK_SP_CALLS) {
-      writes.push(writeCallCountSP({ service_provider_sid, calls_in_progress: callsSP }));
+      writes.push(writeCallCountSP({service_provider_sid, calls_in_progress: callsSP}));
     }
 
     if (process.env.JAMBONES_TRACK_ACCOUNT_CALLS || process.env.JAMBONES_HOSTING) {
-      writes.push(writeCallCount({ service_provider_sid, account_sid, calls_in_progress: calls }));
+      writes.push(writeCallCount({service_provider_sid, account_sid, calls_in_progress: calls}));
     }
 
     if (process.env.JAMBONES_TRACK_APP_CALLS && application_sid) {
-      writes.push(writeCallCountApp({
-        service_provider_sid,
-        account_sid, application_sid,
-        calls_in_progress: callsApp
-      }));
+      writes.push(writeCallCountApp({service_provider_sid, account_sid, application_sid, calls_in_progress: callsApp}));
     }
 
     /* write the call counts to the database */
-    Promise.all(writes).catch((err) => logger.error({ err }, 'Error writing call counts'));
+    Promise.all(writes).catch((err) => logger.error({err}, 'Error writing call counts'));
 
-    return { callsSP, calls, callsApp };
+    return {callsSP, calls, callsApp};
   } catch (err) {
     logger.error(err, 'error incrementing call counts');
   }
 
-  return { callsSP: null, calls: null, callsApp: null };
+  return {callsSP: null, calls: null, callsApp: null};
 };
 
 const roundTripTime = (startAt) => {

package-lock.json

@@ -16,7 +16,7 @@
         "@jambonz/http-health-check": "^0.0.1",
         "@jambonz/realtimedb-helpers": "^0.8.8",
         "@jambonz/rtpengine-utils": "^0.4.4",
-        "@jambonz/siprec-client-utils": "^0.2.9",
+        "@jambonz/siprec-client-utils": "^0.2.10",
         "@jambonz/stats-collector": "^0.1.10",
         "@jambonz/time-series": "^0.2.10",
         "bent": "^7.3.12",
@@ -1463,9 +1463,9 @@
       }
     },
     "node_modules/@jambonz/siprec-client-utils": {
-      "version": "0.2.9",
-      "resolved": "https://registry.npmjs.org/@jambonz/siprec-client-utils/-/siprec-client-utils-0.2.9.tgz",
-      "integrity": "sha512-C/1UOrAvQVG0iwiSMS0MC9VHRjhg3/sOjNna+eEjHjws1SHl8NrKBoDL8uOwLqOM2ccpbqCPH9GJAxo5OnOhww==",
+      "version": "0.2.10",
+      "resolved": "https://registry.npmjs.org/@jambonz/siprec-client-utils/-/siprec-client-utils-0.2.10.tgz",
+      "integrity": "sha512-Ns7rWK6cXVCr/1IoqPuVg9UKVRZNcs5EMvnhuoPhRD6L0HzLnfB0/BAq29bkHj0sr0bu0dp3hD5B+BnOcJuhaQ==",
       "license": "MIT",
       "dependencies": {
         "sdp-transform": "^2.14.1",
@@ -7957,9 +7957,9 @@
       }
     },
     "@jambonz/siprec-client-utils": {
-      "version": "0.2.9",
-      "resolved": "https://registry.npmjs.org/@jambonz/siprec-client-utils/-/siprec-client-utils-0.2.9.tgz",
-      "integrity": "sha512-C/1UOrAvQVG0iwiSMS0MC9VHRjhg3/sOjNna+eEjHjws1SHl8NrKBoDL8uOwLqOM2ccpbqCPH9GJAxo5OnOhww==",
+      "version": "0.2.10",
+      "resolved": "https://registry.npmjs.org/@jambonz/siprec-client-utils/-/siprec-client-utils-0.2.10.tgz",
+      "integrity": "sha512-Ns7rWK6cXVCr/1IoqPuVg9UKVRZNcs5EMvnhuoPhRD6L0HzLnfB0/BAq29bkHj0sr0bu0dp3hD5B+BnOcJuhaQ==",
       "requires": {
         "sdp-transform": "^2.14.1",
         "uuid": "^8.3.2"

package.json

@@ -30,7 +30,7 @@
     "@jambonz/http-health-check": "^0.0.1",
     "@jambonz/realtimedb-helpers": "^0.8.8",
     "@jambonz/rtpengine-utils": "^0.4.4",
-    "@jambonz/siprec-client-utils": "^0.2.9",
+    "@jambonz/siprec-client-utils": "^0.2.10",
     "@jambonz/stats-collector": "^0.1.10",
     "@jambonz/time-series": "^0.2.10",
     "@jambonz/digest-utils": "^0.0.5",