Client disconnect taking a long time on Android 4

[jaytxng]

On Android 4, I'm able to connect to VoxImplant via Voximplant.getInstance().connect without issues But when we want to disconnect, the app hangs while waiting for a response. It ends up returning a ServerError: Response not successful: Received status code 401. On Android 5.0+, we don't have this issue.

One thing that's different is that we upgrade the security provider for Android 4 similar to this in order for requests to work. Is there a min requirement for TLS support?

[YuliaGrigorieva]

Hello @iamjaytong ,

The issue seems strange, we do not have such an error in the SDK.

Do I understand correctly that you can connect to the Voximplant Cloud without any workaround with secutity provider and you have observed the issue only with the Client.disconnect API?

Could you please provide adb logcat logs with the VOXSDK tag?

Best regards, Yulia Grigorieva

[jaytxng]

Hi @YuliaGrigorieva,

following is the log:

I/VOXSDK  ( 7348): Client [DISCONNECTED] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Client [DISCONNECTED] connect: connectivity check: false
I/VOXSDK  ( 7348): Authenticator [REQUEST_TO_BALANCER]
I/VOXSDK  ( 7348): Authenticator [REQUEST_TO_BALANCER] onResponse
I/VOXSDK  ( 7348): Authenticator [REQUEST_TO_BALANCER] onResponse: response code is successful
I/VOXSDK  ( 7348): Authenticator [WEB_SOCKET_CONNECTING] version: android-2.14.1_react-1.13.0
I/VOXSDK  ( 7348): Signaling: created web socket: okhttp3.internal.ws.RealWebSocket@434bbbf8, for: web-gw-ca-01-166.voximplant.com
I/VOXSDK  ( 7348): Signaling: created web socket: okhttp3.internal.ws.RealWebSocket@43516ae0, for: web-gw-pl-01-137.voximplant.com
I/VOXSDK  ( 7348): Signaling: created web socket: okhttp3.internal.ws.RealWebSocket@43a12b10, for: web-gw-us-03-196.voximplant.com
I/VOXSDK  ( 7348): Signaling: created web socket: okhttp3.internal.ws.RealWebSocket@435d4958, for: web-gw-us-02-148.voximplant.com
I/VOXSDK  ( 7348): Signaling: created web socket: okhttp3.internal.ws.RealWebSocket@4294ff88, for: web-gw-us-06-141.voximplant.com
I/VOXSDK  ( 7348): Signaling: onOpen: okhttp3.internal.ws.RealWebSocket@43a12b10
I/VOXSDK  ( 7348): Signaling: onOpen: closing socket okhttp3.internal.ws.RealWebSocket@434bbbf8
I/VOXSDK  ( 7348): Signaling: onOpen: closing socket okhttp3.internal.ws.RealWebSocket@43516ae0
I/VOXSDK  ( 7348): Signaling: onOpen: closing socket okhttp3.internal.ws.RealWebSocket@435d4958
I/VOXSDK  ( 7348): Signaling: onOpen: closing socket okhttp3.internal.ws.RealWebSocket@4294ff88
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__createConnection" , "params" : []}
I/VOXSDK  ( 7348): Signaling: onOpen: okhttp3.internal.ws.RealWebSocket@435d4958
I/VOXSDK  ( 7348): Client [CONNECTED] onConnected
I/VOXSDK  ( 7348): VoxAudioManager: startHeadsetMonitoring
W/VOXSDK  ( 7348): Signaling: onOpen: socket is already opened: okhttp3.internal.ws.RealWebSocket@43a12b10
I/VOXSDK  ( 7348): Invoke onConnectionEstablished
I/VOXSDK  ( 7348): Signaling: onFailure: failed socket: okhttp3.internal.ws.RealWebSocket@435d4958, current socket: okhttp3.internal.ws.RealWebSocket@43a12b10
I/VOXSDK  ( 7348): Signaling: onFailure: failed socket: okhttp3.internal.ws.RealWebSocket@43516ae0, current socket: okhttp3.internal.ws.RealWebSocket@43a12b10
D/VOXSDK  ( 7348): VoxBluetoothManager: start
D/VOXSDK  ( 7348): VoxBluetoothManager: BluetoothAdapter: enabled=false, state=BA_OFF, name=GT-I9060M, address=F4:42:8F:9D:CB:60
D/VOXSDK  ( 7348): VoxBluetoothManager: HEADSET profile state: BA_DISCONNECTED
D/VOXSDK  ( 7348): VoxBluetoothManager: Bluetooth proxy for headset profile has started
D/VOXSDK  ( 7348): VoxBluetoothManager: start done: BT state=HEADSET_UNAVAILABLE
I/VOXSDK  ( 7348): Signaling: onFailure: failed socket: okhttp3.internal.ws.RealWebSocket@4294ff88, current socket: okhttp3.internal.ws.RealWebSocket@43a12b10
I/VOXSDK  ( 7348): Signaling: onFailure: failed socket: okhttp3.internal.ws.RealWebSocket@434bbbf8, current socket: okhttp3.internal.ws.RealWebSocket@43a12b10
I/VOXSDK  ( 7348): Client [CONNECTED] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Client [CONNECTED] login: user = launchpad-376@launchpad.runeai.voximplant.com
I/VOXSDK  ( 7348): Signaling: SEND: login launchpad-376@launchpad.runeai.voximplant.com
I/VOXSDK  ( 7348): Signaling: onMessage: loginSuccessful
I/VOXSDK  ( 7348): MessengerManager: onMessage: client is logged in
I/VOXSDK  ( 7348): Invoke onLoginSuccessful
I/VOXSDK  ( 7348): Signaling: SEND: {"name":"__ping","params":[]}
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__pong" , "params" : []}
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Signaling: SEND: {"name":"__ping","params":[]}
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__pong" , "params" : []}
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Signaling: SEND: {"name":"__ping","params":[]}
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__pong" , "params" : []}
I/VOXSDK  ( 7348): Signaling: SEND: {"name":"__ping","params":[]}
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__pong" , "params" : []}
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Signaling: SEND: {"name":"__ping","params":[]}
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__pong" , "params" : []}
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Signaling: SEND: {"name":"__ping","params":[]}
I/VOXSDK  ( 7348): Signaling: onMessage: {"name" : "__pong" , "params" : []}
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
I/VOXSDK  ( 7348): Client [LOGGED_IN] disconnect
I/VOXSDK  ( 7348): Authenticator [LOGGED_IN] disconnect
E/VOXSDK  ( 7348): Signaling: failed to send message, web socket is disconnected
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
...
E/VOXSDK  ( 7348): Authenticator [LOGGED_IN] Pong timeout, close connection
I/VOXSDK  ( 7348): Authenticator [LOGGED_IN] onWSClose: reason: null
I/VOXSDK  ( 7348): Client [DISCONNECTED] onDisconnected
I/VOXSDK  ( 7348): CallManager: endAllCalls: no calls
I/VOXSDK  ( 7348): VoxAudioManager: stopHeadsetMonitoring
I/VOXSDK  ( 7348): Invoke onConnectionClosed
D/VOXSDK  ( 7348): VoxAudioManager: stop
E/VOXSDK  ( 7348): VoxAudioManager: Trying to stop AudioManager in incorrect state: PREINITIALIZED
D/VOXSDK  ( 7348): VoxBluetoothManager: stop: BT state=HEADSET_UNAVAILABLE
D/VOXSDK  ( 7348): VoxBluetoothManager: stopScoAudio: skip due to invalid state HEADSET_UNAVAILABLE
D/VOXSDK  ( 7348): VoxBluetoothManager: cancelTimer
D/VOXSDK  ( 7348): VoxBluetoothManager: stop done: BT state=UNINITIALIZED

