client-sdk-android icon indicating copy to clipboard operation
client-sdk-android copied to clipboard

Published 20 hours ago • verified publisher icon livekit

`RoomEvent.Reconnected` never received

Open AchrafAmil opened this issue 3 years ago • 2 comments

After switching from WiFi to 4G the livekit client successfully recovers as I receive a RoomEvent.Reconnecting followed by the video stream coming back on track after few ms of being frozen.

Though, I never receive RoomEvent.Reconnected so I had to rely on RoomEvent.TrackPublished happening after a reconnection to consider the reconnection as successful.

All received events during a reconnection:

10:31:53.644 New event in room: Reconnecting
10:31:54.257 New event in room: TrackUnpublished
10:31:54.257 New event in room: TrackUnpublished
10:31:58.011 New event in room: TrackPublished
10:31:58.064 New event in room: TrackPublished
10:31:58.455 New event in room: ConnectionQualityChanged

Verbose livekit logs starting from reconnecting state:

PublisherTransportObserver: onIceConnection new state: CHECKING
PublisherTransportObserver: onConnection new state: CONNECTING
RTCEngine: received ice candidate from peer
SubscriberTransportObserver: onIceCandidate
SignalClient: sending request: # livekit.LivekitRtc$SignalRequest@d816c463
trickle {.. some json ..}
PublisherTransportObserver: onIceCandidate
SignalClient: sending request: # livekit.LivekitRtc$SignalRequest@77d15186
trickle {.. some json ..}
PublisherTransportObserver: onIceCandidate
SignalClient: sending request: # livekit.LivekitRtc$SignalRequest@77d15186
trickle {.. some json ..}

PublisherTransportObserver: onConnection new state: CONNECTED
PublisherTransportObserver: onIceConnection new state: CONNECTED
RTCEngine$reconnect$job: publisher reconnected to ICE
SubscriberTransportObserver: onConnectionChange new state: CONNECTED
RTCEngine$configure$connectionStateListener: onIceConnection new state: CONNECTED
RTCEngine: primary ICE connected
SubscriberTransportObserver: onIceConnection new state: CONNECTED
RTCEngine$reconnect$job: reconnected to ICE
SignalClient: sending request: # livekit.LivekitRtc$SignalRequest@f27316f0
add_track {.. some json ..}
SignalClient: response: # livekit.LivekitRtc$SignalResponse@73ed16fc
track_published {.. some json ..}
RTCEngine: local track published 2f15daa6-0c03-4785-a0e1-4c5aabe67c17
LocalParticipant: using video encoding: VideoEncoding(maxBitrate=2000000, maxFps=30)

AchrafAmil avatar Jun 29 '22 08:06 AchrafAmil

@AchrafAmil thanks for the report. Does the Room.connectionState stay at RECONNECTING or does it switch to CONNECTED (without firing the event)?

davidliu avatar Jun 29 '22 09:06 davidliu

@AchrafAmil thanks for the report. Does the Room.connectionState stay at RECONNECTING or does it switch to CONNECTED (without firing the event)?

It does switch to connected.

Checking the event.room.state: After RoomEvent.Reconnecting -> state is RECONNECTING After each of the two RoomEvent.TrackPublished happening few seconds after reconnecting -> state is CONNECTED

AchrafAmil avatar Jun 29 '22 16:06 AchrafAmil

Using 1.1.3, the same issue still appears to occur, if the connection of the client totally fails. It looks like the RTCEngince connectionState is set to DISCONNECTED in this case, because reconnection is immediately failing. When the client recovers connection, only onEngineConnected() is called and not onEngineReconnected().

To simulate this kind of client issue, I was enabling airplane mode on the client.

The connectionState values in this sequence:

D/RTCEngine: primary ICE connected
D/RTCEngine: primary ICE disconnected -> reconnection failed
D/RTCEngine: primary ICE connected

Is this an expected behaviour?

