diff --git a/app.js b/app.js index 7b046b3..ce0fbb4 100644 --- a/app.js +++ b/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, diff --git a/lib/call-session.js b/lib/call-session.js index b7d673c..8e21daf 100644 --- a/lib/call-session.js +++ b/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, diff --git a/lib/middleware.js b/lib/middleware.js index 69f9d23..72d85d4 100644 --- a/lib/middleware.js +++ b/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 */ diff --git a/lib/utils.js b/lib/utils.js index 5e44757..c2429a1 100644 --- a/lib/utils.js +++ b/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);