VAPI-4167 feat: trace call stats every 10 seconds while in a call

README.md

@@ -102,7 +102,7 @@ bandwidthRtc.sendDtmf("5", undefined, 200, 100); // 200ms tone, 100ms gap
 - Fields: `packetsReceived`, `packetsLost`, `bytesReceived`, `jitter`, `audioLevel`, `packetsSent`, `bytesSent`, `roundTripTime`, `codec`, `inboundBitrate`, `outboundBitrate`, `timestamp` (seconds)
 - RTCP data from the remote receiver: `remoteFractionLost`, `remoteJitter`, `rtcpRoundTripTime`. These are 0 until the first receiver report arrives.
 - With several audio streams, packet and byte counts are summed; jitter, loss, round trip time and audio level show the highest stream
-- Debug log: while connected, a snapshot is logged every 5 minutes, and a final one when the call ends (disconnect, fatal error, or the signaling socket closing for good)
+- Debug log: while connected, a snapshot is logged every 5 minutes, and a final one when the call ends (disconnect, fatal error, or the signaling socket closing for good). While in a call (a subscribe stream is available), a snapshot is also logged every 10 seconds under "In-call stats", with a final one when the call ends. The two traces run independently and may log at the same time
 
 ## Event Listeners
 

src/v1/bandwidthRtc.test.ts

@@ -1416,4 +1416,140 @@ describe("bandwidthRtcV1 call stats trace", () => {
     expect((brtc as any).lastTracedCallStats).toBeUndefined();
     brtc.disconnect();
   });
+
+  describe("in-call trace", () => {
+    const IN_CALL_INTERVAL_MS = 10 * 1000;
+    const inCallCalls = () => (logger.debug as jest.Mock).mock.calls.filter(([msg]) => msg === "In-call stats");
+    const finalInCallCalls = () => (logger.debug as jest.Mock).mock.calls.filter(([msg]) => String(msg).startsWith("Final in-call stats"));
+
+    // Connects and runs init() with a mocked setupPeerConnection, capturing the subscribe ontrack handler
+    const setup = async () => {
+      const brtc = new BandwidthRtc();
+      let onTrack: (event: any) => void = () => {};
+      jest.spyOn(brtc as any, "setupPeerConnection").mockImplementation(async (...args: any[]) => {
+        if (args[0] === "subscribe") {
+          onTrack = args[1];
+        }
+        return pc();
+      });
+      await brtc.connect({ endpointToken: "t" });
+      await brtc.init({ publishSdpOffer: { sdpOffer: "p" }, subscribeSdpOffer: { sdpOffer: "s" } } as any);
+      return { brtc, startCall: (id: string) => startCall(onTrack, id) };
+    };
+
+    const startCall = (onTrack: (event: any) => void, id: string) => {
+      const stream: any = { id };
+      const track = { id: `track-${id}` };
+      onTrack({ track, streams: [stream] });
+      return { end: () => stream.onremovetrack({ track }) };
+    };
+
+    test("does not trace before a call stream is available", async () => {
+      const { brtc } = await setup();
+
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS * 3);
+      expect(inCallCalls()).toHaveLength(0);
+      expect(finalInCallCalls()).toHaveLength(0);
+      brtc.disconnect();
+    });
+
+    test("logs every 10 seconds while a call stream is active, then a final snapshot when it ends", async () => {
+      const { brtc, startCall } = await setup();
+      const call = startCall("call-1");
+
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS - 1);
+      expect(inCallCalls()).toHaveLength(0);
+      await jest.advanceTimersByTimeAsync(1);
+      expect(inCallCalls()).toHaveLength(1);
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS);
+      expect(inCallCalls()).toHaveLength(2);
+
+      call.end();
+      await jest.advanceTimersByTimeAsync(0);
+      expect(finalInCallCalls().map(([msg]) => msg)).toEqual(["Final in-call stats (call ended)"]);
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS * 3);
+      expect(inCallCalls()).toHaveLength(2);
+      brtc.disconnect();
+    });
+
+    test("keeps tracing until the last of several concurrent call streams ends", async () => {
+      const { brtc, startCall } = await setup();
+      const first = startCall("call-1");
+      const second = startCall("call-2");
+
+      first.end();
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS);
+      expect(finalInCallCalls()).toHaveLength(0);
+      expect(inCallCalls()).toHaveLength(1);
+
+      second.end();
+      await jest.advanceTimersByTimeAsync(0);
+      expect(finalInCallCalls()).toHaveLength(1);
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS * 3);
+      expect(inCallCalls()).toHaveLength(1);
+      brtc.disconnect();
+    });
+
+    test("starts a fresh trace for the next call", async () => {
+      const { brtc, startCall } = await setup();
+      startCall("call-1").end();
+      startCall("call-2");
+
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS);
+      expect(inCallCalls()).toHaveLength(1);
+      brtc.disconnect();
+    });
+
+    test("disconnect during a call logs one final snapshot, read before the peer connection closes", async () => {
+      const { brtc, startCall } = await setup();
+      startCall("call-1");
+      const subscribing = (brtc as any).subscribingPeerConnection;
+
+      brtc.disconnect();
+      expect(subscribing.getStats.mock.invocationCallOrder[0]).toBeLessThan(subscribing.close.mock.invocationCallOrder[0]);
+      fireSignaling(brtc, "disconnected");
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS * 3);
+      expect(finalInCallCalls().map(([msg]) => msg)).toEqual(["Final in-call stats (disconnect)"]);
+      expect(inCallCalls()).toHaveLength(0);
+      expect((brtc as any).activeCallStreamIds.size).toBe(0);
+    });
+
+    test("a reconnect during a call logs a final snapshot before the old peer connections close", async () => {
+      const { brtc, startCall } = await setup();
+      startCall("call-1");
+      const oldPublishing = (brtc as any).publishingPeerConnection;
+
+      await brtc.init({ publishSdpOffer: { sdpOffer: "p" }, subscribeSdpOffer: { sdpOffer: "s" } } as any, true);
+      expect(oldPublishing.getStats.mock.invocationCallOrder[0]).toBeLessThan(oldPublishing.close.mock.invocationCallOrder[0]);
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS * 3);
+      expect(finalInCallCalls().map(([msg]) => msg)).toEqual(["Final in-call stats (reconnect)"]);
+      expect(inCallCalls()).toHaveLength(0);
+      expect((brtc as any).activeCallStreamIds.size).toBe(0);
+      brtc.disconnect();
+    });
+
+    test("does not use a failed read as the next bitrate baseline", async () => {
+      jest.spyOn(logger, "warn").mockImplementation(() => {});
+      const { brtc, startCall } = await setup();
+      (brtc as any).publishingPeerConnection.getStats.mockRejectedValueOnce(new Error("boom"));
+      startCall("call-1");
+
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS);
+      expect((brtc as any).lastInCallTracedStats).toBeUndefined();
+      await jest.advanceTimersByTimeAsync(IN_CALL_INTERVAL_MS);
+      expect((brtc as any).lastInCallTracedStats).toBeDefined();
+      brtc.disconnect();
+    });
+
+    test("the 5-minute trace still fires during a call, independently of the in-call trace", async () => {
+      const { brtc, startCall } = await setup();
+      startCall("call-1");
+
+      await jest.advanceTimersByTimeAsync(TRACE_INTERVAL_MS);
+      expect(traceCalls()).toHaveLength(1);
+      expect(inCallCalls()).toHaveLength(TRACE_INTERVAL_MS / IN_CALL_INTERVAL_MS);
+      expect((brtc as any).lastTracedCallStats).toBeDefined();
+      brtc.disconnect();
+    });
+  });
 });

