debug: add comprehensive WebRTC call flow logging to diagnose "stuck on Connecting"

Adds debug logging across CallManager, CallController, and WebRtcCallSession to trace the full call lifecycle: SDP offer/answer creation, remote description set success/failure, ICE candidate exchange, ICE connection state transitions, and signaling state changes. The noOpSdpObserver is replaced with a logging observer so setRemoteDescription success/failure is visible in logcat. Filter logcat with: CallManager|CallController|WebRtcCallSession https://claude.ai/code/session_01M3yyyRyu8KWJZ5PjNt4V2H
2026-04-03 13:30:50 +00:00
parent 316290ac32
commit 76477373d9
3 changed files with 123 additions and 20 deletions
@@ -181,6 +181,7 @@ class CallController(
        peerPubKeys: Set<String>,
        callType: CallType,
    ) {
+        Log.d(TAG) { "initiateCallInternal: peers=${peerPubKeys.map { it.take(8) }}, callType=$callType" }
        scope.launch {
            val callId = UUID.randomUUID().toString()
            _errorMessage.value = null
@@ -189,6 +190,7 @@ class CallController(

            try {
                withContext(Dispatchers.IO) { createWebRtcSession() }
+                Log.d(TAG) { "initiateCall: WebRTC session created" }
            } catch (e: Exception) {
                Log.e(TAG, "Failed to create WebRTC session", e)
                _errorMessage.value = "Failed to start call: ${e.message}"
@@ -208,13 +210,16 @@ class CallController(
                _isVideoEnabled.value = true
            }

+            Log.d(TAG) { "initiateCall: creating offer..." }
            session.createOffer { sdp ->
+                Log.d(TAG) { "initiateCall: offer created, sdpLength=${sdp.description.length}, publishing..." }
                scope.launch {
                    if (peerPubKeys.size == 1) {
                        callManager.initiateCall(peerPubKeys.first(), callType, callId, sdp.description)
                    } else {
                        callManager.initiateGroupCall(peerPubKeys, callType, callId, sdp.description)
                    }
+                    Log.d(TAG) { "initiateCall: offer published, callId=$callId, state=${callManager.state.value::class.simpleName}" }
                }
            }
        }
@@ -222,7 +227,12 @@ class CallController(

    fun acceptIncomingCall(sdpOffer: String) {
        val state = callManager.state.value
-        if (state !is CallState.IncomingCall) return
+        if (state !is CallState.IncomingCall) {
+            Log.d(TAG) { "acceptIncomingCall: state is ${state::class.simpleName}, not IncomingCall — ignoring" }
+            return
+        }
+
+        Log.d(TAG) { "acceptIncomingCall: callId=${state.callId}, callType=${state.callType}, sdpOfferLength=${sdpOffer.length}, pendingICE=${pendingIceCandidates.size}" }

        scope.launch {
            _errorMessage.value = null
@@ -231,6 +241,7 @@ class CallController(

            try {
                withContext(Dispatchers.IO) { createWebRtcSession() }
+                Log.d(TAG) { "acceptIncomingCall: WebRTC session created" }
            } catch (e: Exception) {
                Log.e(TAG, "Failed to create WebRTC session", e)
                _errorMessage.value = "Failed to accept call: ${e.message}"
@@ -239,32 +250,48 @@ class CallController(

            val session =
                webRtcSession ?: run {
+                    Log.e(TAG, "acceptIncomingCall: webRtcSession is null after creation")
                    _errorMessage.value = "Failed to create WebRTC session"
                    return@launch
                }

            session.addAudioTrack()
+            Log.d(TAG) { "acceptIncomingCall: audio track added" }
            if (state.callType == CallType.VIDEO) {
                session.addVideoTrack()
                _localVideoTrack.value = session.getLocalVideoTrack()
                _isVideoEnabled.value = true
+                Log.d(TAG) { "acceptIncomingCall: video track added" }
            }

+            Log.d(TAG) { "acceptIncomingCall: setting remote description (OFFER)..." }
            session.setRemoteDescription(SessionDescription(SessionDescription.Type.OFFER, sdpOffer))
+            Log.d(TAG) { "acceptIncomingCall: flushing ${pendingIceCandidates.size} pending ICE candidates..." }
            flushPendingIceCandidates()

+            Log.d(TAG) { "acceptIncomingCall: creating answer..." }
            session.createAnswer { sdp ->
+                Log.d(TAG) { "acceptIncomingCall: answer created, sdpLength=${sdp.description.length}, publishing..." }
                scope.launch {
                    callManager.acceptCall(sdp.description)
+                    Log.d(TAG) { "acceptIncomingCall: answer published, state=${callManager.state.value::class.simpleName}" }
                }
            }
        }
    }

    fun onCallAnswerReceived(sdpAnswer: String) {
-        val session = webRtcSession ?: return
+        val session = webRtcSession
+        if (session == null) {
+            Log.e(TAG, "Answer received but webRtcSession is NULL — cannot set remote description")
+            return
+        }
        val signalingState = session.getSignalingState()
-        Log.d(TAG) { "Answer received, SDP length=${sdpAnswer.length}, signalingState=$signalingState" }
+        Log.d(TAG) {
+            "Answer received, SDP length=${sdpAnswer.length}, signalingState=$signalingState, " +
+                "remoteDescriptionSet=${remoteDescriptionSet.get()}, pendingICE=${pendingIceCandidates.size}, " +
+                "callState=${callManager.state.value::class.simpleName}"
+        }

        // An answer is only valid when we have a pending local offer.
        // Ignore stale answers (e.g. our own renegotiation answer echoed back by the relay).
@@ -273,7 +300,9 @@ class CallController(
            return
        }

+        Log.d(TAG) { "Setting remote description (ANSWER)..." }
        session.setRemoteDescription(SessionDescription(SessionDescription.Type.ANSWER, sdpAnswer))
+        Log.d(TAG) { "Flushing pending ICE candidates after answer..." }
        flushPendingIceCandidates()
    }

@@ -97,16 +97,32 @@ class WebRtcCallSession(

                    override fun onIceCandidatesRemoved(candidates: Array<out IceCandidate>?) {}

-                    override fun onSignalingChange(state: PeerConnection.SignalingState?) {}
+                    override fun onSignalingChange(state: PeerConnection.SignalingState?) {
+                        Log.d(TAG) { "Signaling state changed: $state" }
+                    }

                    override fun onIceConnectionChange(state: PeerConnection.IceConnectionState?) {
                        Log.d(TAG) { "ICE connection state: $state" }
                        when (state) {
+                            PeerConnection.IceConnectionState.NEW -> {
+                                Log.d(TAG) { "ICE: NEW - waiting for candidates" }
+                            }
+
+                            PeerConnection.IceConnectionState.CHECKING -> {
+                                Log.d(TAG) { "ICE: CHECKING - testing candidate pairs" }
+                            }
+
                            PeerConnection.IceConnectionState.CONNECTED -> {
+                                Log.d(TAG) { "ICE: CONNECTED - peer connection established!" }
                                onPeerConnected()
                            }

+                            PeerConnection.IceConnectionState.COMPLETED -> {
+                                Log.d(TAG) { "ICE: COMPLETED - all candidate pairs tested, connection stable" }
+                            }
+
                            PeerConnection.IceConnectionState.FAILED -> {
+                                Log.e(TAG, "ICE: FAILED - could not establish connection")
                                onError("Connection failed - check network")
                                onDisconnected()
                            }
@@ -115,16 +131,24 @@ class WebRtcCallSession(
                                // DISCONNECTED is often transient (network switch, brief
                                // packet loss). WebRTC will transition to FAILED if
                                // recovery is impossible, so we only act on FAILED above.
-                                Log.d(TAG) { "ICE disconnected (transient, waiting for recovery or FAILED)" }
+                                Log.d(TAG) { "ICE: DISCONNECTED (transient, waiting for recovery or FAILED)" }
+                            }
+
+                            PeerConnection.IceConnectionState.CLOSED -> {
+                                Log.d(TAG) { "ICE: CLOSED" }
                            }

                            else -> {}
                        }
                    }

-                    override fun onIceConnectionReceivingChange(receiving: Boolean) {}
+                    override fun onIceConnectionReceivingChange(receiving: Boolean) {
+                        Log.d(TAG) { "ICE receiving change: $receiving" }
+                    }

-                    override fun onIceGatheringChange(state: PeerConnection.IceGatheringState?) {}
+                    override fun onIceGatheringChange(state: PeerConnection.IceGatheringState?) {
+                        Log.d(TAG) { "ICE gathering state: $state" }
+                    }

                    override fun onAddStream(stream: MediaStream?) {
                        // Fallback for Plan B SDP — Unified Plan uses onAddTrack
@@ -219,7 +243,8 @@ class WebRtcCallSession(
            object : SdpObserver {
                override fun onCreateSuccess(sdp: SessionDescription?) {
                    sdp?.let {
-                        peerConnection?.setLocalDescription(noOpSdpObserver(), it)
+                        Log.d(TAG) { "Offer created, sdpLength=${it.description.length}, setting local description" }
+                        peerConnection?.setLocalDescription(loggingSdpObserver("setLocalDescription(OFFER)"), it)
                        onSdpCreated(it)
                    }
                }
@@ -248,7 +273,8 @@ class WebRtcCallSession(
            object : SdpObserver {
                override fun onCreateSuccess(sdp: SessionDescription?) {
                    sdp?.let {
-                        peerConnection?.setLocalDescription(noOpSdpObserver(), it)
+                        Log.d(TAG) { "Answer created, sdpLength=${it.description.length}, setting local description" }
+                        peerConnection?.setLocalDescription(loggingSdpObserver("setLocalDescription(ANSWER)"), it)
                        onSdpCreated(it)
                    }
                }
@@ -267,11 +293,29 @@ class WebRtcCallSession(
    }

    fun setRemoteDescription(sdp: SessionDescription) {
-        peerConnection?.setRemoteDescription(noOpSdpObserver(), sdp)
+        Log.d(TAG) { "setRemoteDescription type=${sdp.type} sdpLength=${sdp.description.length}" }
+        peerConnection?.setRemoteDescription(
+            object : SdpObserver {
+                override fun onCreateSuccess(sdp: SessionDescription?) {}
+
+                override fun onCreateFailure(error: String?) {}
+
+                override fun onSetSuccess() {
+                    Log.d(TAG) { "setRemoteDescription SUCCESS (type=${sdp.type})" }
+                }
+
+                override fun onSetFailure(error: String?) {
+                    Log.e(TAG, "setRemoteDescription FAILED: $error (type=${sdp.type})")
+                    error?.let { onError("SDP error: $it") }
+                }
+            },
+            sdp,
+        )
    }

    fun addIceCandidate(candidate: IceCandidate) {
-        peerConnection?.addIceCandidate(candidate)
+        val added = peerConnection?.addIceCandidate(candidate)
+        Log.d(TAG) { "addIceCandidate result=$added sdpMid=${candidate.sdpMid} sdp=${candidate.sdp.take(60)}" }
    }

    fun getSignalingState(): PeerConnection.SignalingState? = peerConnection?.signalingState()
@@ -303,19 +347,23 @@ class WebRtcCallSession(
        peerConnectionFactory = null
    }

-    private fun noOpSdpObserver() =
+    private fun loggingSdpObserver(label: String) =
        object : SdpObserver {
-            override fun onCreateSuccess(sdp: SessionDescription?) {}
+            override fun onCreateSuccess(sdp: SessionDescription?) {
+                Log.d(TAG) { "$label onCreateSuccess" }
+            }

            override fun onCreateFailure(error: String?) {
-                Log.e(TAG, "SDP operation failed: $error")
+                Log.e(TAG, "$label onCreateFailure: $error")
                error?.let { onError("SDP error: $it") }
            }

-            override fun onSetSuccess() {}
+            override fun onSetSuccess() {
+                Log.d(TAG) { "$label onSetSuccess" }
+            }

            override fun onSetFailure(error: String?) {
-                Log.e(TAG, "SDP set failed: $error")
+                Log.e(TAG, "$label onSetFailure: $error")
                error?.let { onError("SDP error: $it") }
            }
        }
@@ -77,10 +77,12 @@ class CallManager(
        callId: String,
        sdpOffer: String,
    ) {
+        Log.d("CallManager") { "initiateCall: callId=$callId, callee=${calleePubKey.take(8)}, type=$callType, sdpLength=${sdpOffer.length}" }
        val result = factory.createCallOffer(sdpOffer, calleePubKey, callId, callType, signer)
        _state.value = CallState.Offering(callId, setOf(calleePubKey), callType)
        publishEvent(result.wrap)
        startTimeout(callId)
+        Log.d("CallManager") { "initiateCall: offer published, timeout started" }
    }

    // ---- Group call initiation ----
@@ -108,7 +110,12 @@ class CallManager(
        val callId = event.callId() ?: return
        val callType = event.callType() ?: CallType.VOICE

-        if (!isFollowing(callerPubKey)) return
+        Log.d("CallManager") { "onIncomingCallEvent: from=${callerPubKey.take(8)}, callId=$callId, type=$callType, sdpOfferLength=${event.sdpOffer().length}" }
+
+        if (!isFollowing(callerPubKey)) {
+            Log.d("CallManager") { "onIncomingCallEvent: caller not followed — ignoring" }
+            return
+        }

        if (_state.value !is CallState.Idle) {
            // Already in a call — send a "busy" reject so the caller gets
@@ -135,15 +142,21 @@ class CallManager(

    suspend fun acceptCall(sdpAnswer: String) {
        val current = _state.value
-        if (current !is CallState.IncomingCall) return
+        if (current !is CallState.IncomingCall) {
+            Log.d("CallManager") { "acceptCall: state is ${current::class.simpleName}, not IncomingCall — ignoring" }
+            return
+        }

+        Log.d("CallManager") { "acceptCall: callId=${current.callId}, transitioning to Connecting, sdpAnswerLength=${sdpAnswer.length}" }
        _state.value = CallState.Connecting(current.callId, current.peerPubKeys(), current.callType)
        cancelTimeout()

        // Include all group members + self so other devices get notified too.
        val allRecipients = current.groupMembers + signer.pubKey
+        Log.d("CallManager") { "acceptCall: publishing answer to ${allRecipients.size} recipients" }
        val result = factory.createGroupCallAnswer(sdpAnswer, allRecipients, current.callId, signer)
        result.wraps.forEach { publishEvent(it) }
+        Log.d("CallManager") { "acceptCall: answer published, now in Connecting state" }
    }

    suspend fun rejectCall() {
@@ -163,9 +176,17 @@ class CallManager(
        val callId = event.callId()
        val answeringPeer = event.pubKey

+        Log.d("CallManager") {
+            "onCallAnswered: from=${answeringPeer.take(8)}, callId=$callId, " +
+                "currentState=${current::class.simpleName}, sdpAnswerLength=${event.sdpAnswer().length}"
+        }
+
        when (current) {
            is CallState.Offering -> {
-                if (callId != current.callId) return
+                if (callId != current.callId) {
+                    Log.d("CallManager") { "onCallAnswered: callId mismatch (got=$callId, expected=${current.callId})" }
+                    return
+                }
                // First answer: start the call immediately. Remaining peers stay pending.
                val pending = current.peerPubKeys - answeringPeer
                _state.value =
@@ -176,6 +197,7 @@ class CallManager(
                        pendingPeerPubKeys = pending,
                    )
                cancelTimeout()
+                Log.d("CallManager") { "onCallAnswered: Offering -> Connecting, invoking onAnswerReceived callback (isNull=${onAnswerReceived == null})" }
                onAnswerReceived?.invoke(event)
            }

@@ -311,8 +333,12 @@ class CallManager(

    fun onPeerConnected() {
        val current = _state.value
-        if (current !is CallState.Connecting) return
+        if (current !is CallState.Connecting) {
+            Log.d("CallManager") { "onPeerConnected: state is ${current::class.simpleName}, not Connecting — ignoring" }
+            return
+        }

+        Log.d("CallManager") { "onPeerConnected: Connecting -> Connected! callId=${current.callId}" }
        _state.value =
            CallState.Connected(
                callId = current.callId,