diff --git a/README.md b/README.md index 8fd5be6..31e3741 100644 --- a/README.md +++ b/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 diff --git a/src/v1/bandwidthRtc.test.ts b/src/v1/bandwidthRtc.test.ts index 872bd19..65d2af0 100644 --- a/src/v1/bandwidthRtc.test.ts +++ b/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(); + }); + }); }); diff --git a/src/v1/bandwidthRtc.ts b/src/v1/bandwidthRtc.ts index 297631a..39ac450 100644 --- a/src/v1/bandwidthRtc.ts +++ b/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 = new Set(); + private inCallStatsTraceTimer?: ReturnType; + // 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,