[jaytxng]

After a bit more debugging, it looks like the network error was coming from another API call. When I removed that call for now, the vox disconnection process still takes longer on Android 4 (~14seconds) vs 5+ (<1sec).

log was hanging as well before E/VOXSDK ( 7348): Authenticator [LOGGED_IN] Pong timeout, close connection

[YuliaGrigorieva]

Hello @iamjaytong ,

Thank you for the logs provided.

I/VOXSDK  ( 7348): Client [LOGGED_IN] disconnect

This log points that the Client.disconnect API was called for some reason.

There is a gap in the logs, without timestamps. Was there another connection attempt in ...?

Best regards, Yulia Grigorieva

[jaytxng]

@YuliaGrigorieva The ... is just to show where the app was waiting for a long time before the rest of voxsdk logs come through. No other voxsdk logs are in there and no connection attempt was made.

I/VOXSDK  ( 7348): Client [LOGGED_IN] disconnect
I/VOXSDK  ( 7348): Authenticator [LOGGED_IN] disconnect

Client disconnect is from our app when a user signs out and calls Client.disconnect, so this is intentional and looks correct to me.

E/VOXSDK  ( 7348): Signaling: failed to send message, web socket is disconnected
I/VOXSDK  ( 7348): Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false

I'm assuming based on the logs earlier that client regularly sends pings and expect pongs to keep the websocket alive. What I'm not sure is why does it try to send another message after disconnect which failed immediately?

