refined the method for syncing call count updates and added debugging (#189)

* refined the method for syncing call count updates and added debugging

* include callId in debug key

* fix debug key name

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'));
           }

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;
+/**
+ * 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,8 +236,7 @@ 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}));
     }
@@ -162,11 +246,7 @@ const nudgeCallCounts = async(logger, sids, nudgeOperator, writers) => {
     }
 
     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 */