VAPI-4167 fix: final in-call stats lost the call's inbound counters

src/v1/bandwidthRtc.test.ts

@@ -1528,6 +1528,112 @@ describe("bandwidthRtcV1 call stats trace", () => {
       brtc.disconnect();
     });
 
+    describe("final snapshot across a subscribe re-offer", () => {
+      const inboundReport = new Map<string, any>([
+        ["in", { id: "in", type: "inbound-rtp", kind: "audio", packetsReceived: 500, bytesReceived: 80000, jitter: 0.02, codecId: "c" }],
+        ["c", { id: "c", type: "codec", mimeType: "audio/opus" }],
+      ]);
+      let revision = 0;
+
+      // Swaps in a subscribing connection whose inbound stats vanish once setRemoteDescription runs, as when the gateway removes the call's track
+      const setupReOffer = async () => {
+        const { brtc, startCall } = await setup();
+        const pcMock: any = {
+          getStats: jest.fn().mockResolvedValue(inboundReport),
+          close: jest.fn(),
+          createAnswer: jest.fn().mockResolvedValue({ sdp: "answer-sdp" }),
+          setLocalDescription: jest.fn().mockResolvedValue(undefined),
+          setRemoteDescription: jest.fn().mockImplementation(async () => {
+            pcMock.getStats.mockResolvedValue(new Map());
+            pcMock.onSetRemoteDescription?.();
+          }),
+        };
+        (brtc as any).subscribingPeerConnection = pcMock;
+        (brtc as any).signaling.answerSdp = jest.fn().mockResolvedValue(undefined);
+        const reOffer = () => (brtc as any).handleSdpOffer({ peerType: "subscribe", sdpOffer: "offer", sdpRevision: ++revision });
+        return { brtc, startCall, pcMock, reOffer };
+      };
+
+      beforeEach(() => {
+        revision = 0;
+      });
+
+      test("logs the snapshot read before the re-offer, which carries the call's inbound counters", async () => {
+        const { brtc, startCall, pcMock, reOffer } = await setupReOffer();
+        const call = startCall("call-1");
+        pcMock.onSetRemoteDescription = () => call.end();
+
+        await reOffer();
+
+        expect(finalInCallCalls()).toHaveLength(1);
+        expect(finalInCallCalls()[0][0]).toBe("Final in-call stats (call ended)");
+        expect(finalInCallCalls()[0][1]).toMatchObject({ packetsReceived: 500, bytesReceived: 80000, jitter: 0.02, codec: "opus" });
+        expect(pcMock.getStats.mock.invocationCallOrder[0]).toBeLessThan(pcMock.setRemoteDescription.mock.invocationCallOrder[0]);
+        expect((brtc as any).preRenegotiationCallStats).toBeUndefined();
+        brtc.disconnect();
+      });
+
+      test("falls back to a fresh read when the pre-offer read was incomplete", async () => {
+        jest.spyOn(logger, "warn").mockImplementation(() => {});
+        const { brtc, startCall, pcMock, reOffer } = await setupReOffer();
+        const call = startCall("call-1");
+        pcMock.onSetRemoteDescription = () => call.end();
+        pcMock.getStats.mockRejectedValueOnce(new Error("boom"));
+
+        await reOffer();
+        await jest.advanceTimersByTimeAsync(0);
+
+        expect(finalInCallCalls()).toHaveLength(1);
+        expect(finalInCallCalls()[0][1]).toMatchObject({ packetsReceived: 0, codec: "unknown" });
+        brtc.disconnect();
+      });
+
+      test("does not read stats on a subscribe offer when no in-call trace is running", async () => {
+        const { brtc, pcMock, reOffer } = await setupReOffer();
+
+        await reOffer();
+
+        expect(pcMock.getStats).not.toHaveBeenCalled();
+        expect(pcMock.setRemoteDescription).toHaveBeenCalledTimes(1);
+        expect((brtc as any).preRenegotiationCallStats).toBeUndefined();
+        brtc.disconnect();
+      });
+
+      test("a stash from one call is not used by a later call", async () => {
+        const { brtc, startCall, pcMock, reOffer } = await setupReOffer();
+        const first = startCall("call-1");
+        // The offer is applied but the call keeps going, so the stash is left behind
+        await reOffer();
+        expect((brtc as any).preRenegotiationCallStats).toMatchObject({ packetsReceived: 500 });
+
+        first.end();
+        await jest.advanceTimersByTimeAsync(0);
+        (logger.debug as jest.Mock).mockClear();
+
+        startCall("call-2");
+        expect((brtc as any).preRenegotiationCallStats).toBeUndefined();
+        brtc.disconnect();
+        await jest.advanceTimersByTimeAsync(0);
+        expect(finalInCallCalls().map(([msg]) => msg)).toEqual(["Final in-call stats (disconnect)"]);
+        expect(pcMock.getStats).toHaveBeenCalled();
+      });
+
+      test("disconnect during a call still does a fresh final read despite a stashed snapshot", async () => {
+        const { brtc, startCall, pcMock, reOffer } = await setupReOffer();
+        startCall("call-1");
+        await reOffer();
+        expect((brtc as any).preRenegotiationCallStats).toBeDefined();
+        pcMock.getStats.mockClear();
+
+        brtc.disconnect();
+        await jest.advanceTimersByTimeAsync(0);
+
+        // The 5-minute trace also reads on disconnect, so only the logged value shows the in-call read was fresh
+        expect(finalInCallCalls().map(([msg]) => msg)).toEqual(["Final in-call stats (disconnect)"]);
+        expect(finalInCallCalls()[0][1]).toMatchObject({ packetsReceived: 0 });
+      });
+    });
+
     test("does not use a failed read as the next bitrate baseline", async () => {
       jest.spyOn(logger, "warn").mockImplementation(() => {});
       const { brtc, startCall } = await setup();

src/v1/bandwidthRtc.ts

@@ -75,6 +75,8 @@ const CALL_STATS_TRACE_INTERVAL_MS = 5 * 60 * 1000;
  * independently of the 5-minute trace, so both can log at the same moment.
  */
 const IN_CALL_STATS_TRACE_INTERVAL_MS = 10 * 1000;
+// Final in-call trace reason when the last call stream ends; the only one that uses the pre-renegotiation snapshot
+const CALL_ENDED_REASON = "call ended";
 
 export class BandwidthRtc {
   private options?: RtcOptions;
@@ -91,6 +93,8 @@ export class BandwidthRtc {
   private inCallStatsTraceTimer?: ReturnType<typeof setInterval>;
   // Own baseline, separate from lastTracedCallStats, so each trace's bitrates span its own interval
   private lastInCallTracedStats?: CallStatsSnapshot;
+  // Read just before a subscribe re-offer is applied: the offer that ends a call removes the track's inbound stats
+  private preRenegotiationCallStats?: CallStatsSnapshot;
 
   // One peer connection for all published (outgoing) streams, one for all subscribed (incoming) streams
   private publishingPeerConnection?: RTCPeerConnection;
@@ -592,6 +596,7 @@ export class BandwidthRtc {
       this.inCallStatsTraceTimer = undefined;
     }
     this.lastInCallTracedStats = undefined;
+    this.preRenegotiationCallStats = undefined;
     this.activeCallStreamIds.clear();
   }
 
@@ -601,8 +606,33 @@ export class BandwidthRtc {
       return;
     }
     const baseline = this.lastInCallTracedStats;
+    const preRenegotiation = this.preRenegotiationCallStats;
     this.stopInCallStatsTrace();
-    void this.traceCallStats(`Final in-call stats (${reason})`, baseline);
+    const label = `Final in-call stats (${reason})`;
+    // A fresh read would miss the ended call's inbound stats, so log the one taken before the re-offer
+    if (reason === CALL_ENDED_REASON && preRenegotiation) {
+      logger.debug(label, preRenegotiation);
+      return;
+    }
+    void this.traceCallStats(label, baseline);
+  }
+
+  // Runs under subscribeMutex, before setRemoteDescription. Always clears the stash first so a failed read never leaves an older one.
+  private async stashPreRenegotiationCallStats() {
+    this.preRenegotiationCallStats = undefined;
+    const timer = this.inCallStatsTraceTimer;
+    if (!timer) {
+      return;
+    }
+    try {
+      const { snapshot, complete } = await this.collectCallStats(this.lastInCallTracedStats);
+      // The trace ended or restarted while the read was in flight: the result belongs to an earlier call
+      if (complete && this.inCallStatsTraceTimer === timer) {
+        this.preRenegotiationCallStats = snapshot;
+      }
+    } catch (err) {
+      logger.warn("Pre-renegotiation call stats failed", err);
+    }
   }
 
   private async traceInCallStats() {
@@ -855,6 +885,8 @@ export class BandwidthRtc {
           this.subscribeTrackMetadata.set(trackId, metadata);
         }
 
+        await this.stashPreRenegotiationCallStats();
+
         await this.subscribingPeerConnection!.setRemoteDescription({
           type: "offer",
           sdp: remoteSdpOffer,
@@ -958,7 +990,7 @@ export class BandwidthRtc {
           streamTracks.delete(stream);
           logger.debug("onStreamUnavailable", stream.id);
           if (this.activeCallStreamIds.delete(stream.id) && this.activeCallStreamIds.size === 0) {
-            this.endInCallStatsTrace("call ended");
+            this.endInCallStatsTrace(CALL_ENDED_REASON);
           }
           this.streamUnavailableHandler?.({
             mediaTypes: [MediaType.AUDIO],