Also forgot to mention in original issue description that we're using "react-native-voximplant": "1.13.0"

[jaytxng]

for comparison, same codebase on an Android 7 and this is the log:

08-14 12:31:10.286 27632 27736 I VOXSDK  : Client [LOGGED_IN] getClientState: connectWasCalled: false, loginWasCalled: false
08-14 12:31:10.290 27632 27736 I VOXSDK  : Client [LOGGED_IN] disconnect
08-14 12:31:10.290 27632 27778 I VOXSDK  : Authenticator [LOGGED_IN] disconnect
08-14 12:31:10.293 27632 27731 E VOXSDK  : Signaling: onFailure: web socket (okhttp3.internal.ws.RealWebSocket@bb9af94) failure reason = Socket closed
08-14 12:31:10.294 27632 27778 I VOXSDK  : Authenticator [LOGGED_IN] onWSClose: reason: Socket closed
08-14 12:31:10.294 27632 27778 I VOXSDK  : Client [DISCONNECTED] onDisconnected
08-14 12:31:10.294 27632 27778 I VOXSDK  : CallManager: endAllCalls: no calls
08-14 12:31:10.295 27632 27775 I VOXSDK  : Invoke onConnectionClosed
08-14 12:31:10.295 27632 27778 I VOXSDK  : VoxAudioManager: stopHeadsetMonitoring
08-14 12:31:10.296 27632 27632 D VOXSDK  : VoxAudioManager: stop
08-14 12:31:10.296 27632 27632 E VOXSDK  : VoxAudioManager: Trying to stop AudioManager in incorrect state: PREINITIALIZED
08-14 12:31:10.301 27632 27632 D VOXSDK  : VoxBluetoothManager: stop: BT state=HEADSET_UNAVAILABLE
08-14 12:31:10.301 27632 27632 D VOXSDK  : VoxBluetoothManager: stopScoAudio: skip due to invalid state HEADSET_UNAVAILABLE
08-14 12:31:10.302 27632 27632 D VOXSDK  : VoxBluetoothManager: cancelTimer
08-14 12:31:10.304 27632 27632 D VOXSDK  : VoxBluetoothManager: stop done: BT state=UNINITIALIZED

the difference looks like authenticator here knows socket is closed. in the original case authenticator looks like it's expecting pong, times out, and gave a null reason.

[YuliaGrigorieva]

@iamjaytong ,

Thank you for adding logs for android 7, it is really helpful, I see the difference now.

Can you please let me know the exact version of android 4 (api level), so I can try to reproduce it myself?

Best regards, Yulia Grigorieva

[jaytxng]

@YuliaGrigorieva Yeah the device is using Android 4.4.4 (API level 19)

[YuliaGrigorieva]

Hello @iamjaytong ,

Unfortunately, I was not able to reproduce the issue myself. However, I have analyzed the code based on the logs provided. It seems that the issue is in okhttp library that we have as a dependency. The SDK does not receive the event about the web socket close that lead to this issue.

We can fix this issue, but you will need to upgrade the Voximplant React Native SDK to a new version. The release is planned for August 21-24.

Best regards, Yulia Grigorieva

[jaytxng]

@YuliaGrigorieva thanks for your help investigating this, will look forward to the new SDK release and try it out to see if that fixes the issue.

[YuliaGrigorieva]

Hello @iamjaytong ,

We have just released Voximplant React Native SDK 1.22.0.

Please update the SDK in your project and let me know if the issue is resolved.

Best regards, Yulia Grigorieva

[jaytxng]

@YuliaGrigorieva thanks for letting me know! I'll give that a try and reopen if I run into any issues.

[anniewey]

@YuliaGrigorieva is there any logout function without disconnecting the client? in order to login to other credentials

[YuliaGrigorieva]

@anniewey

No. You need to call Client.disconnect and connect again to log in another user.

Best regards, Yulia Grigorieva