search

twilio / video-quickstart-android

Twilio Video Quickstart for Android
MIT License
212 stars 159 forks source link

Data track callback never get called #744

Closed VivekKannaV closed 11 months ago

VivekKannaV commented 1 year ago

Description

Whenever I connect to the room all works good except the data track publication. Not receiving the callback failed / published both.

Steps to Reproduce

  1. Create data track
  2. Connect to the room with data track

Code

val dataTrackOptions = DataTrackOptions.Builder()
            .name("SignalTrack")
            .maxPacketLifeTime(2000)
            .build()
val dataTrack = LocalDataTrack.create(context, dataTrackOptions)
val options = ConnectOptions.Builder(accessToken)
            .roomName(roomId)
            .dataTracks(listOf(dataTrack))
            .enableNetworkQuality(true)
            .encodingParameters(EncodingParameters(16, 0))
            .build()

val activeRoom = Video.connect(context, options, this)
override fun onConnected(room: Room) {
        activeRoom.localParticipant.setListener(this)
}
override fun onDataTrackPublished(localParticipant: LocalParticipant, localDataTrackPublication: LocalDataTrackPublication) {
        // Not getting called
}

override fun onDataTrackPublicationFailed(localParticipant: LocalParticipant, localDataTrack: LocalDataTrack, twilioException: TwilioException) {
        // Not getting called
}

Expected Behavior

Actual Behavior

Note: This was working absolutely fine 1 or 2 week back, but not now with the same code.

Reproduces how Often

100%

Logs

00:15:44.407 29251-29251 Twilio                   D  [Core](511038448896): API Call createDataTrack
00:15:44.407 29251-29251                          I  [Core](511038448896): Creating a data track ...
00:15:44.408 29251-29251                          D  [Core](511038448896): API Call getName
00:15:44.408 29251-29251                          D  [Core](511038448896): API Call isEnabled
00:15:44.408 29251-29251                          D  [Core](511038448896): API Call isOrdered
00:15:44.408 29251-29251                          D  [Core](511038448896): API Call isReliable
00:15:44.408 29251-29251                          D  [Core](511038448896): API Call getMaxPacketLifeTime
00:15:44.408 29251-29251                          D  [Core](511038448896): API Call getMaxRetransmits
00:15:44.416 29251-31606                          D  [Core](RoomNotifier): API Call connect
00:15:44.416 29251-31606                          D  [Core](RoomNotifier): Using user provided notifier queue
00:15:44.416 29251-31606                          D  [Core](RoomNotifier): <0x75be0d7f00> RoomImpl::setProxy: proxy: 0x7605e5a040
00:15:44.417 29251-31606                          D  [Core](RoomNotifier): <0x7605e3be18> IoContext::IoContext
00:15:44.417 29251-31606                          D  [Core](RoomNotifier): <0x75be0d7f00> RoomImpl::connect
00:15:44.417 29251-31606                          D  [Core](RoomNotifier): RoomSignalingImpl::RoomSignalingImpl()
00:15:44.417 29251-31606                          D  [Core](RoomNotifier): <0x7570b12b88> SafePoster::SafePoster
00:15:44.418 29251-31606                          D  [Core](RoomNotifier): Opening a new connection 1ef60f10-a4f6-4960-80ab-bad6e3fe847e to wss://global.vss.twilio.com/signaling.
00:15:44.418 29251-31606                          D  [Core](RoomNotifier): Create Transport.
00:15:44.418 29251-31606                          D  [Core](RoomNotifier): Building a SSL Context
00:15:44.418 29251-31606                          D  [Core](RoomNotifier): Loading a custom certificate bundle
00:15:44.422 29251-31606                          D  [Core](RoomNotifier): Adding a cipher list: ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-GCM-SHA384:
00:15:44.422 29251-31606                          D  [Core](RoomNotifier): WebSocket::Implementation::connect: url=wss://global.vss.twilio.com/signaling
00:15:44.423 29251-31606                          D  [Core](RoomNotifier): <0x757090cd00> WebSocket::Implementation::resolveDnsAsync
00:15:44.423 29251-31606                          D  [Core](RoomNotifier): WebSocket connection timeout set to 20000 milliseconds.
00:15:44.423 29251-31606                          D  [Core](RoomNotifier): Create Transport done.
00:15:44.423 29251-31606                          D  [Core](RoomNotifier): API Call getTrackId
00:15:44.423 29251-31609                          D  [Core](505687755968): <0x757090cd00> WebSocket::Implementation::startDnsResolve Starting DNS resolution for global.vss.twilio.com
00:15:44.423 29251-31607                          D  [Core](505723538624): API Call getTrackId
00:15:44.423 29251-31606                          D  [Core](RoomNotifier): API Call getNetworkingThread
00:15:44.424 29251-31607                          D  [Core](505723538624): API Call getTrackId
00:15:44.424 29251-31607                          D  [Core](505723538624): API Call getName
00:15:44.424 29251-31607                          D  [Core](505723538624): API Call isEnabled
00:15:44.424 29251-31606                          D  [Core](RoomNotifier): <0x756fed5518> PeerConnectionManager::PeerConnectionManager
00:15:44.424 29251-31606                          D  [Core](RoomNotifier): API Call getSignalingThread
00:15:44.424 29251-31606                          D  [Core](RoomNotifier): API Call getSignalingThread
00:15:44.424 29251-31606                          D  [Core](RoomNotifier): API Call getTrackId
00:15:44.424 29251-31606                          D  [Core](RoomNotifier): Setting notifier queue. notifier_queue: 0x7605e5a018
00:15:44.424 29251-31606                          D  [Core](RoomNotifier): RoomSignalingImpl: State transition successful: kInit -> kConnecting
00:15:44.424 29251-31607                          D  [Core](505723538624): Cache a connect, sync or ICE message.
00:15:44.469 29251-31609                          D  [Core](505687755968): <0x757090cd00> WebSocket::Implementation::doDnsLookup: DNS resolution completed. duration: 45ms
00:15:44.469 29251-31609                          D  [Core](505687755968): WebSocket::Implementation::on_dns_resolve
00:15:44.469 29251-31609                          D  [Core](505687755968): The DNS resolution completed for global.vss.twilio.com.
00:15:44.469 29251-31609                          D  [Core](505687755968): Trying to connect to 13.234.62.104.
00:15:44.494 29251-31608                          D  [Core](505688796352): Connected to 13.234.62.104.
00:15:44.494 29251-31608                          D  [Core](505688796352): The TCP handshake completed for global.vss.twilio.com.
00:15:44.494 29251-31608                          D  [Core](505688796352): MultiConnect timer was aborted.
00:15:44.550 29251-31608                          D  [Core](505688796352): The TLS handshake completed for global.vss.twilio.com.
00:15:44.579 29251-31608                          D  [Core](505688796352): on_ws_handshake: WebSocket handshake completed.
00:15:44.579 29251-31608                          D  [Core](505688796352): <0x757090cd00> WebSocket::Implementation::callOnReadyIfConnecting
00:15:44.579 29251-31608                          D  [Core](505688796352): The WebSocket protocol upgrade completed for global.vss.twilio.com. Reading indefinitely.
00:15:44.579 29251-31608                          D  [Core](505688796352): The WebSocket connection timer was aborted.
00:15:44.579 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::init
00:15:44.580 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::send (87 bytes)
                                                     {"id":"1ef60f10-a4f6-4960-80ab-bad6e3fe847e","timeout":5000,"type":"hello","version":2}