vincentbrison avatar Sep 19 '22 09:09 vincentbrison

@vincentbrison Hmm, could you post a full set of logs? Hard to diagnose from this alone.

davidliu avatar Sep 19 '22 10:09 davidliu

Of course, here is a log with the following sequence:

  • Connecting to a room
  • Connected
  • Airplane mode on, reconnecting, then disconnected
  • Airplane mode off, connected
  • Manually disconnecting the call
Logs 
: tcp_port.cc: (line 303): Port[222552d0::1:0:local:Net[eth0:2001:2:0:x:x:x:x:x/64:Cellular:id=2]]: TCP server socket creation failed; continuing anyway.
2022-09-19 14:32:56.481 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: turn_port.cc: (line 836): Port[321b9150:0:1:0:relay:Net[wlan0:2001:2:0:x:x:x:x:x/64:Wifi:id=6]]: TURN host lookup received error 0
2022-09-19 14:32:56.481 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: turn_port.cc: (line 836): Port[321b5800:0:1:0:relay:Net[eth0:2001:2:0:x:x:x:x:x/64:Cellular:id=2]]: TURN host lookup received error 0
2022-09-19 14:32:56.505 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: android_network_monitor.cc: (line 406): BindSocketToNetwork got error: -1 addr: 10.0.2.x ifname: eth0
2022-09-19 14:32:56.505 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: physical_socket_server.cc: (line 210): Binding socket to network address failed; result: -1
2022-09-19 14:32:56.506 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: basic_packet_socket_factory.cc: (line 76): TCP bind failed with error 2
2022-09-19 14:32:56.506 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: tcp_port.cc: (line 303): Port[22255fb0::1:0:local:Net[eth0:10.0.0.x/8:Cellular:id=1]]: TCP server socket creation failed; continuing anyway.
2022-09-19 14:32:56.506 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: android_network_monitor.cc: (line 406): BindSocketToNetwork got error: -1 addr: 10.0.2.x ifname: eth0
2022-09-19 14:32:56.506 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: physical_socket_server.cc: (line 210): Binding socket to network address failed; result: -1
2022-09-19 14:32:56.506 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: basic_packet_socket_factory.cc: (line 106): TCP bind failed with error 2
2022-09-19 14:32:56.506 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: tcp_port.cc: (line 581): Conn[521b30b0:0:Net[eth0:10.0.0.x/8:Cellular:id=1]:yufPZQUp:1:0:local:tcp:10.0.2.x:9->B+U8cQxt:1:2124414975:local:tcp:35.195.155.x:7881|C--W|-|0|0|6520120445339959294|-]: Failed to create connection to 35.195.155.x:7881
2022-09-19 14:32:56.526 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: basic_port_allocator.cc: (line 976): Discarding candidate because port is already done gathering.
2022-09-19 14:32:56.547 24836-24865/com.nabla.sdk.playground.dev D/PeerConnectionTransport: starting to negotiate
2022-09-19 14:32:56.549 24836-24924/com.nabla.sdk.playground.dev W/RTCModule: media_session.cc: (line 949): RED codec red is missing an associated payload type.
2022-09-19 14:32:56.553 24836-24923/com.nabla.sdk.playground.dev W/RTCModule: audio_send_stream.cc: (line 876): Config is invalid: min_bitrate_bps=-1; max_bitrate_bps=-1; both expected greater or equal to 0
2022-09-19 14:32:56.559 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: basic_port_allocator.cc: (line 976): Discarding candidate because port is already done gathering.
2022-09-19 14:32:56.587 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: android_network_monitor.cc: (line 406): BindSocketToNetwork got error: -1 addr: 10.0.2.x ifname: eth0
2022-09-19 14:32:56.587 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: physical_socket_server.cc: (line 210): Binding socket to network address failed; result: -1
2022-09-19 14:32:56.587 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: basic_packet_socket_factory.cc: (line 106): TCP bind failed with error 2
2022-09-19 14:32:56.587 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: turn_port.cc: (line 387): Failed to create TURN client socket
2022-09-19 14:32:56.623 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: openssl_adapter.cc: (line 435): ContinueSSL -- error -1
2022-09-19 14:32:56.623 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: openssl_adapter.cc: (line 443): OpenSSLAdapter::Error(ContinueSSL, -1)
2022-09-19 14:32:56.623 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: turn_port.cc: (line 528): Port[321af5c0:0:1:0:relay:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: Connection with server failed with error: -1
2022-09-19 14:32:56.625 24836-24923/com.nabla.sdk.playground.dev W/RTCModule: audio_send_stream.cc: (line 876): Config is invalid: min_bitrate_bps=-1; max_bitrate_bps=-1; both expected greater or equal to 0
2022-09-19 14:32:56.626 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: peer_connection.cc: (line 2685): Candidate has an unknown component: Cand[:1931765387:2:udp:2130706431:35.195.155.x:7882:local::0:sNbOtyQkFCGdhxEP:FyUmwdmjtGncvuyCdNWxZcNEzMgNYACG:0:0:0] for mid 0
2022-09-19 14:32:56.627 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: peer_connection.cc: (line 2685): Candidate has an unknown component: Cand[:3470202731:2:tcp:2124414975:35.195.155.x:7881:local::0:sNbOtyQkFCGdhxEP:FyUmwdmjtGncvuyCdNWxZcNEzMgNYACG:0:0:0] for mid 0
2022-09-19 14:32:56.666 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: openssl_adapter.cc: (line 435): ContinueSSL -- error -1
2022-09-19 14:32:56.666 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: openssl_adapter.cc: (line 443): OpenSSLAdapter::Error(ContinueSSL, -1)
2022-09-19 14:32:56.666 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: turn_port.cc: (line 528): Port[321b7090:0:1:0:relay:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: Connection with server failed with error: -1
2022-09-19 14:32:56.728 24836-24887/com.nabla.sdk.playground.dev D/PeerConnectionTransport: starting to negotiate
2022-09-19 14:32:56.729 24836-24924/com.nabla.sdk.playground.dev W/RTCModule: media_session.cc: (line 949): RED codec red is missing an associated payload type.
2022-09-19 14:32:57.376 24836-24924/com.nabla.sdk.playground.dev D/RTCEngine: primary ICE connected
2022-09-19 14:32:57.391 24836-24923/com.nabla.sdk.playground.dev W/RTCModule: sdes.cc: (line 136): CNAME not found for ssrc 184849913
2022-09-19 14:33:00.657 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: basic_port_allocator.cc: (line 816): Machine has no networks; no ports will be allocated
2022-09-19 14:33:00.657 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: basic_port_allocator.cc: (line 816): Machine has no networks; no ports will be allocated
2022-09-19 14:33:00.657 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: turn_port.cc: (line 860): Port[321b1eb0:0:1:0:relay:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: Failed to send TURN message, error: 101
2022-09-19 14:33:00.663 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: turn_port.cc: (line 860): Port[321b80f0:0:1:0:relay:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: Failed to send TURN message, error: 101
2022-09-19 14:33:00.666 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222518e0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 63 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:00.680 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222518e0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 68 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:00.774 24836-24885/com.nabla.sdk.playground.dev W/RTCEngine$reconnect$job: Error during reconnection.
    java.net.UnknownHostException: Unable to resolve host "uexssyrb8a.nabla.com": No address associated with hostname
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:156)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103)
        at java.net.InetAddress.getAllByName(InetAddress.java:1152)
        at okhttp3.Dns$Companion$DnsSystem.lookup(Dns.kt:49)
        at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress(RouteSelector.kt:164)
        at okhttp3.internal.connection.RouteSelector.nextProxy(RouteSelector.kt:129)
        at okhttp3.internal.connection.RouteSelector.next(RouteSelector.kt:71)
        at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:205)
        at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106)
        at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74)
        at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.kt:221)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.make$lambda-4(HttpLoggingInterceptorFactory.kt:22)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.$r8$lambda$ffmrFpQd68Ecl_6Ph53UVibyiHw(Unknown Source:0)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory$$ExternalSyntheticLambda0.intercept(Unknown Source:4)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.SdkVersionInterceptor.intercept(SdkVersionInterceptor.kt:12)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.PublicApiKeyInterceptor.intercept(PublicApiKeyInterceptor.kt:11)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.AuthorizationInterceptor.intercept(AuthorizationInterceptor.kt:44)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.AcceptLanguageInterceptor.intercept(AcceptLanguageInterceptor.kt:12)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.UserHeaderInterceptor.intercept(UserHeaderInterceptor.kt:19)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:920)
     Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
        at libcore.io.Linux.android_getaddrinfo(Native Method)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:136)
        at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:221)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:136)
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:135)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103) 
        at java.net.InetAddress.getAllByName(InetAddress.java:1152) 
        at okhttp3.Dns$Companion$DnsSystem.lookup(Dns.kt:49) 
        at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress(RouteSelector.kt:164) 
        at okhttp3.internal.connection.RouteSelector.nextProxy(RouteSelector.kt:129) 
        at okhttp3.internal.connection.RouteSelector.next(RouteSelector.kt:71) 
        at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:205) 
        at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106) 
        at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74) 
        at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255) 
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.kt:221) 
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.make$lambda-4(HttpLoggingInterceptorFactory.kt:22) 
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.$r8$lambda$ffmrFpQd68Ecl_6Ph53UVibyiHw(Unknown Source:0) 
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory$$ExternalSyntheticLambda0.intercept(Unknown Source:4) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.SdkVersionInterceptor.intercept(SdkVersionInterceptor.kt:12) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.PublicApiKeyInterceptor.intercept(PublicApiKeyInterceptor.kt:11) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.AuthorizationInterceptor.intercept(AuthorizationInterceptor.kt:44) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.AcceptLanguageInterceptor.intercept(AcceptLanguageInterceptor.kt:12) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.UserHeaderInterceptor.intercept(UserHeaderInterceptor.kt:19) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) 
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
        at java.lang.Thread.run(Thread.java:920) 
