Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

One way audio after resuming (coming back from holding) #5865

Closed
chagai95 opened this issue Apr 28, 2022 · 3 comments · Fixed by #6039
Closed

One way audio after resuming (coming back from holding) #5865

chagai95 opened this issue Apr 28, 2022 · 3 comments · Fixed by #6039
Assignees
@langleyd
Labels
A-VoIP O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Minor Impairs non-critical functionality or suitable workarounds exist T-Defect Something isn't working: bugs, crashes, hangs and other reported problems

Comments

@chagai95
Copy link
Contributor

Steps to reproduce

  1. Call someone.
  2. Have them answer.
  3. Put them on hold.
  4. Resume.

Outcome

What did you expect?

To hear them.

What happened instead?

You can now not hear them anymore.

Your phone model

Mi 11 Lite

Operating system version

MIUI Global 13.0.4 Stable, Android 12

Application version and app store

from version 1.3.8 and onwards

Homeserver

matrix.org

Will you send logs?

Yes
@chagai95 chagai95 added the T-Defect Something isn't working: bugs, crashes, hangs and other reported problems label Apr 28, 2022
@chagai95
Copy link
Contributor Author

chagai95 commented Apr 28, 2022 •
edited
Loading

I added some debug logs and here is what I am seeing in the logs when testing myself, but I also will send logs from the official app:

I/ViewRootImpl@11267c8[VectorCallActivity]: ViewPostIme pointer 0
I/MSHandlerLifeCycle: isMultiSplitHandlerRequested: windowingMode=1 isFullscreen=true isPopOver=false isHidden=false skipActivityType=false isHandlerType=true this: DecorView@7ec5e33[VectorCallActivity]
I/ViewRootImpl@11267c8[VectorCallActivity]: ViewPostIme pointer 1
I/MSHandlerLifeCycle: isMultiSplitHandlerRequested: windowingMode=1 isFullscreen=true isPopOver=false isHidden=false skipActivityType=false isHandlerType=true this: DecorView@7ec5e33[VectorCallActivity]
D/VectorCallViewModel$handle: ToggleHoldResume isRemoteOnHold: true
D/WebRtcCall$updateRemoteOnHold: onHold: false
V/VOIP/WebRtcCallManager: WebRtcPeerConnectionManager onCall active: 1651146902437nQRA0bdwbMK3z6fL(3)
D/WebRtcCallManager: Setting audioManager mode
I/CallAudioManager: Update audio route for mode: AUDIO_CALL
D/Analytics: capture(CallStarted(isVideo=false, numParticipants=2, placed=false))
D/WebRtcCall$updateRemoteOnHold: updateRemoteOnHold changing direction from SEND_ONLY to SEND_RECV
V/VOIP/PeerConnectionObserver: StreamObserver onRenegotiationNeeded
D/VectorCallViewModel$callListener: call.isLocalOnHold: false call?.isRemoteOnHold: false
V/VOIP/WebRtcCall: creating offer...
V/VOIP/VectorCallActivity: renderState call VectorCallViewState(callId=1651146902437nQRA0bdwbMK3z6fL(3), roomId=!gjSVBlAQaZomwqnobO:dev-matrix.aarenet.com, isVideoCall=false, isRemoteOnHold=false, isLocalOnHold=false, isAudioMuted=false, isVideoEnabled=true, isVideoCaptureInError=false, isHD=false, isFrontCamera=false, canSwitchCamera=false, device=im.vector.app.features.call.audio.CallAudioManager$Device$Phone@81ca5f6, availableDevices=[im.vector.app.features.call.audio.CallAudioManager$Device$Speaker@107cdf7, im.vector.app.features.call.audio.CallAudioManager$Device$Phone@81ca5f6], callState=Success(value=Connected(iceConnectionState=CONNECTED)), otherKnownCallInfo=null, callInfo=CallInfo(callId=1651146902437nQRA0bdwbMK3z6fL(3), opponentUserItem=UserItem(id=@33_6e6e7408d599d81a:dev-matrix.aarenet.com, displayName=Native User 8002, avatarUrl=null)), formattedDuration=00:16, canOpponentBeTransferred=true, transferee=im.vector.app.features.call.VectorCallViewState$TransfereeState$NoTransferee@55309a3)
V/SdpObserverAdapter: ## SdpObserver: onCreateSuccess org.webrtc.SessionDescription@1a68f02
V/VOIP/PeerConnectionObserver: StreamObserver onSignalingChange: HAVE_LOCAL_OFFER
I/org.webrtc.Logging: WebRtcAudioTrackExternal: initPlayout(sampleRate=48000, channels=1, bufferSizeFactor=1.0)
I/org.webrtc.Logging: WebRtcAudioTrackExternal: byteBuffer.capacity: 960
I/org.webrtc.Logging: WebRtcAudioTrackExternal: minBufferSizeInBytes: 7696
I/org.webrtc.Logging: WebRtcAudioTrackExternal: createAudioTrackOnLollipopOrHigher
I/org.webrtc.Logging: WebRtcAudioTrackExternal: nativeOutputSampleRate: 48000
I/org.webrtc.Logging: WebRtcAudioTrackExternal: AudioTrack: session ID: 4177, channels: 1, sample rate: 48000, max gain: 1.0
I/org.webrtc.Logging: WebRtcAudioTrackExternal: AudioTrack: buffer size in frames: 3848
I/org.webrtc.Logging: WebRtcAudioTrackExternal: AudioTrack: buffer capacity in frames: 3848
I/org.webrtc.Logging: VolumeLogger: start@[name=worker_thread - 7307, id=232]
I/org.webrtc.Logging: VolumeLogger: audio mode is: MODE_IN_COMMUNICATION
I/org.webrtc.Logging: WebRtcAudioTrackExternal: startPlayout
I/org.webrtc.Logging: VolumeLogger: VOICE_CALL stream volume: 8 (max=8)
V/SdpObserverAdapter: ## SdpObserver: onSetSuccess
I/org.webrtc.Logging: WebRtcAudioTrackExternal: AudioTrackThread@[name=AudioTrackJavaThread, id=260]
I/org.webrtc.Logging: WebRtcAudioTrackExternal: doAudioTrackStateCallback: 0
V/VOIP/MxCallImpl: negotiate 1651146902437nQRA0bdwbMK3z6fL(3)
V/EventSenderProcessorCoroutine: ## post SendEventQueuedTask queueIdentifier: !YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com, taskIdentifier:  $local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6)
V/QueuedTask: Execute: SendEventQueuedTask queueIdentifier: !YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com, taskIdentifier:  $local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6) start
V/LocalEchoRepository: ## SendEvent: [1651146932675] Update local state of $local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6 to SENDING
V/FormattedJsonHttpLogger: --> PUT https://dev-matrix.aarenet.com/_matrix/client/r0/rooms/!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com/send/m.call.negotiate/$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6
V/FormattedJsonHttpLogger: Content-Type: application/json; charset=UTF-8
V/FormattedJsonHttpLogger: Content-Length: 2725
V/FormattedJsonHttpLogger: User-Agent: anConnect debug/1.2.34 (Linux; U; Android 12; SM-A515F Build/SP1A.210812.01; Flavour GooglePlay; MatrixAndroidSdk2 1.4.12)
V/FormattedJsonHttpLogger: {"call_id":"1651146902437nQRA0bdwbMK3z6fL(3)","party_id":"XZSSLJPOAR","lifetime":120000,"description":{"type":"offer","sdp":"v=0\r\no=- 1616477210360785244 4 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS userMedia\r\nm=audio 56186 UDP/TLS/RTP/SAVPF 103 9 8 0 101 121 127 104 102 106 105 13 112 113\r\nc=IN IP4 10.1.3.65\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=candidate:3528861392 1 udp 2122262783 2a0d:1e40:0:13:dcc4:30ff:fe30:9c21 52654 typ host generation 0 network-id 6 network-cost 10\r\na=candidate:598887366 1 udp 2122194687 10.1.3.65 56186 typ host generation 0 network-id 5 network-cost 10\r\na=candidate:559267639 1 udp 2122005759 ::1 45007 typ host generation 0 network-id 2\r\na=candidate:1510613869 1 udp 2121932543 127.0.0.1 32909 typ host generation 0 network-id 1\r\na=candidate:377110548 1 tcp 1518151935 2a01:59f:991b:a5b4:1:2:21d7:3132 9 typ host tcptype active generation 0 network-id 4 network-cost 900\r\na=candidate:2386185843 1 tcp 1518083839 10.22.124.55 9 typ host tcptype active generation 0 network-id 3 network-cost 900\r\na=candidate:1876313031 1 tcp 1518025983 ::1 38291 typ host tcptype passive generation 0 network-id 2\r\na=candidate:344579997 1 tcp 1517952767 127.0.0.1 45405 typ host tcptype passive generation 0 network-id 1\r\na=ice-ufrag:ILjU\r\na=ice-pwd:Et8VVC7BADI6C4WmKDZKDoq0\r\na=ice-options:trickle renomination\r\na=fingerprint:sha-256 BA:AA:4A:42:27:B0:90:9C:95:86:78:9F:51:8A:B1:A5:FD:74:28:FC:A6:C5:EA:59:B8:D6:C6:5F:85:D3:D7:0E\r\na=setup:actpass\r\na=mid:0\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\na=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\na=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\na=sendrecv\r\na=msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=rtcp-mux\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 minptime=10;useinbandfec=1\r\na=rtpmap:9 G722/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:121 telephone-event/48000\r\na=rtpmap:127 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:102 ILBC/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:112 telephone-event/32000\r\na=rtpmap:113 telephone-event/16000\r\na=ssrc:1094441048 cname:HNty+8BOUmoBMJI/\r\na=ssrc:1094441048 msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=ssrc:1094441048 mslabel:userMedia\r\na=ssrc:1094441048 label:79808c51-85db-47a8-a7ce-2f50ec819ddf\r\n"},"version":"1"}
V/FormattedJsonHttpLogger: {
V/FormattedJsonHttpLogger:   "call_id": "1651146902437nQRA0bdwbMK3z6fL(3)",
V/FormattedJsonHttpLogger:   "party_id": "XZSSLJPOAR",
V/FormattedJsonHttpLogger:   "lifetime": 120000,
V/FormattedJsonHttpLogger:   "description": {
V/FormattedJsonHttpLogger:     "type": "offer",
V/FormattedJsonHttpLogger:     "sdp": "v=0\r\no=- 1616477210360785244 4 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS userMedia\r\nm=audio 56186 UDP\/TLS\/RTP\/SAVPF 103 9 8 0 101 121 127 104 102 106 105 13 112 113\r\nc=IN IP4 10.1.3.65\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=candidate:3528861392 1 udp 2122262783 2a0d:1e40:0:13:dcc4:30ff:fe30:9c21 52654 typ host generation 0 network-id 6 network-cost 10\r\na=candidate:598887366 1 udp 2122194687 10.1.3.65 56186 typ host generation 0 network-id 5 network-cost 10\r\na=candidate:559267639 1 udp 2122005759 ::1 45007 typ host generation 0 network-id 2\r\na=candidate:1510613869 1 udp 2121932543 127.0.0.1 32909 typ host generation 0 network-id 1\r\na=candidate:377110548 1 tcp 1518151935 2a01:59f:991b:a5b4:1:2:21d7:3132 9 typ host tcptype active generation 0 network-id 4 network-cost 900\r\na=candidate:2386185843 1 tcp 1518083839 10.22.124.55 9 typ host tcptype active generation 0 network-id 3 network-cost 900\r\na=candidate:1876313031 1 tcp 1518025983 ::1 38291 typ host tcptype passive generation 0 network-id 2\r\na=candidate:344579997 1 tcp 1517952767 127.0.0.1 45405 typ host tcptype passive generation 0 network-id 1\r\na=ice-ufrag:ILjU\r\na=ice-pwd:Et8VVC7BADI6C4WmKDZKDoq0\r\na=ice-options:trickle renomination\r\na=fingerprint:sha-256 BA:AA:4A:42:27:B0:90:9C:95:86:78:9F:51:8A:B1:A5:FD:74:28:FC:A6:C5:EA:59:B8:D6:C6:5F:85:D3:D7:0E\r\na=setup:actpass\r\na=mid:0\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:2 http:\/\/www.webrtc.org\/experiments\/rtp-hdrext\/abs-send-time\r\na=extmap:3 http:\/\/www.ietf.org\/id\/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\na=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\na=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\na=sendrecv\r\na=msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=rtcp-mux\r\na=rtpmap:103 opus\/48000\/2\r\na=fmtp:103 minptime=10;useinbandfec=1\r\na=rtpmap:9 G722\/8000\r\na=rtpmap:8 PCMA\/8000\r\na=rtpmap:0 PCMU\/8000\r\na=rtpmap:101 telephone-event\/8000\r\na=rtpmap:121 telephone-event\/48000\r\na=rtpmap:127 ISAC\/16000\r\na=rtpmap:104 ISAC\/32000\r\na=rtpmap:102 ILBC\/8000\r\na=rtpmap:106 CN\/32000\r\na=rtpmap:105 CN\/16000\r\na=rtpmap:13 CN\/8000\r\na=rtpmap:112 telephone-event\/32000\r\na=rtpmap:113 telephone-event\/16000\r\na=ssrc:1094441048 cname:HNty+8BOUmoBMJI\/\r\na=ssrc:1094441048 msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=ssrc:1094441048 mslabel:userMedia\r\na=ssrc:1094441048 label:79808c51-85db-47a8-a7ce-2f50ec819ddf\r\n"
V/FormattedJsonHttpLogger:   },
V/FormattedJsonHttpLogger:   "version": "1"
V/FormattedJsonHttpLogger: }
V/FormattedJsonHttpLogger: --> END PUT (2725-byte body)
V/AsyncTransactionKt$awaitTransaction: Execute transaction in 61 millis
V/EventInsertLiveObserver: EventInsertEntity updated with 1 results in db
D/CurlLoggingInterceptor: --- cURL (https://dev-matrix.aarenet.com/_matrix/client/r0/rooms/!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com/send/m.call.negotiate/$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6)
D/CurlLoggingInterceptor: curl -X PUT --data $'{"call_id":"1651146902437nQRA0bdwbMK3z6fL(3)","party_id":"XZSSLJPOAR","lifetime":120000,"description":{"type":"offer","sdp":"v=0\r\no=- 1616477210360785244 4 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS userMedia\r\nm=audio 56186 UDP/TLS/RTP/SAVPF 103 9 8 0 101 121 127 104 102 106 105 13 112 113\r\nc=IN IP4 10.1.3.65\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=candidate:3528861392 1 udp 2122262783 2a0d:1e40:0:13:dcc4:30ff:fe30:9c21 52654 typ host generation 0 network-id 6 network-cost 10\r\na=candidate:598887366 1 udp 2122194687 10.1.3.65 56186 typ host generation 0 network-id 5 network-cost 10\r\na=candidate:559267639 1 udp 2122005759 ::1 45007 typ host generation 0 network-id 2\r\na=candidate:1510613869 1 udp 2121932543 127.0.0.1 32909 typ host generation 0 network-id 1\r\na=candidate:377110548 1 tcp 1518151935 2a01:59f:991b:a5b4:1:2:21d7:3132 9 typ host tcptype active generation 0 network-id 4 network-cost 900\r\na=candidate:2386185843 1 tcp 1518083839 10.22.124.55 9 typ host tcptype active generation 0 network-id 3 network-cost 900\r\na=candidate:1876313031 1 tcp 1518025983 ::1 38291 typ host tcptype passive generation 0 network-id 2\r\na=candidate:344579997 1 tcp 1517952767 127.0.0.1 45405 typ host tcptype passive generation 0 network-id 1\r\na=ice-ufrag:ILjU\r\na=ice-pwd:Et8VVC7BADI6C4WmKDZKDoq0\r\na=ice-options:trickle renomination\r\na=fingerprint:sha-256 BA:AA:4A:42:27:B0:90:9C:95:86:78:9F:51:8A:B1:A5:FD:74:28:FC:A6:C5:EA:59:B8:D6:C6:5F:85:D3:D7:0E\r\na=setup:actpass\r\na=mid:0\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\na=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\na=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\na=sendrecv\r\na=msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=rtcp-mux\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 minptime=10;useinbandfec=1\r\na=rtpmap:9 G722/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:121 telephone-event/48000\r\na=rtpmap:127 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:102 ILBC/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:112 telephone-event/32000\r\na=rtpmap:113 telephone-event/16000\r\na=ssrc:1094441048 cname:HNty+8BOUmoBMJI/\r\na=ssrc:1094441048 msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=ssrc:1094441048 mslabel:userMedia\r\na=ssrc:1094441048 label:79808c51-85db-47a8-a7ce-2f50ec819ddf\r\n"},"version":"1"}' -H "User-Agent: anConnect debug/1.2.34 (Linux; U; Android 12; SM-A515F Build/SP1A.210812.01; Flavour GooglePlay; MatrixAndroidSdk2 1.4.12)" -H "Authorization: Bearer syt_MzNfNTJiNzMyYjMxMjdlZWU5YQ_VfgVZEOjMMWEpDGRbWNt_0QkuJ5" 'https://dev-matrix.aarenet.com/_matrix/client/r0/rooms/!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com/send/m.call.negotiate/$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6' | python -m json.tool
V/AsyncTransactionKt$awaitTransaction: Execute transaction in 22 millis
V/EventInsertLiveObserver$onChange: ##Transaction: There are 0 events to process 
V/AsyncTransactionKt$awaitTransaction: Execute transaction in 8 millis
V/FormattedJsonHttpLogger: <-- 200 OK https://dev-matrix.aarenet.com/_matrix/client/r0/rooms/!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com/send/m.call.negotiate/$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6 (147ms)
V/FormattedJsonHttpLogger: Server: nginx
V/FormattedJsonHttpLogger: Date: Thu, 28 Apr 2022 11:55:34 GMT
V/FormattedJsonHttpLogger: Content-Type: application/json
V/FormattedJsonHttpLogger: Transfer-Encoding: chunked
V/FormattedJsonHttpLogger: Connection: keep-alive
V/FormattedJsonHttpLogger: Cache-Control: no-cache, no-store, must-revalidate
V/FormattedJsonHttpLogger: Access-Control-Allow-Origin: *
V/FormattedJsonHttpLogger: Access-Control-Allow-Methods: GET, HEAD, POST, PUT, DELETE, OPTIONS
V/FormattedJsonHttpLogger: Access-Control-Allow-Headers: X-Requested-With, Content-Type, Authorization, Date
V/FormattedJsonHttpLogger: {"event_id":"$gzkj0ScVDPkDtj4uSZfrtffA_NPT6G8I2_vB9ZemNYs"}
V/FormattedJsonHttpLogger: {
V/FormattedJsonHttpLogger:   "event_id": "$gzkj0ScVDPkDtj4uSZfrtffA_NPT6G8I2_vB9ZemNYs"
V/FormattedJsonHttpLogger: }
V/FormattedJsonHttpLogger: <-- END HTTP (59-byte body)
V/LocalEchoRepository: ## SendEvent: [1651146932882] Update local state of $local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6 to SENT
D/DefaultSendEventTask: Event: $gzkj0ScVDPkDtj4uSZfrtffA_NPT6G8I2_vB9ZemNYs just sent in !YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com
V/QueuedTask: Execute: SendEventQueuedTask queueIdentifier: !YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com, taskIdentifier:  $local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6) finish
V/VOIP/VectorCallActivity: renderState call VectorCallViewState(callId=1651146902437nQRA0bdwbMK3z6fL(3), roomId=!gjSVBlAQaZomwqnobO:dev-matrix.aarenet.com, isVideoCall=false, isRemoteOnHold=false, isLocalOnHold=false, isAudioMuted=false, isVideoEnabled=true, isVideoCaptureInError=false, isHD=false, isFrontCamera=false, canSwitchCamera=false, device=im.vector.app.features.call.audio.CallAudioManager$Device$Phone@81ca5f6, availableDevices=[im.vector.app.features.call.audio.CallAudioManager$Device$Speaker@107cdf7, im.vector.app.features.call.audio.CallAudioManager$Device$Phone@81ca5f6], callState=Success(value=Connected(iceConnectionState=CONNECTED)), otherKnownCallInfo=null, callInfo=CallInfo(callId=1651146902437nQRA0bdwbMK3z6fL(3), opponentUserItem=UserItem(id=@33_6e6e7408d599d81a:dev-matrix.aarenet.com, displayName=Native User 8002, avatarUrl=null)), formattedDuration=00:17, canOpponentBeTransferred=true, transferee=im.vector.app.features.call.VectorCallViewState$TransfereeState$NoTransferee@55309a3)
V/AsyncTransactionKt$awaitTransaction: Execute transaction in 21 millis
V/FormattedJsonHttpLogger: <-- 200 OK https://dev-matrix.aarenet.com/_matrix/client/r0/sync?filter=1&set_presence=online&timeout=30000&since=s35148_231562_66_4044_12041_30_7580_3370_1 (4627ms)
V/FormattedJsonHttpLogger: Server: nginx
V/FormattedJsonHttpLogger: Date: Thu, 28 Apr 2022 11:55:34 GMT
V/FormattedJsonHttpLogger: Content-Type: application/json
V/FormattedJsonHttpLogger: Transfer-Encoding: chunked
V/FormattedJsonHttpLogger: Connection: keep-alive
V/FormattedJsonHttpLogger: Cache-Control: no-cache, no-store, must-revalidate
V/FormattedJsonHttpLogger: Access-Control-Allow-Origin: *
V/FormattedJsonHttpLogger: Access-Control-Allow-Methods: GET, HEAD, POST, PUT, DELETE, OPTIONS
V/FormattedJsonHttpLogger: Access-Control-Allow-Headers: X-Requested-With, Content-Type, Authorization, Date
V/FormattedJsonHttpLogger: {"next_batch":"s35149_231562_66_4044_12041_30_7580_3370_1","device_one_time_keys_count":{"signed_curve25519":50},"org.matrix.msc2732.device_unused_fallback_key_types":["signed_curve25519"],"rooms":{"join":{"!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com":{"timeline":{"events":[{"type":"m.call.negotiate","sender":"@33_52b732b3127eee9a:dev-matrix.aarenet.com","content":{"call_id":"1651146902437nQRA0bdwbMK3z6fL(3)","party_id":"XZSSLJPOAR","lifetime":120000,"description":{"type":"offer","sdp":"v=0\r\no=- 1616477210360785244 4 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS userMedia\r\nm=audio 56186 UDP/TLS/RTP/SAVPF 103 9 8 0 101 121 127 104 102 106 105 13 112 113\r\nc=IN IP4 10.1.3.65\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=candidate:3528861392 1 udp 2122262783 2a0d:1e40:0:13:dcc4:30ff:fe30:9c21 52654 typ host generation 0 network-id 6 network-cost 10\r\na=candidate:598887366 1 udp 2122194687 10.1.3.65 56186 typ host generation 0 network-id 5 network-cost 10\r\na=candidate:559267639 1 udp 2122005759 ::1 45007 typ host generation 0 network-id 2\r\na=candidate:1510613869 1 udp 2121932543 127.0.0.1 32909 typ host generation 0 network-id 1\r\na=candidate:377110548 1 tcp 1518151935 2a01:59f:991b:a5b4:1:2:21d7:3132 9 typ host tcptype active generation 0 network-id 4 network-cost 900\r\na=candidate:2386185843 1 tcp 1518083839 10.22.124.55 9 typ host tcptype active generation 0 network-id 3 network-cost 900\r\na=candidate:1876313031 1 tcp 1518025983 ::1 38291 typ host tcptype passive generation 0 network-id 2\r\na=candidate:344579997 1 tcp 1517952767 127.0.0.1 45405 typ host tcptype passive generation 0 network-id 1\r\na=ice-ufrag:ILjU\r\na=ice-pwd:Et8VVC7BADI6C4WmKDZKDoq0\r\na=ice-options:trickle renomination\r\na=fingerprint:sha-256 BA:AA:4A:42:27:B0:90:9C:95:86:78:9F:51:8A:B1:A5:FD:74:28:FC:A6:C5:EA:59:B8:D6:C6:5F:85:D3:D7:0E\r\na=setup:actpass\r\na=mid:0\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\na=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\na=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\na=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\na=sendrecv\r\na=msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=rtcp-mux\r\na=rtpmap:103 opus/48000/2\r\na=fmtp:103 minptime=10;useinbandfec=1\r\na=rtpmap:9 G722/8000\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:101 telephone-event/8000\r\na=rtpmap:121 telephone-event/48000\r\na=rtpmap:127 ISAC/16000\r\na=rtpmap:104 ISAC/32000\r\na=rtpmap:102 ILBC/8000\r\na=rtpmap:106 CN/32000\r\na=rtpmap:105 CN/16000\r\na=rtpmap:13 CN/8000\r\na=rtpmap:112 telephone-event/32000\r\na=rtpmap:113 telephone-event/16000\r\na=ssrc:1094441048 cname:HNty+8BOUmoBMJI/\r\na=ssrc:1094441048 msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=ssrc:1094441048 mslabel:userMedia\r\na=ssrc:1094441048 label:79808c51-85db-47a8-a7ce-2f50ec819ddf\r\n"},"version":"1"},"origin_server_ts":1651146934675,"unsigned":{"age":131,"transaction_id":"$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6"},"event_id":"$gzkj0ScVDPkDtj4uSZfrtffA_NPT6G8I2_vB9ZemNYs"}],"prev_batch":"s35148_231562_66_4044_12041_30_7580_3370_1","limited":false},"state":{"events":[]},"account_data":{"events":[]},"ephemeral":{"events":[]},"unread_notifications":{"notification_count":26,"highlight_count":0},"summary":{},"org.matrix.msc2654.unread_count":0}}}}
V/FormattedJsonHttpLogger: {
V/FormattedJsonHttpLogger:   "next_batch": "s35149_231562_66_4044_12041_30_7580_3370_1",
V/FormattedJsonHttpLogger:   "device_one_time_keys_count": {
V/FormattedJsonHttpLogger:     "signed_curve25519": 50
V/FormattedJsonHttpLogger:   },
V/FormattedJsonHttpLogger:   "org.matrix.msc2732.device_unused_fallback_key_types": [
V/FormattedJsonHttpLogger:     "signed_curve25519"
V/FormattedJsonHttpLogger:   ],
V/FormattedJsonHttpLogger:   "rooms": {
V/FormattedJsonHttpLogger:     "join": {
V/FormattedJsonHttpLogger:       "!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com": {
V/FormattedJsonHttpLogger:         "timeline": {
V/FormattedJsonHttpLogger:           "events": [
V/FormattedJsonHttpLogger:             {
V/FormattedJsonHttpLogger:               "type": "m.call.negotiate",
V/FormattedJsonHttpLogger:               "sender": "@33_52b732b3127eee9a:dev-matrix.aarenet.com",
V/FormattedJsonHttpLogger:               "content": {
V/FormattedJsonHttpLogger:                 "call_id": "1651146902437nQRA0bdwbMK3z6fL(3)",
V/FormattedJsonHttpLogger:                 "party_id": "XZSSLJPOAR",
V/FormattedJsonHttpLogger:                 "lifetime": 120000,
V/FormattedJsonHttpLogger:                 "description": {
V/FormattedJsonHttpLogger:                   "type": "offer",
V/FormattedJsonHttpLogger:                   "sdp": "v=0\r\no=- 1616477210360785244 4 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS userMedia\r\nm=audio 56186 UDP\/TLS\/RTP\/SAVPF 103 9 8 0 101 121 127 104 102 106 105 13 112 113\r\nc=IN IP4 10.1.3.65\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=candidate:3528861392 1 udp 2122262783 2a0d:1e40:0:13:dcc4:30ff:fe30:9c21 52654 typ host generation 0 network-id 6 network-cost 10\r\na=candidate:598887366 1 udp 2122194687 10.1.3.65 56186 typ host generation 0 network-id 5 network-cost 10\r\na=candidate:559267639 1 udp 2122005759 ::1 45007 typ host generation 0 network-id 2\r\na=candidate:1510613869 1 udp 2121932543 127.0.0.1 32909 typ host generation 0 network-id 1\r\na=candidate:377110548 1 tcp 1518151935 2a01:59f:991b:a5b4:1:2:21d7:3132 9 typ host tcptype active generation 0 network-id 4 network-cost 900\r\na=candidate:2386185843 1 tcp 1518083839 10.22.124.55 9 typ host tcptype active generation 0 network-id 3 network-cost 900\r\na=candidate:1876313031 1 tcp 1518025983 ::1 38291 typ host tcptype passive generation 0 network-id 2\r\na=candidate:344579997 1 tcp 1517952767 127.0.0.1 45405 typ host tcptype passive generation 0 network-id 1\r\na=ice-ufrag:ILjU\r\na=ice-pwd:Et8VVC7BADI6C4WmKDZKDoq0\r\na=ice-options:trickle renomination\r\na=fingerprint:sha-256 BA:AA:4A:42:27:B0:90:9C:95:86:78:9F:51:8A:B1:A5:FD:74:28:FC:A6:C5:EA:59:B8:D6:C6:5F:85:D3:D7:0E\r\na=setup:actpass\r\na=mid:0\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=extmap:2 http:\/\/www.webrtc.org\/experiments\/rtp-hdrext\/abs-send-time\r\na=extmap:3 http:\/\/www.ietf.org\/id\/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\na=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\na=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\na=sendrecv\r\na=msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=rtcp-mux\r\na=rtpmap:103 opus\/48000\/2\r\na=fmtp:103 minptime=10;useinbandfec=1\r\na=rtpmap:9 G722\/8000\r\na=rtpmap:8 PCMA\/8000\r\na=rtpmap:0 PCMU\/8000\r\na=rtpmap:101 telephone-event\/8000\r\na=rtpmap:121 telephone-event\/48000\r\na=rtpmap:127 ISAC\/16000\r\na=rtpmap:104 ISAC\/32000\r\na=rtpmap:102 ILBC\/8000\r\na=rtpmap:106 CN\/32000\r\na=rtpmap:105 CN\/16000\r\na=rtpmap:13 CN\/8000\r\na=rtpmap:112 telephone-event\/32000\r\na=rtpmap:113 telephone-event\/16000\r\na=ssrc:1094441048 cname:HNty+8BOUmoBMJI\/\r\na=ssrc:1094441048 msid:userMedia 79808c51-85db-47a8-a7ce-2f50ec819ddf\r\na=ssrc:1094441048 mslabel:userMedia\r\na=ssrc:1094441048 label:79808c51-85db-47a8-a7ce-2f50ec819ddf\r\n"
V/FormattedJsonHttpLogger:                 },
V/FormattedJsonHttpLogger:                 "version": "1"
V/FormattedJsonHttpLogger:               },
V/FormattedJsonHttpLogger:               "origin_server_ts": 1651146934675,
V/FormattedJsonHttpLogger:               "unsigned": {
V/FormattedJsonHttpLogger:                 "age": 131,
V/FormattedJsonHttpLogger:                 "transaction_id": "$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6"
V/FormattedJsonHttpLogger:               },
V/FormattedJsonHttpLogger:               "event_id": "$gzkj0ScVDPkDtj4uSZfrtffA_NPT6G8I2_vB9ZemNYs"
V/FormattedJsonHttpLogger:             }
V/FormattedJsonHttpLogger:           ],
V/FormattedJsonHttpLogger:           "prev_batch": "s35148_231562_66_4044_12041_30_7580_3370_1",
V/FormattedJsonHttpLogger:           "limited": false
V/FormattedJsonHttpLogger:         },
V/FormattedJsonHttpLogger:         "state": {
V/FormattedJsonHttpLogger:           "events": []
V/FormattedJsonHttpLogger:         },
V/FormattedJsonHttpLogger:         "account_data": {
V/FormattedJsonHttpLogger:           "events": []
V/FormattedJsonHttpLogger:         },
V/FormattedJsonHttpLogger:         "ephemeral": {
V/FormattedJsonHttpLogger:           "events": []
V/FormattedJsonHttpLogger:         },
V/FormattedJsonHttpLogger:         "unread_notifications": {
V/FormattedJsonHttpLogger:           "notification_count": 26,
V/FormattedJsonHttpLogger:           "highlight_count": 0
V/FormattedJsonHttpLogger:         },
V/FormattedJsonHttpLogger:         "summary": {},
V/FormattedJsonHttpLogger:         "org.matrix.msc2654.unread_count": 0
V/FormattedJsonHttpLogger:       }
V/FormattedJsonHttpLogger:     }
V/FormattedJsonHttpLogger:   }
V/FormattedJsonHttpLogger: }
V/FormattedJsonHttpLogger: <-- END HTTP (3544-byte body)
D/SYNC/SyncTask: Incremental sync request parsing, 1 room(s) 0 toDevice(s). Got nextBatch: s35149_231562_66_4044_12041_30_7580_3370_1
V/SyncResponseHandler: Start handling sync, is InitialSync: false
V/SyncResponseHandler: Finish handling start cryptoService in 0 ms
V/SyncResponseHandler: Handle toDevice
V/SyncResponseHandler: Finish handling toDevice in 1 ms
V/SyncResponseHandler$handleResponse: Handle rooms
V/RoomSyncHandler: Handle join sync for room !YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com
V/StreamEventsManager: ## dispatchLiveEventReceived $gzkj0ScVDPkDtj4uSZfrtffA_NPT6G8I2_vB9ZemNYs
V/RoomSyncHandler: Remove local echo for tx:$local.d4fe0daa-eca1-4656-aa43-bfe070dac9e6
V/RoomSummaryUpdater: ## Space: Updating summary room [!YwdiwIPPGwDfhUnFnO:dev-matrix.aarenet.com] roomType: [null]
D/RoomSummaryUpdater: ## CRYPTO: currentEncryptionEvent is null
V/SyncResponseHandler$handleResponse: Finish handling rooms in 78 ms
V/SyncResponseHandler$handleResponse: Handle groups
V/SyncResponseHandler$handleResponse: Finish handling groups in 0 ms
V/SyncResponseHandler$handleResponse: Handle accountData
V/SyncResponseHandler$handleResponse: Finish handling accountData in 0 ms
V/SyncResponseHandler$handleResponse: Handle Presence
V/SyncResponseHandler$handleResponse: Finish handling Presence in 0 ms
V/AsyncTransactionKt$awaitTransaction: Execute transaction in 108 millis
V/EventInsertLiveObserver: EventInsertEntity updated with 1 results in db
V/EventInsertLiveObserver$onChange: ##Transaction: There are 1 events to process 
V/SyncResponseHandler: [PushRules] --> checkPushRules
V/AsyncTransactionKt$awaitTransaction: Execute transaction in 13 millis
I/VOIP/CallEventProcessor: Call event came via onPostProcess
V/DefaultProcessEventForPushTask: [PushRules] Found 0 out of 1 to check for push rules with 17 rules
D/DefaultProcessEventForPushTask: [PushRules] matched 0 out of 0
V/DefaultProcessEventForPushTask: [PushRules] Found 0 redacted events
V/SyncResponseHandler: [PushRules] <-- Push task scheduled
V/NotificationDrawerManager: refreshNotificationDrawer(), delay: 0 ms
V/NotificationDrawerManager: refreshNotificationDrawerBg()
D/NotificationDrawerManager: Skipping notification update due to event list not changing
V/SyncResponseHandler: On sync completed
D/SYNC/SyncTask: Incremental sync done
V/CRYPTO/CryptoSyncHandler: Unwedging:  0 are wedged
D/SYNC/SyncTask: Sync task finished on Thread: DefaultDispatcher-worker-44
V/CRYPTO/CryptoSyncHandler: Nothing to unwedge
V/DeviceListManager: ## CRYPTO | refreshOutdatedDeviceLists()
D/SYNC/SyncThread: ...Continue
D/SYNC/SyncThread: Entering loop, state: Running(afterPause=false)
D/SYNC/SyncThread: Execute sync request with timeout 30000
V/OneTimeKeysUploader: maybeUploadOneTimeKeys: executed too recently
V/IncomingGossipingRequestManager: ## CRYPTO | GOSSIP processReceivedGossipingRequests() : 0 request to process
D/SYNC/SyncTask: Sync task started on Thread: DefaultDispatcher-worker-13
V/RoomSummaryUpdater: ## SPACES: Cycle detected = false
V/VOIP/VectorCallActivity: renderState call VectorCallViewState(callId=1651146902437nQRA0bdwbMK3z6fL(3), roomId=!gjSVBlAQaZomwqnobO:dev-matrix.aarenet.com, isVideoCall=false, isRemoteOnHold=false, isLocalOnHold=false, isAudioMuted=false, isVideoEnabled=true, isVideoCaptureInError=false, isHD=false, isFrontCamera=false, canSwitchCamera=false, device=im.vector.app.features.call.audio.CallAudioManager$Device$Phone@81ca5f6, availableDevices=[im.vector.app.features.call.audio.CallAudioManager$Device$Speaker@107cdf7, im.vector.app.features.call.audio.CallAudioManager$Device$Phone@81ca5f6], callState=Success(value=Connected(iceConnectionState=CONNECTED)), otherKnownCallInfo=null, callInfo=CallInfo(callId=1651146902437nQRA0bdwbMK3z6fL(3), opponentUserItem=UserItem(id=@33_6e6e7408d599d81a:dev-matrix.aarenet.com, displayName=Native User 8002, avatarUrl=null)), formattedDuration=00:18, canOpponentBeTransferred=true, transferee=im.vector.app.features.call.VectorCallViewState$TransfereeState$NoTransferee@55309a3)

@chagai95
Copy link
Contributor Author

I can't reproduce this anymore on matrix.org, so I'm starting to think I might have not seen it on the public server, nevertheless I do see it with Android Element with the server routing all calls via sip:

RTP is being sent to Android but for some reason Android is not playing anything.

@chagai95
Copy link
Contributor Author

Maybe this is useful:
v1.3.7-RC2...v1.3.8

@ganfra ganfra added A-VoIP S-Minor Impairs non-critical functionality or suitable workarounds exist O-Uncommon Most users are unlikely to come across this or unexpected workflow labels Apr 29, 2022
@langleyd langleyd self-assigned this May 12, 2022
@langleyd langleyd mentioned this issue May 12, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@langleyd langleyd

Labels
A-VoIP O-Uncommon Most users are unlikely to come across this or unexpected workflow S-Minor Impairs non-critical functionality or suitable workarounds exist T-Defect Something isn't working: bugs, crashes, hangs and other reported problems
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Direction and track need to be set for hold/unhold element-hq/element-android
3 participants
@langleyd @ganfra @chagai95