diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/CallController.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/CallController.kt index 1b5ff2725..a475cedd4 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/CallController.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/CallController.kt @@ -181,6 +181,7 @@ class CallController( peerPubKeys: Set, 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() } diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/WebRtcCallSession.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/WebRtcCallSession.kt index e70549dfa..c74f41f6e 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/WebRtcCallSession.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/call/WebRtcCallSession.kt @@ -97,16 +97,32 @@ class WebRtcCallSession( override fun onIceCandidatesRemoved(candidates: Array?) {} - 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") } } } diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/call/CallManager.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/call/CallManager.kt index 7c10f9c9c..2a3749158 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/call/CallManager.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/call/CallManager.kt @@ -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,