2022-09-19 14:33:00.881 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222464a0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 108 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:00.881 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: connection.cc: (line 435): Conn[521ac300:0:Net[wlan0:10.0.2.x/24:Wifi:id=5]:vTnt/m1U:1:0:stun:udp:90.66.142.x:49854->d9F9Cfrc:1:2130706431:local:udp:35.195.155.x:7882|CRWS|S|1|0|7241259335685242879|86]: Failed to send STUN ping  err=-1 id=5478675a4647503048634551
2022-09-19 14:33:01.082 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222518e0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 64 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:01.110 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222518e0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 69 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:01.135 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222518e0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 112 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:01.135 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: connection.cc: (line 435): Conn[521a8610:0:Net[wlan0:10.0.2.x/24:Wifi:id=5]:e4ovsxM3:1:0:stun:udp:90.66.142.x:53461->GBat2HK5:1:2130706431:local:udp:35.195.155.x:7882|CRWS|S|0|0|7241259335685242878|42]: Failed to send STUN ping  err=-1 id=695167726a36494630486557
2022-09-19 14:33:01.376 24836-24912/com.nabla.sdk.playground.dev D/RTCEngine: primary ICE disconnected
2022-09-19 14:33:01.428 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222464a0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 69 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:01.429 24836-24922/com.nabla.sdk.playground.dev E/RTCModule: stun_port.cc: (line 304): Port[222464a0:0:1:0:local:Net[wlan0:10.0.2.x/24:Wifi:id=5]]: UDP send of 39 bytes to host 35.195.155.x:7882 (35.195.155.x:7882) failed with error 101
2022-09-19 14:33:01.444 24836-24960/com.nabla.sdk.playground.dev W/RTCEngine$reconnect$job: Error during reconnection.
    java.net.UnknownHostException: Unable to resolve host "uexssyrb8a.nabla.com": No address associated with hostname
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:124)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103)
        at java.net.InetAddress.getAllByName(InetAddress.java:1152)
        at okhttp3.Dns$Companion$DnsSystem.lookup(Dns.kt:49)
        at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress(RouteSelector.kt:164)
        at okhttp3.internal.connection.RouteSelector.nextProxy(RouteSelector.kt:129)
        at okhttp3.internal.connection.RouteSelector.next(RouteSelector.kt:71)
        at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:205)
        at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106)
        at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74)
        at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.kt:221)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.make$lambda-4(HttpLoggingInterceptorFactory.kt:22)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.$r8$lambda$ffmrFpQd68Ecl_6Ph53UVibyiHw(Unknown Source:0)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory$$ExternalSyntheticLambda0.intercept(Unknown Source:4)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.SdkVersionInterceptor.intercept(SdkVersionInterceptor.kt:12)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.PublicApiKeyInterceptor.intercept(PublicApiKeyInterceptor.kt:11)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.AuthorizationInterceptor.intercept(AuthorizationInterceptor.kt:44)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.AcceptLanguageInterceptor.intercept(AcceptLanguageInterceptor.kt:12)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.UserHeaderInterceptor.intercept(UserHeaderInterceptor.kt:19)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:920)
