meetecho / janus-gateway

Janus WebRTC Server
https://janus.conf.meetecho.com
GNU General Public License v3.0
8.15k stars 2.47k forks source link

[0.x] textroom plugin:janus server sent "webrtcup" event, but client stuck at iceConnectionState CHECKING #2949

Closed FJEagle closed 2 years ago

FJEagle commented 2 years ago

We use textroom plugin to communicate with janus server in android app. Sometimes, client received the "webrtcup" event pushed by janus server, but client stuck at iceConnectionState CHECKING and client-side onIceCandidate was not triggerred. The datachannel failed to be created. But this does not always happen, generally it works fine. Any advice to debug this problem? Thanks.

What version of Janus is this happening on? 0.10.7/0.11.8

Additional context Logs when this problem happened:

server side log ``` [Mon Apr 11 19:43:03 2022] Got a Janus API request from janus.transport.http (0x7fe2a401d220) [Mon Apr 11 19:43:03 2022] Session 8365425559870364 found... returning up to 1 messages [Mon Apr 11 19:43:03 2022] Got a keep-alive on session 8365425559870364 [Mon Apr 11 19:43:05 2022] Peer address Unknown family 123 is now [Mon Apr 11 19:43:05 2022] SCTP_ADDR_UNREACHABLE[Mon Apr 11 19:43:05 2022] (error = 0x00000000). [Mon Apr 11 19:43:08 2022] Got a Janus API request from janus.transport.http (0x7fe298012dd0) [Mon Apr 11 19:43:08 2022] Session 1869869330665735 found... returning up to 10 messages [Mon Apr 11 19:43:08 2022] Got a keep-alive on session 1869869330665735 [Mon Apr 11 19:43:09 2022] Got a Janus API request from janus.transport.http (0x7fe2a4007d90) [Mon Apr 11 19:43:09 2022] Creating new session: 7665061494737629; 0x7fe2b4008e90 [Mon Apr 11 19:43:09 2022] Session created (7665061494737629), create a queue for the long poll [Mon Apr 11 19:43:09 2022] Got a Janus API request from janus.transport.http (0x7fe2a4003a10) [Mon Apr 11 19:43:09 2022] Session 7665061494737629 found... returning up to 1 messages [Mon Apr 11 19:43:09 2022] Got a keep-alive on session 7665061494737629 [Mon Apr 11 19:43:09 2022] Got a Janus API request from janus.transport.http (0x7fe2a4007810) [Mon Apr 11 19:43:09 2022] Creating new handle in session 7665061494737629: 3798836899274176; 0x7fe2b4008e90 0x7fe2b400dc40 [Mon Apr 11 19:43:09 2022] [3798836899274176] Handle thread started; 0x7fe2b400dc40 [Mon Apr 11 19:43:10 2022] Got a Janus API request from janus.transport.http (0x7fe2a4002210) [Mon Apr 11 19:43:10 2022] Transport task pool, serving request [Mon Apr 11 19:43:10 2022] [3798836899274176] There's a message for JANUS TextRoom plugin [Mon Apr 11 19:43:10 2022] [3798836899274176] Audio has NOT been negotiated [Mon Apr 11 19:43:10 2022] [3798836899274176] Video has NOT been negotiated [Mon Apr 11 19:43:10 2022] [3798836899274176] SCTP/DataChannels have been negotiated [Mon Apr 11 19:43:10 2022] [3798836899274176] Setting ICE locally: got ANSWER (0 audios, 0 videos) [Mon Apr 11 19:43:10 2022] [3798836899274176] Creating ICE agent (ICE Full mode, controlling) [Mon Apr 11 19:43:10 2022] [3798836899274176] Adding 45.125.46.212 to the addresses to gather candidates for [Mon Apr 11 19:43:10 2022] [3798836899274176] Gathering done for stream 1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Setting DTLS initial timeout: 1000ms [Mon Apr 11 19:43:10 2022] ------------------------------------------- [Mon Apr 11 19:43:10 2022] >> Anonymized [Mon Apr 11 19:43:10 2022] ------------------------------------------- [Mon Apr 11 19:43:10 2022] [3798836899274176] We have 1 candidates for Stream #1, Component #1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Address: 45.125.46.212:37652 [Mon Apr 11 19:43:10 2022] [3798836899274176] Priority: 2015363327 [Mon Apr 11 19:43:10 2022] [3798836899274176] Foundation: 1 [Mon Apr 11 19:43:10 2022] [3798836899274176] 1 1 udp 2015363327 45.125.46.212 37652 typ host [Mon Apr 11 19:43:10 2022] ------------------------------------------- [Mon Apr 11 19:43:10 2022] >> Merged (540 bytes) [Mon Apr 11 19:43:10 2022] ------------------------------------------- [Mon Apr 11 19:43:10 2022] v=0 o=- 1649677390189105 1 IN IP4 45.125.46.212 s=Janus TextRoom plugin t=0 0 a=group:BUNDLE data a=msid-semantic: WMS janus m=application 9 UDP/DTLS/SCTP webrtc-datachannel c=IN IP4 45.125.46.212 a=sendrecv a=sctp-port:5000 a=mid:data a=ice-ufrag:GHne a=ice-pwd:B3KoE6onIPamkxjpFqJ3Gr a=ice-options:trickle a=fingerprint:sha-256 B6:49:50:04:44:3D:00:7C:A4:59:70:58:32:60:E3:3A:E4:44:B7:C5:A7:4A:EB:9D:5C:FE:66:A1:A2:D8:69:C2 a=setup:actpass a=candidate:1 1 udp 2015363327 45.125.46.212 37652 typ host a=end-of-candidates [Mon Apr 11 19:43:10 2022] [3798836899274176] Sending event to transport... [Mon Apr 11 19:43:10 2022] >> Pushing event: 0 (took 1798 us) [Mon Apr 11 19:43:10 2022] Got a Janus API request from janus.transport.http (0x7fe2a40076f0) [Mon Apr 11 19:43:10 2022] Session 7665061494737629 found... returning up to 1 messages [Mon Apr 11 19:43:10 2022] Got a keep-alive on session 7665061494737629 [Mon Apr 11 19:43:10 2022] [3798836899274176] Discovered new remote candidate for component 1 in stream 1: type=prflx [Mon Apr 11 19:43:10 2022] [3798836899274176] Stream #1, Component #1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Address: 58.220.132.148:59415 [Mon Apr 11 19:43:10 2022] [3798836899274176] Priority: 1853824767 [Mon Apr 11 19:43:10 2022] [3798836899274176] Foundation: remote1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Adding remote candidate component:1 stream:1 type:prflx 58.220.132.148:59415 --> 58.220.132.148:59415 [Mon Apr 11 19:43:10 2022] [3798836899274176] Transport: UDP [Mon Apr 11 19:43:10 2022] [3798836899274176] Queueing trickle candidate, status is not START yet [Mon Apr 11 19:43:10 2022] Got a Janus API request from janus.transport.http (0x7fe2a4006470) [Mon Apr 11 19:43:10 2022] Transport task pool, serving request [Mon Apr 11 19:43:10 2022] [3798836899274176] There's a message for JANUS TextRoom plugin [Mon Apr 11 19:43:10 2022] [3798836899274176] Remote SDP: v=0 o=- 8594631152457082093 2 IN IP4 127.0.0.1 s=- t=0 0 a=group:BUNDLE data a=msid-semantic: WMS m=application 9 UDP/DTLS/SCTP webrtc-datachannel c=IN IP4 0.0.0.0 b=AS:30 a=ice-ufrag:nxoU a=ice-pwd:sNcnSC2gHG464cP+v5AeU6AM a=ice-options:trickle renomination a=fingerprint:sha-256 82:7C:A8:7A:93:3E:6E:B2:E5:D5:0C:C2:AD:10:AA:0E:B2:0A:0A:25:00:7B:73:86:8F:0B:4F:03:DB:A8:E6:92 a=setup:active a=mid:data a=sctp-port:5000 [Mon Apr 11 19:43:10 2022] [3798836899274176] Audio has NOT been negotiated, Video has NOT been negotiated, SCTP/DataChannels have been negotiated [Mon Apr 11 19:43:10 2022] [3798836899274176] Parsing SCTP candidates (stream=1)... [Mon Apr 11 19:43:10 2022] [3798836899274176] ICE ufrag (local): nxoU [Mon Apr 11 19:43:10 2022] [3798836899274176] ICE pwd (local): sNcnSC2gHG464cP+v5AeU6AM [Mon Apr 11 19:43:10 2022] [3798836899274176] Fingerprint (local) : sha-256 82:7C:A8:7A:93:3E:6E:B2:E5:D5:0C:C2:AD:10:AA:0E:B2:0A:0A:25:00:7B:73:86:8F:0B:4F:03:DB:A8:E6:92 [Mon Apr 11 19:43:10 2022] [3798836899274176] DTLS setup (local): active [Mon Apr 11 19:43:10 2022] [3798836899274176] Setting accept state (DTLS server) [Mon Apr 11 19:43:10 2022] [3798836899274176] Data Channel mid: data [Mon Apr 11 19:43:10 2022] [3798836899274176] Setting remote credentials... [Mon Apr 11 19:43:10 2022] [3798836899274176] Component state changed for component 1 in stream 1: 2 (connecting) [Mon Apr 11 19:43:10 2022] [3798836899274176] Done! Sending connectivity checks... [Mon Apr 11 19:43:10 2022] [3798836899274176] ## Setting remote candidates: stream 1, component 1 (1 in the list) [Mon Apr 11 19:43:10 2022] [3798836899274176] Queueing candidate 0x7fe2b400d280 (startup) [Mon Apr 11 19:43:10 2022] ------------------------------------------- [Mon Apr 11 19:43:10 2022] >> Anonymized [Mon Apr 11 19:43:10 2022] [3798836899274176] Processing candidate 0x7fe2b400d280 [Mon Apr 11 19:43:10 2022] ------------------------------------------- [Mon Apr 11 19:43:10 2022] [3798836899274176] 1 remote candidate added [Mon Apr 11 19:43:10 2022] [3798836899274176] Sending event to transport... [Mon Apr 11 19:43:10 2022] >> Pushing event: 0 (Success) [Mon Apr 11 19:43:10 2022] [3798836899274176] New selected pair for component 1 in stream 1: 1 <-> remote1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Component is ready enough, starting DTLS handshake... [Mon Apr 11 19:43:10 2022] [3798836899274176] Component state changed for component 1 in stream 1: 3 (connected) [Mon Apr 11 19:43:10 2022] [3798836899274176] Component state changed for component 1 in stream 1: 4 (ready) [Mon Apr 11 19:43:10 2022] [3798836899274176] Creating retransmission timer with ID 7 [Mon Apr 11 19:43:10 2022] Got a Janus API request from janus.transport.http (0x7fe2a401a950) [Mon Apr 11 19:43:10 2022] Session 7665061494737629 found... returning up to 1 messages [Mon Apr 11 19:43:10 2022] Got a keep-alive on session 7665061494737629 [Mon Apr 11 19:43:10 2022] [3798836899274176] DTLS established, yay! [Mon Apr 11 19:43:10 2022] [3798836899274176] Computing sha-256 fingerprint of remote certificate... [Mon Apr 11 19:43:10 2022] [3798836899274176] Remote fingerprint (sha-256) of the client is 82:7C:A8:7A:93:3E:6E:B2:E5:D5:0C:C2:AD:10:AA:0E:B2:0A:0A:25:00:7B:73:86:8F:0B:4F:03:DB:A8:E6:92 [Mon Apr 11 19:43:10 2022] [3798836899274176] Fingerprint is a match! [Mon Apr 11 19:43:10 2022] [3798836899274176] SRTP_AES128_CM_SHA1_80 [Mon Apr 11 19:43:10 2022] [3798836899274176] Key/Salt/Master: 30/16/14 [Mon Apr 11 19:43:10 2022] [3798836899274176] Created inbound SRTP session for component 1 in stream 1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Created outbound SRTP session for component 1 in stream 1 [Mon Apr 11 19:43:10 2022] [3798836899274176] Connecting the SCTP association [Mon Apr 11 19:43:10 2022] [3798836899274176] Connected to the DataChannel peer [Mon Apr 11 19:43:10 2022] [3798836899274176] The DTLS handshake for the component 1 in stream 1 has been completed [Mon Apr 11 19:43:10 2022] [3798836899274176] The DTLS handshake has been completed [Mon Apr 11 19:43:10 2022] [3798836899274176] Telling the plugin about it (JANUS TextRoom plugin) [Mon Apr 11 19:43:10 2022] [janus.plugin.textroom-0x7fe2b4004330] WebRTC media is now available [Mon Apr 11 19:43:10 2022] [3798836899274176] Sending event to transport...; 0x7fe2b400dc40 [Mon Apr 11 19:43:10 2022] [3798836899274176] DTLS already set up, disabling retransmission timer! [Mon Apr 11 19:43:11 2022] Got a Janus API request from janus.transport.http (0x7fe2a40076f0) [Mon Apr 11 19:43:11 2022] Session 7665061494737629 found... returning up to 1 messages [Mon Apr 11 19:43:11 2022] Got a keep-alive on session 7665061494737629 [Mon Apr 11 19:43:11 2022] Association change [Mon Apr 11 19:43:11 2022] SCTP_COMM_UP[Mon Apr 11 19:43:11 2022] , streams (in/out) = (300/300)[Mon Apr 11 19:43:11 2022] , supports[Mon Apr 11 19:43:11 2022] PR[Mon Apr 11 19:43:11 2022] MULTIBUF[Mon Apr 11 19:43:11 2022] RE-CONFIG[Mon Apr 11 19:43:11 2022] . [Mon Apr 11 19:43:22 2022] Timeout expired for session 1627878901769869... [Mon Apr 11 19:43:22 2022] [6235208287404639] Hanging up PeerConnection because of a Detach [Mon Apr 11 19:43:22 2022] Detaching handle from JANUS TextRoom plugin; 0x7fe2b4009ad0 0x7fe298039340 0x7fe2b4009ad0 0x7fe2b40041f0 [Mon Apr 11 19:43:22 2022] [6235208287404639] Handle detached, scheduling destruction [Mon Apr 11 19:43:22 2022] [3714708703991495] Hanging up PeerConnection because of a Detach [Mon Apr 11 19:43:22 2022] Detaching handle from JANUS Streaming plugin; 0x7fe2b400cd20 0x7fe2b4008b60 0x7fe2b400cd20 0x7fe2b400d900 [Mon Apr 11 19:43:22 2022] [3714708703991495] Handle detached, scheduling destruction [Mon Apr 11 19:43:22 2022] Session has timed out and has not been claimed (1627878901769869), getting rid of the queue for the long poll [Mon Apr 11 19:43:22 2022] Destroying session 1627878901769869; 0x7fe298047a00 [Mon Apr 11 19:43:22 2022] [3714708703991495] Telling the plugin about the hangup (JANUS Streaming plugin) [Mon Apr 11 19:43:22 2022] [6235208287404639] DTLS alert triggered on stream 1 (component 1), closing... [Mon Apr 11 19:43:22 2022] [janus.plugin.streaming-0x7fe2b4008b60] No WebRTC media anymore [Mon Apr 11 19:43:22 2022] [6235208287404639] Telling the plugin about the hangup (JANUS TextRoom plugin) [Mon Apr 11 19:43:22 2022] [3714708703991495] Telling the plugin about the handle detach (JANUS Streaming plugin) [Mon Apr 11 19:43:22 2022] [janus.plugin.textroom-0x7fe298039340] No WebRTC media anymore [Mon Apr 11 19:43:22 2022] Leaving 0 rooms [Mon Apr 11 19:43:22 2022] Removing streaming session... [Mon Apr 11 19:43:22 2022] [3714708703991495] Sending event to transport...; 0x7fe2b400cd20 [Mon Apr 11 19:43:22 2022] [3714708703991495] Finalizing loop source [Mon Apr 11 19:43:22 2022] [3714708703991495] Handle thread ended! 0x7fe2b400cd20 [Mon Apr 11 19:43:22 2022] [3714708703991495] Handle and related resources freed; 0x7fe2b400cd20 0x7fe298047a00 [Mon Apr 11 19:43:22 2022] [6235208287404639] WebRTC resources freed; 0x7fe2b4009ad0 0x7fe298047a00 [Mon Apr 11 19:43:22 2022] [6235208287404639] Telling the plugin about the handle detach (JANUS TextRoom plugin) [Mon Apr 11 19:43:22 2022] Removing TextRoom session... [Mon Apr 11 19:43:22 2022] [janus.plugin.textroom-0x7fe298039340] No WebRTC media anymore [Mon Apr 11 19:43:22 2022] Leaving 0 rooms [Mon Apr 11 19:43:22 2022] [6235208287404639] Sending event to transport...; 0x7fe2b4009ad0 [Mon Apr 11 19:43:22 2022] [6235208287404639] Finalizing loop source [Mon Apr 11 19:43:22 2022] [6235208287404639] Handle thread ended! 0x7fe2b4009ad0 [Mon Apr 11 19:43:22 2022] [6235208287404639] Handle and related resources freed; 0x7fe2b4009ad0 0x7fe298047a00 [Mon Apr 11 19:43:38 2022] Got a Janus API request from janus.transport.http (0x7fe298024a30) [Mon Apr 11 19:43:38 2022] Session 1869869330665735 found... returning up to 10 messages [Mon Apr 11 19:43:38 2022] Got a keep-alive on session 1869869330665735 [Mon Apr 11 19:43:41 2022] Got a Janus API request from janus.transport.http (0x7fe2a4002480) [Mon Apr 11 19:43:41 2022] Session 7665061494737629 found... returning up to 1 messages [Mon Apr 11 19:43:41 2022] Got a keep-alive on session 7665061494737629 ```
client side log ``` 2022-04-11 19:43:07.646 17986-18020/androidapp.control D/OkHttp: --> POST https://app.androidapp.com/janus http/1.1 2022-04-11 19:43:07.646 17986-18020/androidapp.control D/OkHttp: Content-Type: application/json 2022-04-11 19:43:07.646 17986-18020/androidapp.control D/OkHttp: Content-Length: 70 2022-04-11 19:43:07.647 17986-18020/androidapp.control D/OkHttp: {"apisecret":"secret321","janus":"create","transaction":"212916171540"} 2022-04-11 19:43:07.647 17986-18020/androidapp.control D/OkHttp: --> END POST (70-byte body) 2022-04-11 19:43:09.105 17986-18020/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus (1457ms) 2022-04-11 19:43:09.106 17986-18020/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:09.106 17986-18020/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:09 GMT 2022-04-11 19:43:09.106 17986-18020/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:09.106 17986-18020/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:09.106 17986-18020/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: { 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: "janus": "success", 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: "transaction": "212916171540", 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: "data": { 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: "id": 7665061494737629 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.108 17986-18020/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.109 17986-18020/androidapp.control D/OkHttp: <-- END HTTP (107-byte body) 2022-04-11 19:43:09.126 17986-18020/androidapp.control I/androidapp.Control: Created Janus session, id=7665061494737629 2022-04-11 19:43:09.130 17986-18020/androidapp.control W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:1477 android.content.ContextWrapper.startService:650 android.content.ContextWrapper.startService:650 androidapp.Control.janus.JanusSession.startPolling:132 androidapp.Control.janus.SharingEngineJanus$1.doInBackground:81 2022-04-11 19:43:09.135 17986-18020/androidapp.control I/org.webrtc.Logging: NativeLibrary: Loading native library: jingle_peerconnection_so 2022-04-11 19:43:09.136 17986-18020/androidapp.control I/org.webrtc.Logging: NativeLibrary: Loading library: jingle_peerconnection_so 2022-04-11 19:43:09.148 17986-18020/androidapp.control I/org.webrtc.Logging: PeerConnectionFactory: PeerConnectionFactory was initialized without an injected Loggable. Any existing Loggable will be deleted. 2022-04-11 19:43:09.178 17986-18020/androidapp.control I/org.webrtc.Logging: WebRtcAudioManagerExternal: Sample rate is set to 48000 Hz 2022-04-11 19:43:09.179 17986-18020/androidapp.control I/org.webrtc.Logging: WebRtcAudioManagerExternal: Sample rate is set to 48000 Hz 2022-04-11 19:43:09.180 17986-18020/androidapp.control I/org.webrtc.Logging: JavaAudioDeviceModule: createAudioDeviceModule 2022-04-11 19:43:09.180 17986-18020/androidapp.control I/org.webrtc.Logging: JavaAudioDeviceModule: HW NS will not be used. 2022-04-11 19:43:09.181 17986-18020/androidapp.control I/org.webrtc.Logging: JavaAudioDeviceModule: HW AEC will not be used. 2022-04-11 19:43:09.182 17986-18020/androidapp.control I/org.webrtc.Logging: WebRtcAudioEffectsExternal: ctor@[name=AsyncTask #1, id=1577] 2022-04-11 19:43:09.183 17986-18020/androidapp.control I/org.webrtc.Logging: WebRtcAudioRecordExternal: ctor@[name=AsyncTask #1, id=1577] 2022-04-11 19:43:09.184 17986-18020/androidapp.control I/org.webrtc.Logging: WebRtcAudioTrackExternal: ctor@[name=AsyncTask #1, id=1577] 2022-04-11 19:43:09.195 17986-18052/androidapp.control I/org.webrtc.Logging: PeerConnectionFactory: onNetworkThreadReady 2022-04-11 19:43:09.196 17986-18053/androidapp.control I/org.webrtc.Logging: PeerConnectionFactory: onWorkerThreadReady 2022-04-11 19:43:09.196 17986-18054/androidapp.control I/org.webrtc.Logging: PeerConnectionFactory: onSignalingThreadReady 2022-04-11 19:43:09.233 17986-18051/androidapp.control D/OkHttp: --> GET https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 http/1.1 2022-04-11 19:43:09.233 17986-18051/androidapp.control D/OkHttp: --> END GET 2022-04-11 19:43:09.262 17986-18020/androidapp.control D/OkHttp: --> POST https://app.androidapp.com/janus/7665061494737629 http/1.1 2022-04-11 19:43:09.262 17986-18020/androidapp.control D/OkHttp: Content-Type: application/json 2022-04-11 19:43:09.263 17986-18020/androidapp.control D/OkHttp: Content-Length: 103 2022-04-11 19:43:09.269 17986-18020/androidapp.control D/OkHttp: {"apisecret":"secret321","janus":"attach","transaction":"496702029995","plugin":"janus.plugin.textroom"} 2022-04-11 19:43:09.269 17986-18020/androidapp.control D/OkHttp: --> END POST (103-byte body) 2022-04-11 19:43:09.531 17986-18020/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629 (243ms) 2022-04-11 19:43:09.531 17986-18020/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:09.532 17986-18020/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:09 GMT 2022-04-11 19:43:09.532 17986-18020/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:09.532 17986-18020/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:09.532 17986-18020/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:09.534 17986-18020/androidapp.control D/OkHttp: { 2022-04-11 19:43:09.535 17986-18020/androidapp.control D/OkHttp: "janus": "success", 2022-04-11 19:43:09.535 17986-18020/androidapp.control D/OkHttp: "session_id": 7665061494737629, 2022-04-11 19:43:09.535 17986-18020/androidapp.control D/OkHttp: "transaction": "496702029995", 2022-04-11 19:43:09.536 17986-18020/androidapp.control D/OkHttp: "data": { 2022-04-11 19:43:09.536 17986-18020/androidapp.control D/OkHttp: "id": 3798836899274176 2022-04-11 19:43:09.536 17986-18020/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.536 17986-18020/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.536 17986-18020/androidapp.control D/OkHttp: <-- END HTTP (142-byte body) 2022-04-11 19:43:09.543 17986-18020/androidapp.control I/androidapp.Control: Attached plugin janus.plugin.textroom, handle_id=3798836899274176 2022-04-11 19:43:09.622 17986-18020/androidapp.control D/OkHttp: --> POST https://app.androidapp.com/janus/7665061494737629/3798836899274176 http/1.1 2022-04-11 19:43:09.622 17986-18020/androidapp.control D/OkHttp: Content-Type: application/json 2022-04-11 19:43:09.622 17986-18020/androidapp.control D/OkHttp: Content-Length: 161 2022-04-11 19:43:09.623 17986-18020/androidapp.control D/OkHttp: {"apisecret":"secret321","janus":"message","session_id":"7665061494737629","transaction":"775448000779","handle_id":"3798836899274176","body":{"request":"setup"}} 2022-04-11 19:43:09.623 17986-18020/androidapp.control D/OkHttp: --> END POST (161-byte body) 2022-04-11 19:43:09.763 17986-18051/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 (529ms) 2022-04-11 19:43:09.763 17986-18051/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:09.763 17986-18051/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:10 GMT 2022-04-11 19:43:09.763 17986-18051/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:09.763 17986-18051/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:09.770 17986-18051/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:09.782 17986-18051/androidapp.control D/OkHttp: { 2022-04-11 19:43:09.783 17986-18051/androidapp.control D/OkHttp: "janus": "event", 2022-04-11 19:43:09.783 17986-18051/androidapp.control D/OkHttp: "session_id": 7665061494737629, 2022-04-11 19:43:09.783 17986-18051/androidapp.control D/OkHttp: "transaction": "775448000779", 2022-04-11 19:43:09.785 17986-18051/androidapp.control D/OkHttp: "sender": 3798836899274176, 2022-04-11 19:43:09.785 17986-18051/androidapp.control D/OkHttp: "plugindata": { 2022-04-11 19:43:09.785 17986-18051/androidapp.control D/OkHttp: "plugin": "janus.plugin.textroom", 2022-04-11 19:43:09.785 17986-18051/androidapp.control D/OkHttp: "data": { 2022-04-11 19:43:09.785 17986-18051/androidapp.control D/OkHttp: "textroom": "event", 2022-04-11 19:43:09.786 17986-18051/androidapp.control D/OkHttp: "result": "ok" 2022-04-11 19:43:09.786 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.787 17986-18051/androidapp.control D/OkHttp: }, 2022-04-11 19:43:09.787 17986-18051/androidapp.control D/OkHttp: "jsep": { 2022-04-11 19:43:09.787 17986-18051/androidapp.control D/OkHttp: "type": "offer", 2022-04-11 19:43:09.787 17986-18051/androidapp.control D/OkHttp: "sdp": "v=0\r\no=- 1649677390189105 1 IN IP4 45.125.46.212\r\ns=Janus TextRoom plugin\r\nt=0 0\r\na=group:BUNDLE data\r\na=msid-semantic: WMS janus\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 45.125.46.212\r\na=sendrecv\r\na=sctp-port:5000\r\na=mid:data\r\na=ice-ufrag:GHne\r\na=ice-pwd:B3KoE6onIPamkxjpFqJ3Gr\r\na=ice-options:trickle\r\na=fingerprint:sha-256 B6:49:50:04:44:3D:00:7C:A4:59:70:58:32:60:E3:3A:E4:44:B7:C5:A7:4A:EB:9D:5C:FE:66:A1:A2:D8:69:C2\r\na=setup:actpass\r\na=candidate:1 1 udp 2015363327 45.125.46.212 37652 typ host\r\na=end-of-candidates\r\n" 2022-04-11 19:43:09.788 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.788 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.788 17986-18051/androidapp.control D/OkHttp: <-- END HTTP (901-byte body) 2022-04-11 19:43:09.800 17986-18051/androidapp.control D/androidapp.Control: Polled data: {"janus":"event","session_id":7665061494737629","transaction":"775448000779","sender":"3798836899274176","plugindata":{"plugin":"janus.plugin.textroom","data":{"textroom":"event","result":"ok"}},"jsep":"{"type":"offer","sdp":"v=0 o=- 1649677390189105 1 IN IP4 45.125.46.212 s=Janus TextRoom plugin t=0 0 a=group:BUNDLE data a=msid-semantic: WMS janus m=application 9 UDP/DTLS/SCTP webrtc-datachannel c=IN IP4 45.125.46.212 a=sendrecv a=sctp-port:5000 a=mid:data a=ice-ufrag:GHne a=ice-pwd:B3KoE6onIPamkxjpFqJ3Gr a=ice-options:trickle a=fingerprint:sha-256 B6:49:50:04:44:3D:00:7C:A4:59:70:58:32:60:E3:3A:E4:44:B7:C5:A7:4A:EB:9D:5C:FE:66:A1:A2:D8:69:C2 a=setup:actpass a=candidate:1 1 udp 2015363327 45.125.46.212 37652 typ host a=end-of-candidates "}} 2022-04-11 19:43:09.805 17986-18051/androidapp.control W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendBroadcast:967 android.content.ContextWrapper.sendBroadcast:437 androidapp.Control.janus.JanusSessionPollService$1.run:113 java.lang.Thread.run:764 2022-04-11 19:43:09.803 17986-18020/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629/3798836899274176 (179ms) 2022-04-11 19:43:09.827 17986-18020/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:09.827 17986-18020/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:10 GMT 2022-04-11 19:43:09.827 17986-18020/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:09.827 17986-18020/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:09.827 17986-18020/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:09.830 17986-18020/androidapp.control D/OkHttp: { 2022-04-11 19:43:09.830 17986-18020/androidapp.control D/OkHttp: "janus": "ack", 2022-04-11 19:43:09.830 17986-18020/androidapp.control D/OkHttp: "session_id": 7665061494737629, 2022-04-11 19:43:09.830 17986-18020/androidapp.control D/OkHttp: "transaction": "775448000779" 2022-04-11 19:43:09.830 17986-18020/androidapp.control D/OkHttp: } 2022-04-11 19:43:09.830 17986-18020/androidapp.control D/OkHttp: <-- END HTTP (90-byte body) 2022-04-11 19:43:09.834 17986-18020/androidapp.control I/androidapp.Control: Got response to JSEP offer, waiting for event 2022-04-11 19:43:09.877 17986-18051/androidapp.control D/OkHttp: --> GET https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 http/1.1 2022-04-11 19:43:09.877 17986-18051/androidapp.control D/OkHttp: --> END GET 2022-04-11 19:43:09.898 17986-18054/androidapp.control D/androidapp.Control: Textroom plugin: signalingState changed to HAVE_REMOTE_OFFER 2022-04-11 19:43:09.898 17986-18054/androidapp.control I/androidapp.Control: RemoteDescription - success 2022-04-11 19:43:09.903 17986-18054/androidapp.control I/androidapp.Control: createAnswer - create success 2022-04-11 19:43:09.905 17986-18054/androidapp.control D/androidapp.Control: Textroom plugin: signalingState changed to STABLE 2022-04-11 19:43:09.906 17986-18054/androidapp.control D/androidapp.Control: Textroom plugin: iceConnectionState changed to CHECKING 2022-04-11 19:43:09.908 17986-18052/androidapp.control I/org.webrtc.Logging: NetworkMonitor: Start monitoring with native observer -1856223360 2022-04-11 19:43:09.931 17986-18060/androidapp.control I/org.webrtc.Logging: NetworkMonitorAutoDetect: Network becomes available: 100 2022-04-11 19:43:09.933 17986-18054/androidapp.control I/androidapp.Control: LocalDescription - success 2022-04-11 19:43:09.952 17986-18060/androidapp.control I/org.webrtc.Logging: NetworkMonitorAutoDetect: capabilities changed: [ Transports: CELLULAR Capabilities: DUN&XCAP&INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN&VALIDATED&FOREGROUND LinkUpBandwidth>=51200Kbps LinkDnBandwidth>=102400Kbps Specifier: <1>] 2022-04-11 19:43:09.956 17986-18054/androidapp.control D/OkHttp: --> POST https://app.androidapp.com/janus/7665061494737629/3798836899274176 http/1.1 2022-04-11 19:43:09.956 17986-18054/androidapp.control D/OkHttp: Content-Type: application/json 2022-04-11 19:43:09.957 17986-18054/androidapp.control D/OkHttp: Content-Length: 661 2022-04-11 19:43:09.958 17986-18054/androidapp.control D/OkHttp: {"apisecret":"secret321","janus":"message","session_id":"7665061494737629","transaction":"017154238062","handle_id":"3798836899274176","body":{"request":"ack"},"jsep":{"sdp":"v=0\r\no=- 8594631152457082093 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE data\r\na=msid-semantic: WMS\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 0.0.0.0\r\nb=AS:30\r\na=ice-ufrag:nxoU\r\na=ice-pwd:sNcnSC2gHG464cP+v5AeU6AM\r\na=ice-options:trickle renomination\r\na=fingerprint:sha-256 82:7C:A8:7A:93:3E:6E:B2:E5:D5:0C:C2:AD:10:AA:0E:B2:0A:0A:25:00:7B:73:86:8F:0B:4F:03:DB:A8:E6:92\r\na=setup:active\r\na=mid:data\r\na=sctp-port:5000\r\n","type":"answer"}} 2022-04-11 19:43:09.959 17986-18054/androidapp.control D/OkHttp: --> END POST (661-byte body) 2022-04-11 19:43:09.962 17986-18060/androidapp.control I/org.webrtc.Logging: NetworkMonitorAutoDetect: link properties changed: {InterfaceName: ccmni0 LinkAddresses: [10.93.168.193/32,] Routes: [0.0.0.0/0 -> 10.93.168.193 ccmni0,10.93.168.193/32 -> 0.0.0.0 ccmni0,] DnsAddresses: [218.2.135.1,218.2.2.2,] Domains: null MTU: 1460 TcpBufferSizes: 2097152,4194304,8388608,262144,524288,1048576} 2022-04-11 19:43:10.157 17986-18054/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629/3798836899274176 (197ms) 2022-04-11 19:43:10.164 17986-18051/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 (286ms) 2022-04-11 19:43:10.164 17986-18051/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:10.164 17986-18051/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:10 GMT 2022-04-11 19:43:10.164 17986-18051/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:10.165 17986-18051/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:10.166 17986-18051/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:10.181 17986-18051/androidapp.control D/OkHttp: { 2022-04-11 19:43:10.183 17986-18051/androidapp.control D/OkHttp: "janus": "event", 2022-04-11 19:43:10.183 17986-18051/androidapp.control D/OkHttp: "session_id": 7665061494737629, 2022-04-11 19:43:10.183 17986-18051/androidapp.control D/OkHttp: "transaction": "017154238062", 2022-04-11 19:43:10.183 17986-18051/androidapp.control D/OkHttp: "sender": 3798836899274176, 2022-04-11 19:43:10.183 17986-18051/androidapp.control D/OkHttp: "plugindata": { 2022-04-11 19:43:10.184 17986-18051/androidapp.control D/OkHttp: "plugin": "janus.plugin.textroom", 2022-04-11 19:43:10.184 17986-18051/androidapp.control D/OkHttp: "data": { 2022-04-11 19:43:10.184 17986-18051/androidapp.control D/OkHttp: "textroom": "event", 2022-04-11 19:43:10.184 17986-18051/androidapp.control D/OkHttp: "result": "ok" 2022-04-11 19:43:10.185 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:10.185 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:10.185 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:10.185 17986-18051/androidapp.control D/OkHttp: <-- END HTTP (267-byte body) 2022-04-11 19:43:10.192 17986-18051/androidapp.control D/androidapp.Control: Polled data: {"janus":"event","session_id":7665061494737629","transaction":"017154238062","sender":"3798836899274176","plugindata":{"plugin":"janus.plugin.textroom","data":{"textroom":"event","result":"ok"}},"jsep":"null} 2022-04-11 19:43:10.194 17986-18051/androidapp.control W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendBroadcast:967 android.content.ContextWrapper.sendBroadcast:437 androidapp.Control.janus.JanusSessionPollService$1.run:113 java.lang.Thread.run:764 2022-04-11 19:43:10.202 17986-18054/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:10.227 17986-18054/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:10 GMT 2022-04-11 19:43:10.227 17986-18054/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:10.227 17986-18054/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:10.227 17986-18054/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:10.231 17986-18054/androidapp.control D/OkHttp: { 2022-04-11 19:43:10.231 17986-18054/androidapp.control D/OkHttp: "janus": "ack", 2022-04-11 19:43:10.231 17986-18054/androidapp.control D/OkHttp: "session_id": 7665061494737629, 2022-04-11 19:43:10.231 17986-18054/androidapp.control D/OkHttp: "transaction": "017154238062" 2022-04-11 19:43:10.232 17986-18051/androidapp.control D/OkHttp: --> GET https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 http/1.1 2022-04-11 19:43:10.232 17986-18051/androidapp.control D/OkHttp: --> END GET 2022-04-11 19:43:10.235 17986-18054/androidapp.control D/OkHttp: } 2022-04-11 19:43:10.235 17986-18054/androidapp.control D/OkHttp: <-- END HTTP (90-byte body) 2022-04-11 19:43:10.247 17986-18054/androidapp.control I/androidapp.Control: Got response to JSEP offer, waiting for event 2022-04-11 19:43:10.550 17986-18051/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 (316ms) 2022-04-11 19:43:10.551 17986-18051/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:10.551 17986-18051/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:10 GMT 2022-04-11 19:43:10.553 17986-18051/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:10.553 17986-18051/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:10.554 17986-18051/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:10.558 17986-18051/androidapp.control D/OkHttp: { 2022-04-11 19:43:10.560 17986-18051/androidapp.control D/OkHttp: "janus": "webrtcup", 2022-04-11 19:43:10.560 17986-18051/androidapp.control D/OkHttp: "session_id": 7665061494737629, 2022-04-11 19:43:10.561 17986-18051/androidapp.control D/OkHttp: "sender": 3798836899274176 2022-04-11 19:43:10.562 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:10.562 17986-18051/androidapp.control D/OkHttp: <-- END HTTP (92-byte body) 2022-04-11 19:43:10.589 17986-18051/androidapp.control D/androidapp.Control: Polled data: {"janus":"webrtcup","session_id":7665061494737629","transaction":"null","sender":"3798836899274176","plugindata":null,"jsep":"null} 2022-04-11 19:43:10.590 17986-18051/androidapp.control W/ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.sendBroadcast:967 android.content.ContextWrapper.sendBroadcast:437 androidapp.Control.janus.JanusSessionPollService$1.run:108 java.lang.Thread.run:764 2022-04-11 19:43:10.597 17986-17986/androidapp.control I/androidapp.Control: WebRTC is up! 2022-04-11 19:43:10.598 17986-18051/androidapp.control D/OkHttp: --> GET https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 http/1.1 2022-04-11 19:43:10.598 17986-18051/androidapp.control D/OkHttp: --> END GET 2022-04-11 19:43:40.730 17986-18051/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 (30131ms) 2022-04-11 19:43:40.731 17986-18051/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:43:40.731 17986-18051/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:43:41 GMT 2022-04-11 19:43:40.731 17986-18051/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:43:40.731 17986-18051/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:43:40.731 17986-18051/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:43:40.738 17986-18051/androidapp.control D/OkHttp: { 2022-04-11 19:43:40.740 17986-18051/androidapp.control D/OkHttp: "janus": "keepalive" 2022-04-11 19:43:40.740 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:43:40.742 17986-18051/androidapp.control D/OkHttp: <-- END HTTP (27-byte body) 2022-04-11 19:43:40.750 17986-18051/androidapp.control D/androidapp.Control: Polled data: {"janus":"keepalive","session_id":null","transaction":"null","sender":"null","plugindata":null,"jsep":"null} 2022-04-11 19:43:40.751 17986-18051/androidapp.control D/androidapp.Control: Janus: Keep-Alive 2022-04-11 19:43:40.756 17986-18051/androidapp.control D/OkHttp: --> GET https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 http/1.1 2022-04-11 19:43:40.757 17986-18051/androidapp.control D/OkHttp: --> END GET 2022-04-11 19:44:10.903 17986-18051/androidapp.control D/OkHttp: <-- 200 https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 (30145ms) 2022-04-11 19:44:10.904 17986-18051/androidapp.control D/OkHttp: server: nginx/1.21.4 2022-04-11 19:44:10.905 17986-18051/androidapp.control D/OkHttp: date: Mon, 11 Apr 2022 11:44:11 GMT 2022-04-11 19:44:10.905 17986-18051/androidapp.control D/OkHttp: content-type: application/json 2022-04-11 19:44:10.905 17986-18051/androidapp.control D/OkHttp: access-control-max-age: 86400 2022-04-11 19:44:10.906 17986-18051/androidapp.control D/OkHttp: access-control-allow-origin: * 2022-04-11 19:44:10.911 17986-18051/androidapp.control D/OkHttp: { 2022-04-11 19:44:10.912 17986-18051/androidapp.control D/OkHttp: "janus": "keepalive" 2022-04-11 19:44:10.913 17986-18051/androidapp.control D/OkHttp: } 2022-04-11 19:44:10.913 17986-18051/androidapp.control D/OkHttp: <-- END HTTP (27-byte body) 2022-04-11 19:44:10.923 17986-18051/androidapp.control D/androidapp.Control: Polled data: {"janus":"keepalive","session_id":null","transaction":"null","sender":"null","plugindata":null,"jsep":"null} 2022-04-11 19:44:10.924 17986-18051/androidapp.control D/androidapp.Control: Janus: Keep-Alive 2022-04-11 19:44:10.928 17986-18051/androidapp.control D/OkHttp: --> GET https://app.androidapp.com/janus/7665061494737629?apisecret=secret321 http/1.1 2022-04-11 19:44:10.943 17986-18051/androidapp.control D/OkHttp: --> END GET ```
lminiero commented 2 years ago

As explained in the guidelines, we don't like huge logs inline. Either use pastebin/gist or similar, or use details/summary in markdown to collapse them (I've just edited the comment for you). That said, this is a connectivity/ICE related problem, not a code issue, and so it's out of scope here. You should ask ask on the group instead, and use something like the Admin API to check what's going wrong.

FJEagle commented 2 years ago

Sorry for the poor format, and thanks for the help. I would follow your suggestion to debug what is going on, thanks.