src/v1/bandwidthRtc.ts

@@ -70,6 +70,12 @@ const RETRY_ICE_ON_FAILED = false;
 /** How often the call stats snapshot is written to the debug log while connected. */
 const CALL_STATS_TRACE_INTERVAL_MS = 5 * 60 * 1000;
 
+/**
+ * How often the call stats snapshot is written to the debug log while a call stream is active. Runs
+ * independently of the 5-minute trace, so both can log at the same moment.
+ */
+const IN_CALL_STATS_TRACE_INTERVAL_MS = 10 * 1000;
+
 export class BandwidthRtc {
   private options?: RtcOptions;
 
@@ -80,6 +86,12 @@ export class BandwidthRtc {
   // Previous traced snapshot; lets each trace carry bitrates computed over the trace interval
   private lastTracedCallStats?: CallStatsSnapshot;
 
+  // Stream ids of the active calls; the in-call trace runs while this is non-empty
+  private activeCallStreamIds: Set<string> = new Set();
+  private inCallStatsTraceTimer?: ReturnType<typeof setInterval>;
+  // Own baseline, separate from lastTracedCallStats, so each trace's bitrates span its own interval
+  private lastInCallTracedStats?: CallStatsSnapshot;
+
   // One peer connection for all published (outgoing) streams, one for all subscribed (incoming) streams
   private publishingPeerConnection?: RTCPeerConnection;
   private subscribingPeerConnection?: RTCPeerConnection;
@@ -136,7 +148,7 @@ export class BandwidthRtc {
     this.diagnosticsBatcher = new DiagnosticsBatcher();
     this.signaling = new Signaling(this.diagnosticsBatcher);
     // Registered once here: connect() re-registers its own handlers on every call
-    this.signaling.on("disconnected", () => this.endCallStatsTrace("signaling disconnected"));
+    this.signaling.on("disconnected", () => this.endCallStatsTraces("signaling disconnected"));
 
     this.setMicEnabled = this.setMicEnabled.bind(this);
     this.setCameraEnabled = this.setCameraEnabled.bind(this);
@@ -159,7 +171,7 @@ export class BandwidthRtc {
     this.signaling.on("fatalError", this.handleError.bind(this));
 
     // A connect() that replaces a live session ends that call here, before signaling reports it as disconnected
-    this.endCallStatsTrace("connect");
+    this.endCallStatsTraces("connect");
     await this.signaling.connect(authParams, options);
     logger.info("Successfully connected");
     this.startCallStatsTrace();
@@ -563,6 +575,45 @@ export class BandwidthRtc {
     void this.traceCallStats(`Final call stats (${reason})`, baseline);
   }
 
+  /** Ends both traces. Must run before the peer connections close, see endCallStatsTrace. */
+  private endCallStatsTraces(reason: string) {
+    this.endCallStatsTrace(reason);
+    this.endInCallStatsTrace(reason);
+  }
+
+  // Only called on the idle to in-call transition, so no timer or baseline is left to reset
+  private startInCallStatsTrace() {
+    this.inCallStatsTraceTimer = setInterval(() => this.traceInCallStats(), IN_CALL_STATS_TRACE_INTERVAL_MS);
+  }
+
+  private stopInCallStatsTrace() {
+    if (this.inCallStatsTraceTimer) {
+      clearInterval(this.inCallStatsTraceTimer);
+      this.inCallStatsTraceTimer = undefined;
+    }
+    this.lastInCallTracedStats = undefined;
+    this.activeCallStreamIds.clear();
+  }
+
+  /** Same contract as endCallStatsTrace, for the in-call trace. Also forgets the active call streams. */
+  private endInCallStatsTrace(reason: string) {
+    if (!this.inCallStatsTraceTimer) {
+      return;
+    }
+    const baseline = this.lastInCallTracedStats;
+    this.stopInCallStatsTrace();
+    void this.traceCallStats(`Final in-call stats (${reason})`, baseline);
+  }
+
+  private async traceInCallStats() {
+    const timer = this.inCallStatsTraceTimer;
+    const snapshot = await this.traceCallStats("In-call stats", this.lastInCallTracedStats);
+    // The trace ended or restarted while the read was in flight: the result belongs to an earlier call
+    if (snapshot && this.inCallStatsTraceTimer === timer) {
+      this.lastInCallTracedStats = snapshot;
+    }
+  }
+
   private async tracePeriodicCallStats() {
     const timer = this.callStatsTraceTimer;
     const snapshot = await this.traceCallStats("Call stats", this.lastTracedCallStats);
@@ -594,7 +645,7 @@ export class BandwidthRtc {
    */
   disconnect() {
     logger.info("Disconnecting");
-    this.endCallStatsTrace("disconnect");
+    this.endCallStatsTraces("disconnect");
     this.cleanupPublishedStreams();
     this.publishingPeerConnection?.close();
     this.subscribingPeerConnection?.close();
@@ -831,6 +882,10 @@ export class BandwidthRtc {
   }
 
   private async doInit(setMediaPreferencesResponse: SetMediaPreferencesWebRtcResponse, isReconnect: boolean = false) {
+    // The subscribing peer connection and streamTracks are rebuilt below, so the old call streams never
+    // fire onremovetrack. End their trace now, while the old peer connections can still be read.
+    this.endInCallStatsTrace("reconnect");
+
     if (isReconnect) {
       // The signaling websocket reconnected (e.g. a gateway-initiated 1001 that expects the
       // same endpoint to keep going, not a fresh connect()). The subscribing side's SDP
@@ -902,6 +957,9 @@ export class BandwidthRtc {
           // unique stream, so clean up its entry as we fire.
           streamTracks.delete(stream);
           logger.debug("onStreamUnavailable", stream.id);
+          if (this.activeCallStreamIds.delete(stream.id) && this.activeCallStreamIds.size === 0) {
+            this.endInCallStatsTrace("call ended");
+          }
           this.streamUnavailableHandler?.({
             mediaTypes: [MediaType.AUDIO],
             mediaStream: stream,
@@ -929,6 +987,11 @@ export class BandwidthRtc {
         this.subscribeTrackMetadata.delete(onlyTrackId);
       }
       logger.debug("onStreamAvailable", stream.id, metadata);
+      const wasIdle = this.activeCallStreamIds.size === 0;
+      this.activeCallStreamIds.add(stream.id);
+      if (wasIdle) {
+        this.startInCallStatsTrace();
+      }
       this.streamAvailableHandler?.({
         mediaTypes: [MediaType.AUDIO],
         mediaStream: stream,