2022-09-19 14:33:03.557 24836-24960/com.nabla.sdk.playground.dev W/RTCEngine$reconnect$job: Error during reconnection.
    java.net.UnknownHostException: Unable to resolve host "uexssyrb8a.nabla.com": No address associated with hostname
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:156)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103)
        at java.net.InetAddress.getAllByName(InetAddress.java:1152)
        at okhttp3.Dns$Companion$DnsSystem.lookup(Dns.kt:49)
        at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress(RouteSelector.kt:164)
        at okhttp3.internal.connection.RouteSelector.nextProxy(RouteSelector.kt:129)
        at okhttp3.internal.connection.RouteSelector.next(RouteSelector.kt:71)
        at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:205)
        at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106)
        at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74)
        at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.kt:221)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.make$lambda-4(HttpLoggingInterceptorFactory.kt:22)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.$r8$lambda$ffmrFpQd68Ecl_6Ph53UVibyiHw(Unknown Source:0)
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory$$ExternalSyntheticLambda0.intercept(Unknown Source:4)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.SdkVersionInterceptor.intercept(SdkVersionInterceptor.kt:12)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.PublicApiKeyInterceptor.intercept(PublicApiKeyInterceptor.kt:11)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.AuthorizationInterceptor.intercept(AuthorizationInterceptor.kt:44)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.AcceptLanguageInterceptor.intercept(AcceptLanguageInterceptor.kt:12)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at com.nabla.sdk.core.data.auth.UserHeaderInterceptor.intercept(UserHeaderInterceptor.kt:19)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:920)
     Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
        at libcore.io.Linux.android_getaddrinfo(Native Method)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:136)
        at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:221)
        at libcore.io.ForwardingOs.android_getaddrinfo(ForwardingOs.java:136)
        at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:135)
        at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:103) 
        at java.net.InetAddress.getAllByName(InetAddress.java:1152) 
        at okhttp3.Dns$Companion$DnsSystem.lookup(Dns.kt:49) 
        at okhttp3.internal.connection.RouteSelector.resetNextInetSocketAddress(RouteSelector.kt:164) 
        at okhttp3.internal.connection.RouteSelector.nextProxy(RouteSelector.kt:129) 
        at okhttp3.internal.connection.RouteSelector.next(RouteSelector.kt:71) 
        at okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:205) 
        at okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106) 
        at okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74) 
        at okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255) 
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.logging.HttpLoggingInterceptor.intercept(HttpLoggingInterceptor.kt:221) 
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.make$lambda-4(HttpLoggingInterceptorFactory.kt:22) 
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory.$r8$lambda$ffmrFpQd68Ecl_6Ph53UVibyiHw(Unknown Source:0) 
        at com.nabla.sdk.core.data.logger.HttpLoggingInterceptorFactory$$ExternalSyntheticLambda0.intercept(Unknown Source:4) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.SdkVersionInterceptor.intercept(SdkVersionInterceptor.kt:12) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.PublicApiKeyInterceptor.intercept(PublicApiKeyInterceptor.kt:11) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.AuthorizationInterceptor.intercept(AuthorizationInterceptor.kt:44) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.AcceptLanguageInterceptor.intercept(AcceptLanguageInterceptor.kt:12) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at com.nabla.sdk.core.data.auth.UserHeaderInterceptor.intercept(UserHeaderInterceptor.kt:19) 
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109) 
        at okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201) 
        at okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517) 
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) 
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) 
        at java.lang.Thread.run(Thread.java:920) 