00:15:44.604 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::onMessage (43 bytes)
                                                     {"negotiatedTimeout":5000,"type":"welcome"}
00:15:44.606 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::send (520 bytes)
                                                     {"body":{"edge":"roaming","token":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCIsImN0eSI6InR3aWxpby1mcGE7dj0xIn0.eyJqdGkiOiJTSzI0MGUxNTZiOGI4NzdiMWVmMWQ0NDU5ZDc3ZTYzNjkxLTE2ODU5OTA3NDQiLCJncmFudHMiOnsiaWRlbnRpdHkiOiJWSVZFSzAxIiwidmlkZW8iOnsicm9vbSI6IkxDMDQ2bmV3MHpfUjlXTjcxRVRUWkoifX0sImlhdCI6MTY4NTk5MDc0NCwiZXhwIjoxNjg1OTk0MzQ0LCJpc3MiOiJTSzI0MGUxNTZiOGI4NzdiMWVmMWQ0NDU5ZDc3ZTYzNjkxIiwic3ViIjoiQUMxODVhNjIxMDk5Mzg2YTdhMzUyODMxYmRlY2Q3NjFkYSJ9.qVHcBk9S9X7KiPnu8Gq_zGR5Qb90iCcl1-QdCa93wG8","type":"ice","version":2},"type":"msg"}
00:15:44.633 29251-29251 NOTIFICATION_LISTENER    D  Status bar notification received: [Details = StatusBarNotification(pkg=com.trimble.ttm.applauncher.stg user=UserHandle{0} id=100 tag=null key=0|com.trimble.ttm.applauncher.stg|100|null|10224: Notification(channel=ServiceNotification shortcut=null contentView=null vibrate=null sound=null defaults=0x0 flags=0x62 color=0x00000000 vis=PRIVATE semFlags=0x0 semPriority=0 semMissedCount=0)), is on going = true, id = 100, key = 0|com.trimble.ttm.applauncher.stg|100|null|10224, package = com.trimble.ttm.applauncher.stg]
00:15:45.766 29251-31608 Twilio                   D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::onMessage (475 bytes)
                                                     {"body":{"version":1,"type":"iced","participants":[],"ice_servers":[{"urls":"turn:mumbai.turn.twilio.com:3478?transport=udp","username":"30c011785c08963766d7fbecf1b7a01031cf60d1c1c450e1f0fc0a330ed2a31e","credential":"GYJ6meQMe0rg4m0LWmYglDRbQij0x+Ud/tkWJNc0E7c="},{"urls":"turns:mumbai.turn.twilio.com:443?transport=tcp","username":"30c011785c08963766d7fbecf1b7a01031cf60d1c1c450e1f0fc0a330ed2a31e","credential":"GYJ6meQMe0rg4m0LWmYglDRbQij0x+Ud/tkWJNc0E7c="}]},"type":"msg"}
00:15:45.768 29251-31607                          D  [Core](505723538624): Creating PeerConnectionSignaling instance. id: 6ee6bb88F046d0De888D35eBCf6a26F7
00:15:45.768 29251-31607                          D  [Core](505723538624): API Call getSignalingThread
00:15:45.768 29251-31607                          D  [Core](505723538624): API Call getSignalingThread
00:15:45.768 29251-31607                          D  [Core](505723538624): API Call getNetworkingThread
00:15:45.768 29251-31607                          D  [Core](505723538624): <0x75942cc600> SafePoster::SafePoster
00:15:45.768 29251-31607                          D  [Core](505723538624): <0x7594254000> PeerConnectionSignaling::initialize
00:15:45.768 29251-31607                          D  [Core](505723538624): <0x7605e67c00> Starting the Network Manager
00:15:45.769 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): API Call RTCIceServers
00:15:45.769 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): API Call RTCIceServer
00:15:45.769 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): API Call RTCIceServer
00:15:45.769 29251-29803                          I  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Creating peer connection ...
00:15:45.794 29251-31607                          D  [Core](505723538624): <0x7594254000> PeerConnectionSignaling::createDataChannel
00:15:45.794 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine::createDataChannel state: kInitial
00:15:45.794 29251-31607                          D  [Core](505723538624): Queueing operation for next offer: CreateDataChannelOperation id: 0f5d673EF9Cc91Fb797B36fa9ECE5ceA, handle: 504997135992
00:15:45.794 29251-31607                          D  [Core](505723538624): <0x75944ee098> DataTrackSender::addDataChannel: Invoking registerObserver on the signaling thread.
00:15:45.794 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Adding data channel handle for peer connection id: 6ee6bb88F046d0De888D35eBCf6a26F7
00:15:45.795 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine::createOffer state: kInitial
00:15:45.795 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine::generateOffer
00:15:45.795 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine::applyPendingOperations
00:15:45.795 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine::prunePendingOperations
00:15:45.795 29251-31607                          D  [Core](505723538624): Invoking doCreateDataChannel on the signaling thread.
00:15:45.796 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Created data channel, id: -1, track_id: 0f5d673EF9Cc91Fb797B36fa9ECE5ceA
00:15:45.796 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Registering data channel observer.
00:15:45.797 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine state: kInitial -> kWaitingInitialAnswer
00:15:45.798 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Adding an audio transceiver for compatibility with plan-b endpoints.
00:15:45.799 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Adding a video transceiver for compatibility with plan-b endpoints.
00:15:45.799 29251-29803                          D  [Core](MediaFactoryImpl::signaling 0x0x7570d17a80): Create local offer. id: 6ee6bb88F046d0De888D35eBCf6a26F7 revision: 1
00:15:45.804 29251-31607                          D  [Core](505723538624): Setting use dtx
00:15:45.809 29251-31607                          I  [Core](505723538624): Local description created. type: offer id: 6ee6bb88F046d0De888D35eBCf6a26F7 revision: 1
00:15:45.809 29251-31607                          D  [Core](505723538624): <0x7594254220> SdpStateMachine::onLocalDescriptionCreated state: kWaitingInitialAnswer
00:15:45.809 29251-31607                          D  [Core](505723538624): Local offer generated.
00:15:45.809 29251-31607                          D  [Core](505723538624): Waiting to apply the initial offer until we receive the corresponding answer.
00:15:45.810 29251-31607                          D  [Core](505723538624): Removing use dtx from fmtp line
00:15:45.811 29251-31607                          I  [Core](505723538624): Local offer is ready for 6ee6bb88F046d0De888D35eBCf6a26F7.
00:15:45.811 29251-31607                          D  [Core](505723538624): Queue Description: 1 for PeerConnection: 6ee6bb88F046d0De888D35eBCf6a26F7.
00:15:45.811 29251-31607                          D  [Core](505723538624): API Call getExternalAudioProcessor
00:15:45.813 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::send (5111 bytes)
                                                     {"body":{"format":"unified","ice_servers":"success","media_signaling":{"network_quality":{"transports":[{"type":"data-channel"}]}},"name":"LC046new0z_R9WN71ETTZJ","participant":{"revision":1,"tracks":[{"enabled":true,"id":"0f5d673EF9Cc91Fb797B36fa9ECE5ceA","kind":"data","name":"SignalTrack","priority":"standard"}]},"peer_connections":[{"description":{"revision":1,"sdp":"v=0\r\no=- 8631883967631189423 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0 1 2\r\na=extmap-allow-mixed\r\na=msid-semantic: WMS\r\nm=audio 9 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113 126\r\nc=IN IP4 0.0.0.0\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=ice-ufrag:Fewz\r\na=ice-pwd:VvR8SdoKT3noFmrd2nUTFX2+\r\na=ice-options:trickle\r\na=fingerprint:sha-256 4B:DB:10:DF:A3:D3:93:54:FD:66:F8:C4:23:45:A8:07:EB:74:C1:AB:0A:D3:E3:26:FF:02:B1:4C:4D:F2:B0:B2\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://
00:15:46.996 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::onMessage (1153 bytes)
                                                     {"body":{"version":2,"type":"connected","sid":"RMe6412e7cdc87f045240f403fdb5685a3","name":"LC046new0z_R9WN71ETTZJ","participant":{"sid":"PAe7eb4f313cafe7a75e30d2ca34f7ffba","identity":"VIVEK01","tracks":[{"kind":"data","priority":"standard","id":"0f5d673EF9Cc91Fb797B36fa9ECE5ceA","enabled":true,"sid":"MT7e1b6926dadf44c48e600c6fc35e9ac7","name":"SignalTrack","state":"ready"}],"revision":1,"state":"connected","media_warnings":[]},"participants":[{"sid":"PA1d2b5b5322d37bb65dc277956fcc6be5","identity":"vivekkanna_v@trimble.com","tracks":[],"revision":1,"state":"connected"}],"recording":{"enabled":false,"revision":1,"is_recording":false},"subscribed":{"revision":1,"tracks":[]},"published":{"revision":1,"tracks":[{"kind":"data","priority":"standard","id":"0f5d673EF9Cc91Fb797B36fa9ECE5ceA","enabled":true,"sid":"MT7e1b6926dadf44c48e600c6fc35e9ac7","name":"SignalTrack","state":"ready"}]},"session":"185a621099386a7a352831bdecd761dae6412e7cdc
00:15:46.999 29251-31608                          D  [Core](505688796352): <0x7570d9d200> TcmpWssTransport::onMessage (855 bytes)
                                                     {"body":{"version":2,"type":"update","sid":"RMe6412e7cdc87f045240f403fdb5685a3","name":"RMe6412e7cdc87f045240f403fdb5685a3","participant":{"sid":"PAe7eb4f313cafe7a75e30d2ca34f7ffba","identity":"VIVEK01","tracks":[{"kind":"data","priority":"standard","id":"0f5d673EF9Cc91Fb797B36fa9ECE5ceA","enabled":true,"sid":"MT7e1b6926dadf44c48e600c6fc35e9ac7","name":"SignalTrack","state":"ready"}],"revision":1,"state":"connected","media_warnings":[]},"participants":[],"recording":{"enabled":false,"revision":1,"is_recording":false},"subscribe":{"revision":1,"rules":[{"type":"include","all":true}]},"subscribed":{"revision":1,"tracks":[]},"published":{"revision":1,"tracks":[{"kind":"data","priority":"standard","id":"0f5d673EF9Cc91Fb797B36fa9ECE5ceA","enabled":true,"sid":"MT7e1b6926dadf44c48e600c6fc35e9ac7","name":"SignalTrack","state":"ready"}]}},"type":"msg"}
00:15:46.999 29251-31607                          D  [Core](505723538624): <0x7570ba1b48> TimerCancellationFlag::set: reason: TcmpSignaling::cancelReconnectionTimer, data: 0x7605da2258
00:15:46.999 29251-31607                          D  [Core](505723538624): RoomSignalingImpl::onConnectedOrSynced

Versions

KOTLIN = "1.8.21" GRADLE_TOOLS = "8.0.1" TARGET_SDK_VERSION = 33 BUILD_TOOLS_VERSION = "33.0.2" JVM_TARGET_VERSION = "17"

Video Android SDK

7.6.1

Android API

TARGET_SDK = 33 Android SDK: 30, Release: 11

Android Device

Samsung Tab Active A Model: SM-T295 Hardware: qcom

ocarevs commented 1 year ago

Hi @VivekKannaV I see from the Room sid in the provided logs that it's a GO room. In peer-to-peer and go room this callback will not arrive when DataTrack is passed in ConnectOptions; onDataTrackPublished callback in this scenario will only trigger in group rooms.