Do an ICE Restart if WebRTC become disconnected (#3341)

* Do an ice restart if ICE disconnected

  - Waite two seconds after disconnected
  - Remove check for finish ICE gathering and try to add each local candidate. Avoid race in multible ICE gathering

* Add tests for failed iceConnectionState

* suppress type check in unit test

* fix pr issues

spec/test-utils/webrtc.ts

@@ -239,6 +239,8 @@ export class MockRTCPeerConnection {
     public triggerIncomingDataChannel(): void {
         this.onDataChannelListener?.({ channel: {} } as RTCDataChannelEvent);
     }
+
+    public restartIce(): void {}
 }
 
 export class MockRTCRtpSender {

spec/unit/webrtc/call.spec.ts

@@ -1652,12 +1652,18 @@ describe("Call", function () {
         beforeEach(async () => {
             jest.useFakeTimers();
             jest.spyOn(call, "hangup");
-
             await fakeIncomingCall(client, call, "1");
 
             mockPeerConn = call.peerConn as unknown as MockRTCPeerConnection;
+
             mockPeerConn.iceConnectionState = "disconnected";
             mockPeerConn.iceConnectionStateChangeListener!();
+            jest.spyOn(mockPeerConn, "restartIce");
+        });
+
+        it("should restart ICE gathering after being disconnected for 2 seconds", () => {
+            jest.advanceTimersByTime(3 * 1000);
+            expect(mockPeerConn.restartIce).toHaveBeenCalled();
         });
 
         it("should hang up after being disconnected for 30 seconds", () => {
@@ -1665,6 +1671,20 @@ describe("Call", function () {
             expect(call.hangup).toHaveBeenCalledWith(CallErrorCode.IceFailed, false);
         });
 
+        it("should restart ICE gathering once again after ICE being failed", () => {
+            mockPeerConn.iceConnectionState = "failed";
+            mockPeerConn.iceConnectionStateChangeListener!();
+            expect(mockPeerConn.restartIce).toHaveBeenCalled();
+        });
+
+        it("should call hangup after ICE being failed and if there not exists a restartIce method", () => {
+            // @ts-ignore
+            mockPeerConn.restartIce = null;
+            mockPeerConn.iceConnectionState = "failed";
+            mockPeerConn.iceConnectionStateChangeListener!();
+            expect(call.hangup).toHaveBeenCalledWith(CallErrorCode.IceFailed, false);
+        });
+
         it("should not hangup if we've managed to re-connect", () => {
             mockPeerConn.iceConnectionState = "connected";
             mockPeerConn.iceConnectionStateChangeListener!();

src/webrtc/call.ts

@@ -263,7 +263,8 @@ const CALL_TIMEOUT_MS = 60 * 1000; // ms
 const CALL_LENGTH_INTERVAL = 1000; // ms
 /** The time after which we end the call, if ICE got disconnected */
 const ICE_DISCONNECTED_TIMEOUT = 30 * 1000; // ms
-
+/** The time after which we try a ICE restart, if ICE got disconnected */
+const ICE_RECONNECTING_TIMEOUT = 2 * 1000; // ms
 export class CallError extends Error {
     public readonly code: string;
 
@@ -382,6 +383,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
     private opponentPartyId: string | null | undefined;
     private opponentCaps?: CallCapabilities;
     private iceDisconnectedTimeout?: ReturnType<typeof setTimeout>;
+    private iceReconnectionTimeOut?: ReturnType<typeof setTimeout> | undefined;
     private inviteTimeout?: ReturnType<typeof setTimeout>;
     private readonly removeTrackListeners = new Map<MediaStream, () => void>();
 
@@ -965,6 +967,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
         await this.initOpponentCrypto();
         try {
             await this.peerConn.setRemoteDescription(invite.offer);
+            logger.debug(`Call ${this.callId} initWithInvite() set remote description: ${invite.offer.type}`);
             await this.addBufferedIceCandidates();
         } catch (e) {
             logger.debug(`Call ${this.callId} initWithInvite() failed to set remote description`, e);
@@ -1790,10 +1793,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
     private gotLocalIceCandidate = (event: RTCPeerConnectionIceEvent): void => {
         if (event.candidate) {
             if (this.candidatesEnded) {
-                logger.warn(
+                logger.warn(`Call ${this.callId} gotLocalIceCandidate() got candidate after candidates have ended!`);
-                    `Call ${this.callId} gotLocalIceCandidate() got candidate after candidates have ended - ignoring!`,
-                );
-                return;
             }
 
             logger.debug(`Call ${this.callId} got local ICE ${event.candidate.sdpMid} ${event.candidate.candidate}`);
@@ -1817,7 +1817,10 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
             }`,
         );
         if (this.peerConn?.iceGatheringState === "complete") {
-            this.queueCandidate(null);
+            this.queueCandidate(null); // We should leave it to WebRTC to announce the end
+            logger.debug(
+                `Call ${this.callId} onIceGatheringStateChange() ice gathering state complete, set candidates have ended`,
+            );
         }
     };
 
@@ -1899,6 +1902,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
             this.isSettingRemoteAnswerPending = true;
             await this.peerConn!.setRemoteDescription(content.answer);
             this.isSettingRemoteAnswerPending = false;
+            logger.debug(`Call ${this.callId} onAnswerReceived() set remote description: ${content.answer.type}`);
         } catch (e) {
             this.isSettingRemoteAnswerPending = false;
             logger.debug(`Call ${this.callId} onAnswerReceived() failed to set remote description`, e);
@@ -1991,6 +1995,8 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
             await this.peerConn!.setRemoteDescription(description); // SRD rolls back as needed
             this.isSettingRemoteAnswerPending = false;
 
+            logger.debug(`Call ${this.callId} onNegotiateReceived() set remote description: ${description.type}`);
+
             if (description.type === "offer") {
                 let answer: RTCSessionDescriptionInit;
                 try {
@@ -2003,6 +2009,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
                 }
 
                 await this.peerConn!.setLocalDescription(answer);
+                logger.debug(`Call ${this.callId} onNegotiateReceived() create an answer`);
 
                 this.sendVoipEvent(EventType.CallNegotiate, {
                     description: this.peerConn!.localDescription?.toJSON(),
@@ -2226,7 +2233,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
             return; // because ICE can still complete as we're ending the call
         }
         logger.debug(
-            `Call ${this.callId} onIceConnectionStateChanged() running (state=${this.peerConn?.iceConnectionState})`,
+            `Call ${this.callId} onIceConnectionStateChanged() running (state=${this.peerConn?.iceConnectionState}, conn=${this.peerConn?.connectionState})`,
         );
 
         // ideally we'd consider the call to be connected when we get media but
@@ -2234,6 +2241,9 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
         if (["connected", "completed"].includes(this.peerConn?.iceConnectionState ?? "")) {
             clearTimeout(this.iceDisconnectedTimeout);
             this.iceDisconnectedTimeout = undefined;
+            if (this.iceReconnectionTimeOut) {
+                clearTimeout(this.iceReconnectionTimeOut);
+            }
             this.state = CallState.Connected;
 
             if (!this.callLengthInterval && !this.callStartTime) {
@@ -2244,11 +2254,15 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
                 }, CALL_LENGTH_INTERVAL);
             }
         } else if (this.peerConn?.iceConnectionState == "failed") {
+            this.candidatesEnded = false;
             // Firefox for Android does not yet have support for restartIce()
             // (the types say it's always defined though, so we have to cast
             // to prevent typescript from warning).
             if (this.peerConn?.restartIce as (() => void) | null) {
                 this.candidatesEnded = false;
+                logger.debug(
+                    `Call ${this.callId} onIceConnectionStateChanged() ice restart (state=${this.peerConn?.iceConnectionState})`,
+                );
                 this.peerConn!.restartIce();
             } else {
                 logger.info(
@@ -2257,7 +2271,19 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
                 this.hangup(CallErrorCode.IceFailed, false);
             }
         } else if (this.peerConn?.iceConnectionState == "disconnected") {
-            this.iceDisconnectedTimeout = setTimeout(() => {
+            this.candidatesEnded = false;
+            this.iceReconnectionTimeOut = setTimeout((): void => {
+                logger.info(
+                    `Call ${this.callId} onIceConnectionStateChanged() ICE restarting because of ICE disconnected, (state=${this.peerConn?.iceConnectionState}, conn=${this.peerConn?.connectionState})`,
+                );
+                if (this.peerConn?.restartIce as (() => void) | null) {
+                    this.candidatesEnded = false;
+                    this.peerConn!.restartIce();
+                }
+                this.iceReconnectionTimeOut = undefined;
+            }, ICE_RECONNECTING_TIMEOUT);
+
+            this.iceDisconnectedTimeout = setTimeout((): void => {
                 logger.info(
                     `Call ${this.callId} onIceConnectionStateChanged() hanging up call (ICE disconnected for too long)`,
                 );
@@ -2887,6 +2913,11 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
             } catch (err) {
                 if (!this.ignoreOffer) {
                     logger.info(`Call ${this.callId} addIceCandidates() failed to add remote ICE candidate`, err);
+                } else {
+                    logger.debug(
+                        `Call ${this.callId} addIceCandidates() failed to add remote ICE candidate because ignoring offer`,
+                        err,
+                    );
                 }
             }
         }