2022-09-19 14:33:08.428 24836-24924/com.nabla.sdk.playground.dev E/RTCModule: sctp_data_channel.cc: (line 87): Accepting maxRetransmits < 0 for backwards compatibility
2022-09-19 14:33:08.429 24836-24924/com.nabla.sdk.playground.dev E/RTCModule: sctp_data_channel.cc: (line 97): Accepting maxRetransmitTime < 0 for backwards compatibility
2022-09-19 14:33:08.444 24836-24924/com.nabla.sdk.playground.dev E/RTCModule: sctp_data_channel.cc: (line 97): Accepting maxRetransmitTime < 0 for backwards compatibility
2022-09-19 14:33:08.452 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: NetworkMonitorAutoDetect: Unable to obtain permission to request a cellular network.
2022-09-19 14:33:08.461 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: stun_port.cc: (line 479): STUN server address is incompatible.
2022-09-19 14:33:08.509 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: peer_connection.cc: (line 2685): Candidate has an unknown component: Cand[:1931765387:2:udp:2130706431:35.195.155.x:7882:local::0:TTlnZtrSmwaCqitu:eOtfBUZfCizLIisUJadqbKxlKZIidMhW:0:0:0] for mid 0
2022-09-19 14:33:08.509 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: peer_connection.cc: (line 2685): Candidate has an unknown component: Cand[:3470202731:2:tcp:2124414975:35.195.155.x:7881:local::0:TTlnZtrSmwaCqitu:eOtfBUZfCizLIisUJadqbKxlKZIidMhW:0:0:0] for mid 0
2022-09-19 14:33:08.592 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: peer_connection.cc: (line 2685): Candidate has an unknown component: Cand[:1931765387:2:udp:2130706431:35.195.155.x:7882:local::0:TTlnZtrSmwaCqitu:eOtfBUZfCizLIisUJadqbKxlKZIidMhW:0:0:0] for mid 0
2022-09-19 14:33:08.592 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: peer_connection.cc: (line 2685): Candidate has an unknown component: Cand[:3470202731:2:tcp:2124414975:35.195.155.x:7881:local::0:TTlnZtrSmwaCqitu:eOtfBUZfCizLIisUJadqbKxlKZIidMhW:0:0:0] for mid 0
2022-09-19 14:33:08.620 24836-24886/com.nabla.sdk.playground.dev D/PeerConnectionTransport: starting to negotiate
2022-09-19 14:33:08.621 24836-24924/com.nabla.sdk.playground.dev W/RTCModule: media_session.cc: (line 949): RED codec red is missing an associated payload type.
2022-09-19 14:33:08.624 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: stun_port.cc: (line 479): STUN server address is incompatible.
2022-09-19 14:33:08.778 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: basic_port_allocator.cc: (line 976): Discarding candidate because port is already done gathering.
2022-09-19 14:33:08.781 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: turn_port.cc: (line 836): Port[321b3740:0:1:0:relay:Net[eth0:2001:2:0:x:x:x:x:x/64:Cellular:id=2]]: TURN host lookup received error 0
2022-09-19 14:33:08.863 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: openssl_adapter.cc: (line 435): ContinueSSL -- error -1
2022-09-19 14:33:08.863 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: openssl_adapter.cc: (line 443): OpenSSLAdapter::Error(ContinueSSL, -1)
2022-09-19 14:33:08.863 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: turn_port.cc: (line 528): Port[321a20e0:0:1:0:relay:Net[eth0:10.0.0.x/8:Cellular:id=1]]: Connection with server failed with error: -1
2022-09-19 14:33:09.700 24836-24924/com.nabla.sdk.playground.dev D/RTCEngine: primary ICE connected
2022-09-19 14:33:09.715 24836-24923/com.nabla.sdk.playground.dev W/RTCModule: sdes.cc: (line 136): CNAME not found for ssrc 570509744
2022-09-19 14:33:09.715 24836-24923/com.nabla.sdk.playground.dev W/RTCModule: sdes.cc: (line 136): CNAME not found for ssrc 570509744
2022-09-19 14:33:09.946 24836-24884/com.nabla.sdk.playground.dev D/PeerConnectionTransport: starting to negotiate
2022-09-19 14:33:09.946 24836-24924/com.nabla.sdk.playground.dev W/RTCModule: media_session.cc: (line 949): RED codec red is missing an associated payload type.
2022-09-19 14:33:11.497 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: stun_port.cc: (line 479): STUN server address is incompatible.
2022-09-19 14:33:11.497 24836-24922/com.nabla.sdk.playground.dev W/RTCModule: stun_port.cc: (line 479): STUN server address is incompatible.
2022-09-19 14:33:12.877 24836-24836/com.nabla.sdk.playground.dev D/RTCEngine: primary ICE disconnected

