Feature/opentelemetry (#89)

* initial adds for otel tracing

* initial basic testing

* basic tracing for incoming calls

* linting

* add traceId to the webhook params

* trace webhook calls

* tracing: add new commands as tags when receiving async commands over websocket

* tracing new commands

* add summary for config verb

* trace async commands

* bugfix: undefined ref

* tracing: give time for final webhooks before closing root span

* tracing bugfix: span for background gather was not ended

* tracing - minor tag changes

* tracing - add span atttribute for reason call ended

* trace call status webhooks, add app version to trace output

* config: add support for automatically re-enabling

* env var to customize service name in tracing UI

* config: change to use 'sticky' attribute to re-enable bargein automatically

* fix warnings

* when adulting create a new root span

* when background gather triggers bargein via vad clear queue of tasks

* additional trace attributes for dial and refer

* fix dial tracing

* add better summary for dial

* fix prev commit

* add exponential backoff to WsRequestor reconnection logic

* add calling number to log metadata, as this will be frequently the key data given for troubleshooting

* add accountSid to log metadata

* make handshake timeout for ws connections configurable with default 1.5 secs

* rename env var

* fix bug prev checkin

* logging fixes

* consistent env naming

lib/session/call-session.js

@@ -35,7 +35,7 @@ class CallSession extends Emitter {
    * @param {array} opts.tasks - tasks we are to execute
    * @param {callInfo} opts.callInfo - information about the call
    */
-  constructor({logger, application, srf, tasks, callInfo, accountInfo, memberId, confName, confUuid}) {
+  constructor({logger, application, srf, tasks, callInfo, accountInfo, rootSpan, memberId, confName, confUuid}) {
     super();
     this.logger = logger;
     this.application = application;
@@ -50,6 +50,9 @@ class CallSession extends Emitter {
     this.stackIdx = 0;
     this.callGone = false;
     this.notifiedComplete = false;
+    this.rootSpan = rootSpan;
+
+    assert(rootSpan);
 
     this.tmpFiles = new Set();
 
@@ -65,6 +68,7 @@ class CallSession extends Emitter {
     this._pool = srf.locals.dbHelpers.pool;
 
     this.requestor.on('command', this._onCommand.bind(this));
+    this.requestor.on('connection-dropped', this._onWsConnectionDropped.bind(this));
   }
 
   /**
@@ -226,26 +230,36 @@ class CallSession extends Emitter {
     return this.backgroundGatherTask;
   }
 
-  async enableBotMode(gather) {
+  async enableBotMode(gather, autoEnable) {
     try {
       const t = normalizeJambones(this.logger, [gather]);
       this.backgroundGatherTask = makeTask(this.logger, t[0]);
       this.backgroundGatherTask
         .on('dtmf', this._clearTasks.bind(this))
+        .on('vad', this._clearTasks.bind(this))
         .on('transcription', this._clearTasks.bind(this))
         .on('timeout', this._clearTasks.bind(this));
       this.logger.info({gather}, 'CallSession:enableBotMode - starting background gather');
       const resources = await this._evaluatePreconditions(this.backgroundGatherTask);
+      const {span, ctx} = this.rootSpan.startChildSpan(`background-gather:${this.backgroundGatherTask.summary}`);
+      this.backgroundGatherTask.span = span;
+      this.backgroundGatherTask.ctx = ctx;
       this.backgroundGatherTask.exec(this, resources)
         .then(() => {
           this.logger.info('CallSession:enableBotMode: gather completed');
           this.backgroundGatherTask && this.backgroundGatherTask.removeAllListeners();
+          this.backgroundGatherTask && this.backgroundGatherTask.span.end();
           this.backgroundGatherTask = null;
+          if (autoEnable && !this.callGone) {
+            this.logger.info('CallSession:enableBotMode: restarting background gather');
+            setImmediate(() => this.enableBotMode(gather, true));
+          }
           return;
         })
         .catch((err) => {
           this.logger.info({err}, 'CallSession:enableBotMode: gather threw error');
           this.backgroundGatherTask && this.backgroundGatherTask.removeAllListeners();
+          this.backgroundGatherTask && this.backgroundGatherTask.span.end();
           this.backgroundGatherTask = null;
         });
     } catch (err) {
@@ -362,11 +376,16 @@ class CallSession extends Emitter {
           this.backgroundGatherTask.updateTimeout(timeout);
         }
         else {
+          const {span, ctx} = this.rootSpan.startChildSpan(`verb:${task.summary}`);
+          task.span = span;
+          task.ctx = ctx;
           await task.exec(this, resources);
+          task.span.end();
         }
         this.currentTask = null;
         this.logger.info(`CallSession:exec completed task #${stackNum}:${taskNum}: ${task.name}`);
       } catch (err) {
+        task.span?.end();
         this.currentTask = null;
         if (err.message?.includes(BADPRECONDITIONS)) {
           this.logger.info(`CallSession:exec task #${stackNum}:${taskNum}: ${task.name}: ${err.message}`);
@@ -378,10 +397,19 @@ class CallSession extends Emitter {
       }
 
       if (0 === this.tasks.length && this.hasStableDialog && this.requestor instanceof WsRequestor) {
+        let span;
         try {
-          await this._awaitCommandsOrHangup();
+          const {span} = this.rootSpan.startChildSpan('waiting for commands');
+          const {reason, queue, command} = await this._awaitCommandsOrHangup();
+          span.setAttributes({
+            'completion.reason': reason,
+            'async.request.queue': queue,
+            'async.request.command': command
+          });
+          span.end();
           if (!this.hasStableDialog || this.callGone) break;
         } catch (err) {
+          span.end();
           this.logger.info(err, 'CallSession:exec - error waiting for new commands');
           break;
         }
@@ -438,17 +466,15 @@ class CallSession extends Emitter {
    * this is called to clean up when the call is released from one side or another
    */
   _callReleased() {
-    this.logger.debug('CallSession:_callReleased - caller hung up');
     this.callGone = true;
     if (this.currentTask) {
       this.currentTask.kill(this);
       this.currentTask = null;
     }
     if (this.wakeupResolver) {
-      this.wakeupResolver();
+      this.wakeupResolver({reason: 'session ended'});
       this.wakeupResolver = null;
     }
-    this.requestor && this.requestor.close();
   }
 
   /**
@@ -728,6 +754,7 @@ class CallSession extends Emitter {
 
   _onCommand({msgid, command, call_sid, queueCommand, data}) {
     this.logger.info({msgid, command, queueCommand}, 'CallSession:_onCommand - received command');
+    const resolution = {reason: 'received command', queue: queueCommand, command};
     switch (command) {
       case 'redirect':
         if (Array.isArray(data)) {
@@ -742,6 +769,7 @@ class CallSession extends Emitter {
             this.tasks.push(...t);
             this.logger.debug({tasks: listTaskNames(this.tasks)}, 'CallSession:_onCommand - updated task list');
           }
+          resolution.command = listTaskNames(t);
         }
         else this._lccCallHook(data);
         break;
@@ -781,10 +809,24 @@ class CallSession extends Emitter {
         this.logger.info(`CallSession:_onCommand - invalid command ${command}`);
     }
     if (this.wakeupResolver) {
-      this.logger.info('CallSession:_onCommand - got commands, waking up..');
-      this.wakeupResolver();
+      this.logger.debug({resolution}, 'CallSession:_onCommand - got commands, waking up..');
+      this.wakeupResolver(resolution);
       this.wakeupResolver = null;
     }
+    else {
+      const {span} = this.rootSpan.startChildSpan('async command');
+      const {queue, command} = resolution;
+      span.setAttributes({
+        'async.request.queue': queue,
+        'async.request.command': command
+      });
+      span.end();
+    }
+  }
+
+  _onWsConnectionDropped() {
+    const {stats} = this.srf.locals;
+    stats.increment('app.hook.remote_close');
   }
 
   _evaluatePreconditions(task) {
@@ -928,6 +970,8 @@ class CallSession extends Emitter {
     }
     this.tmpFiles.clear();
     this.requestor && this.requestor.close();
+
+    this.rootSpan && this.rootSpan.end();
   }
 
   /**
@@ -960,7 +1004,13 @@ class CallSession extends Emitter {
   async propagateAnswer() {
     if (!this.dlg) {
       assert(this.ep);
-      this.dlg = await this.srf.createUAS(this.req, this.res, {localSdp: this.ep.local.sdp});
+      this.dlg = await this.srf.createUAS(this.req, this.res, {
+        headers: {
+          'X-Trace-ID': this.req.locals.traceId,
+          'X-Call-Sid': this.req.locals.callSid
+        },
+        localSdp: this.ep.local.sdp
+      });
       this.logger.debug('answered call');
       this.dlg.on('destroy', this._callerHungup.bind(this));
       this.wrapDialog(this.dlg);
@@ -1148,9 +1198,10 @@ class CallSession extends Emitter {
         const duration = moment().diff(this.dlg.connectTime, 'seconds');
         this.emit('callStatusChange', {callStatus: CallStatus.Completed, duration});
         this.logger.debug('CallSession: call terminated by jambones');
+        this.rootSpan.setAttributes({'call.termination': 'hangup by jambonz'});
         origDestroy();
         if (this.wakeupResolver) {
-          this.wakeupResolver();
+          this.wakeupResolver({reason: 'session ended'});
           this.wakeupResolver = null;
         }
       }
@@ -1210,9 +1261,13 @@ class CallSession extends Emitter {
 
     this.callInfo.updateCallStatus(callStatus, sipStatus, sipReason);
     if (typeof duration === 'number') this.callInfo.duration = duration;
+    const {span} = this.rootSpan.startChildSpan(`call-status:${this.callInfo.callStatus}`);
+    span.setAttributes(this.callInfo.toJSON());
     try {
       this.notifier.request('call:status', this.call_status_hook, this.callInfo.toJSON());
+      span.end();
     } catch (err) {
+      span.end();
       this.logger.info(err, `CallSession:_notifyCallStatusChange error sending ${callStatus} ${sipStatus}`);
     }