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

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

* wip

* include callId in debug key

app.js

@@ -69,6 +69,7 @@ const {
   retrieveSet,
   isMemberOfSet,
   addKey,
+  deleteKey,
   retrieveKey
 } = require('@jambonz/realtimedb-helpers')({}, logger);
 
@@ -104,6 +105,7 @@ srf.locals = {...srf.locals,
   realtimeDbHelpers: {
     client: redisClient,
     addKey,
+    deleteKey,
     retrieveKey,
     createHash,
     retrieveHash,

lib/call-session.js

@@ -618,7 +618,17 @@ class CallSession extends Emitter {
             const abandoned = err.message && err.message.includes('rtpengine failed: Unknown call-id');
             const status = err.status || (abandoned ? 487 : 500);
             if (err instanceof SipError) this.logger.info(`final call failure  ${status}`);
-            else if (!abandoned) this.logger.error(err, 'unexpected call failure');
+            else if (!abandoned) {
+              const {writeCallCount, writeCallCountSP, writeCallCountApp} = this.req.srf.locals;
+              this.logger.error({err}, 'unexpected call failure');
+              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'));
+            }
             debug(`got final outdial error: ${err}`);
             if (!passFailure) this.res.send(status);
             this.emit('failed');
@@ -643,7 +653,7 @@ class CallSession extends Emitter {
         }
       }
     } catch (err) {
-      if ('abandonded' !== err.message) this.logger.error(err, `Error setting up outbound call to: ${uris}`);
+      if ('abandonded' !== err.message) this.logger.error({err}, `Error setting up outbound call to: ${uris}`);
       this.emit('failed');
       this.srf.endSession(this.req);
       this.rtpEngineResource.destroy();
@@ -694,16 +704,14 @@ class CallSession extends Emitter {
 
         if (process.env.JAMBONES_HOSTING || trackingOn) {
           const {writeCallCount, writeCallCountSP, writeCallCountApp} = this.req.srf.locals;
-          if (!this.req.locals.callCountNudged) {
-            this.req.locals.callCountNudged = true;
-            this.logger.debug('decrementing call count at end of call');
-            await nudgeCallCounts(this.logger, {
-              service_provider_sid: this.service_provider_sid,
-              account_sid: this.account_sid,
-              application_sid: this.application_sid
-            }, this.decrKey, {writeCallCountSP, writeCallCount, writeCallCountApp})
-              .catch((err) => this.logger.error(err, 'Error decrementing call counts'));
-          }
+          this.logger.debug('decrementing call count at end of call');
+          await nudgeCallCounts(this.req, 'complete', {
+            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'));
         }
 
         /* write cdr for connected call */
@@ -867,9 +875,9 @@ Duration=${payload.duration} `
       const acceptCodecs = process.env.JAMBONES_ACCEPT_AND_TRANSCODE ?
         process.env.JAMBONES_ACCEPT_AND_TRANSCODE :
         process.env.JAMBONES_ACCEPT_G729 ? 'g729' : '';
-      offerMedia = { ...offerMedia, ...(acceptCodecs && dlg.type === 'uac' && 
+      offerMedia = { ...offerMedia, ...(acceptCodecs && dlg.type === 'uac' &&
         { codec: { mask: acceptCodecs, transcode: 'pcmu,pcma' } })};
-      answerMedia = { ...answerMedia, ...(process.env.JAMBONES_CODEC_OFFER_WITH_ORDER && dlg.type === 'uac' && 
+      answerMedia = { ...answerMedia, ...(process.env.JAMBONES_CODEC_OFFER_WITH_ORDER && dlg.type === 'uac' &&
         { codec: {offer: process.env.JAMBONES_CODEC_OFFER_WITH_ORDER.split(','), strip: 'all' }})};
       let opts = {
         ...this.rtpEngineOpts.common,

lib/middleware.js

@@ -17,6 +17,8 @@ module.exports = (srf, logger, redisClient) => {
   const initLocals = async(req, res, next) => {
     req.locals = req.locals || {};
     const callId = req.get('Call-ID');
+    req.locals.nudge = 0;
+    req.locals.callId = callId;
     req.locals.account_sid = req.get('X-Account-Sid');
     req.locals.application_sid = req.get('X-Application-Sid');
     req.locals.record_all_calls = req.get('X-Record-All-Calls');
@@ -106,13 +108,12 @@ module.exports = (srf, logger, redisClient) => {
     try {
       /* decrement count if INVITE is later rejected */
       res.once('end', async({status}) => {
-        if (status > 200 && !req.locals.callCountNudged) {
-          req.locals.callCountNudged = true;
-          logger.debug('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'));
           const tags = ['accepted:no', `sipStatus:${status}`];
@@ -125,10 +126,11 @@ module.exports = (srf, logger, redisClient) => {
       });
 
       /* 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

@@ -131,13 +131,96 @@ 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 = [];
 
-  logger.debug(sids, 'nudgeCallCounts');
+  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:outcalls:${account_sid}:${callId}`, new Date().toISOString(), 259200);
+    }
+    else {
+      await deleteKey(`debug:outcalls:${account_sid}:${callId}`);
+    }
+  }
 
   if (process.env.JAMBONES_TRACK_SP_CALLS) {
     const key = makeSPCallCountKey(service_provider_sid);