vincentbrison avatar Sep 19 '22 12:09 vincentbrison

if it has fired Disconnected, it will not resume automatically reconnecting.

davidzhao avatar Sep 19 '22 18:09 davidzhao

if it has fired Disconnected, it will not resume automatically reconnecting.

It does not fire RoomEvent.Disconnected though, as it seems only disconnected at RTCEngine level. From RoomEvent perspective it fires RoomEvent.Reconnecting, then RoomEvent.TrackSubscribed or RoomEvent.TrackPublished but no RoomEvent.Reconnected. It is weird to go from RoomEvent.Reconnecting to RoomEvent.TrackSubscribed without passing by RoomEvent.Reconnected or even RoomEvent.Disconnected.

One solution we have at the moment is to rely on room State which fires all states as expected.

vincentbrison avatar Sep 19 '22 21:09 vincentbrison

I see, thank you for the clarification.

davidzhao avatar Sep 19 '22 21:09 davidzhao

Hey @vincentbrison, would you mind grabbing another set of logs, with LiveKit.loggingLevel = LoggingLevel.VERBOSE? This would help a lot, thanks.

davidliu avatar Sep 20 '22 04:09 davidliu

Here the same sequence using LiveKit.loggingLevel = LoggingLevel.VERBOSE, LiveKit.enableWebRTCLogging = true and logcat filter (RTCModule|SignalClient|SubscriberTransportObserver|RTCEngine|PublisherTransportObserver) log.txt

vincentbrison avatar Sep 20 '22 08:09 vincentbrison

@vincentbrison this should be fixed now in #158.

davidliu avatar Oct 24 '22 16:10 davidliu

Thanks!

vincentbrison avatar Oct 24 '22 16:10 vincentbrison