search

twilio / voice-quickstart-android

Quickstart app for the Voice Android SDK
https://www.twilio.com/docs/api/voice-sdk/android/getting-started
MIT License
184 stars 140 forks source link

Incoming call timeout value is not reached #527

Closed Thortoco closed 2 years ago

Thortoco commented 2 years ago

Description

We recently wanted to benefit from the new timeout value of 10 minutes so we can configure the time to answer an incoming call. For value under 3 minutes it's correct and we correctly receive an EXCEPTION_CALL_CANCELLED when our backend stops the call. But for values set between 3 and 10 minutes, we instead receive a EXCEPTION_SERVICE_UNAVAILABLE (com.twilio.voice.CallException: Service Unavailable 31503 SIP/2.0 503 Service Unavailable). In this case the caller is still in ringing mode while the callee has his call ended. We also have a team using the JS SDK and on their side the ringing timeout is working properly.

Steps to Reproduce

  1. Setup a ringing time over 3 minutes on the backend side
  2. Make a call from client A to client B
  3. Client B has his call cancelled before the ringing timeout is reached
  4. Client A is still in call

Expected Behavior

We can be in ringing mode for 10 minutes.

Actual Behavior

We receive a CallException after 3 minutes of ringing mode.

Reproduces How Often

100%

Versions

Voice Android SDK

6.0.7

OS Version

10, 11, 12

Device Model

Pixel 5 (emulator)

kbagchiGWC commented 2 years ago

@Thortoco Looks like you are overwriting the default 10 mins in your step 1.

Setup a ringing time over 3 minutes on the backend side

Can you share a call sid so that we can confirm the behavior you are observing?

Thortoco commented 2 years ago

Hello @kbagchiGWC Yeah here you go CA617d696e03ad8a421d09441e98765baf.

Thortoco commented 2 years ago

Hello @kbagchiGWC yeah my bad in my step 1 it was 10 minutes set on the backend side. Also, in the source code of the SDK I can't find any reference to the 10 minutes?

kbagchiGWC commented 2 years ago

@Thortoco

10 mins is an internal backend change that keeps the push notification alive for a longer duration. Default used to be 30 seconds. This change was done to address push delivery delay that resulted in "no answer". Now, if you increase the "Dial" timeout to a larger duration, callee will get longer window to answer the call.

However the callsid "CA617d696e03ad8a421d09441e98765baf" provided above, failed with an error 31503.

Thortoco commented 2 years ago

@kbagchiGWC Do you think this error is on our backend side and not on Twilio SDK side?

kbagchiGWC commented 2 years ago

I do not have enough information to come to a conclusion. Can you share device logs and few more call sids?

Thortoco commented 2 years ago

Hello @kbagchiGWC

So here are some logs with adb logcat | grep twilio, those logs are linked to this call sid CA671b4c61d8ecb8409bf3f7dbb48eeb75

06-27 17:19:52.479 10065 10065 D Twilio  : [Platform](Thread 0x0xb40000700e584d70): Java_com_twilio_voice_MediaFactory_nativeCreate
06-27 17:19:52.542 10065 11164 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe562fa0): twilio::voice::AsyncDnsResolver::AsyncDnsResolver(std::weak_ptr<DnsResolverObserver>)
06-27 17:19:52.542 10065 11164 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe562fa0): AsyncDnsResolver resolving hostname = chunderm.gll.twilio.com
06-27 17:19:52.573 10065 11164 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe562fa0): virtual void twilio::voice::SipClient::onResolveResult(twilio::voice::AsyncDnsResolver *, std::string, int)
06-27 17:19:52.573 10065 11164 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe562fa0): onResolveResult for listen, hostname = sip:chunderm.gll.twilio.com:443;transport=tls, ip_addr = 35.157.205.11
06-27 17:19:52.625 10065 11170 I Twilio  : [Signaling](475477376176): RESIP::SIP: subjectAltName of TLS session cert contains DNS <chunderm.de1.twilio.com>
06-27 17:19:52.625 10065 11170 I Twilio  : [Signaling](475477376176): RESIP::SIP: subjectAltName of TLS session cert contains DNS <chunderm.gll.twilio.com>
06-27 17:19:52.625 10065 11170 I Twilio  : [Signaling](475477376176): RESIP::SIP: subjectAltName of TLS session cert contains DNS <chunderm-de1.twilio.com>
06-27 17:19:52.625 10065 11170 I Twilio  : [Signaling](475477376176): RESIP::TRANSPORT: Peer names - chunderm.de1.twilio.com, chunderm.gll.twilio.com, chunderm-de1.twilio.com
06-27 17:19:52.625 10065 11170 I Twilio  : [Signaling](475477376176): RESIP::TRANSPORT: TLS handshake done for peer chunderm.de1.twilio.com, chunderm.gll.twilio.com, chunderm-de1.twilio.com
06-27 17:19:52.855 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=86270455_c3356d0b_426ca043-c44b-4e26-b2b0-bbe14ae7eaee
06-27 17:19:52.855 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:19:52.855 10065 11171 D Twilio  : X-Twilio-EdgeHost: chunderm0.de1.twilio.com
06-27 17:19:52.855 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=86270455_c3356d0b_426ca043-c44b-4e26-b2b0-bbe14ae7eaee
06-27 17:19:52.855 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:19:52.855 10065 11171 D Twilio  : X-Twilio-EdgeHost: chunderm0.de1.twilio.com
06-27 17:21:53.039 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=56886111_c3356d0b_8a23318c-4650-44e5-b162-ae8c57878dab
06-27 17:21:53.039 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:21:53.039 10065 11171 D Twilio  : X-Twilio-EdgeHost: chunderm0.de1.twilio.com
06-27 17:21:53.039 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=56886111_c3356d0b_8a23318c-4650-44e5-b162-ae8c57878dab
06-27 17:21:53.039 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:21:53.039 10065 11171 D Twilio  : X-Twilio-EdgeHost: chunderm0.de1.twilio.com
06-27 17:22:52.590 10065 11171 D Twilio  : [Core](475476335792): virtual void twilio::voice::SipCall::onFailure(resip::ClientInviteSessionHandle, const resip::SipMessage &)
06-27 17:22:52.590 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=b13ffc619701a0accccbec30ca2aed88-f07a0000
06-27 17:22:52.590 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:22:52.591 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=b13ffc619701a0accccbec30ca2aed88-f07a0000
06-27 17:22:52.591 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:22:52.591 10065 11171 D Twilio  : [Core](475476335792): virtual void twilio::voice::SipCall::onFailure(resip::ClientInviteSessionHandle, const resip::SipMessage &)
06-27 17:22:52.591 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=b13ffc619701a0accccbec30ca2aed88-f07a0000
06-27 17:22:52.591 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:22:52.591 10065 11171 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=b13ffc619701a0accccbec30ca2aed88-f07a0000
06-27 17:22:52.591 10065 11171 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=a32408c2
06-27 17:22:52.604 10065 10065 D Twilio  : [Platform](Thread 0x0xb40000700e584d70): Java_com_twilio_voice_CallInviteProxy_nativeRelease
06-27 17:22:52.856 10065 11164 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe562fa0): virtual twilio::voice::AsyncDnsResolver::~AsyncDnsResolver()
06-27 17:22:52.858 10065 10065 D Twilio  : [Platform](Thread 0x0xb40000700e584d70): Java_com_twilio_voice_MediaFactory_nativeRelease

If you need more call sids CA2fab5603a5138e9f0bc098afc1152612 and CAa9ec50ce3502db6fe7475f6d731a3354.

I also investigated with my backend team and on their side their logs look good, when the Android client gets disconnected they still see the call in a ringing state.

Thanks

kbagchiGWC commented 2 years ago

@Thortoco

We could not find the call sids you listed in the Voice Insights. Are these the correct call sids for the incoming calls that remained in "ringing" state? 

CA2fab5603a5138e9f0bc098afc1152612
CAa9ec50ce3502db6fe7475f6d731a3354
CA671b4c61d8ecb8409bf3f7dbb48eeb75

The log you shared is partial and is not helping much. Set the log level as the following before collecting the device log.

Voice.setLogLevel(LogLevel.DEBUG);
Voice.setModuleLogLevel(LogModule.SIGNALING, LogLevel.ALL);
Voice.setModuleLogLevel(LogModule.WEBRTC, LogLevel.ALL);
Thortoco commented 2 years ago

@kbagchiGWC Yeah I can find them in the Monitor > logs > Calls of the Twilio console. I just took a screenshot of it as you can see below 😃

Screenshot 2022-06-27 at 18 43 56

Regarding the logs I already have the logs in the codebase set as 

Voice.setLogLevel(LogLevel.DEBUG)
Voice.setModuleLogLevel(LogModule.WEBRTC, LogLevel.ALL)
Voice.setModuleLogLevel(LogModule.PLATFORM, LogLevel.ALL)
Voice.setModuleLogLevel(LogModule.CORE, LogLevel.ALL)
Voice.setModuleLogLevel(LogModule.SIGNALING, LogLevel.ALL)

I relaunched a call (sid CAf1ff1d272ba17d43209b7d36a10e00f3) but the logs look similar to the first log's recording.

06-27 18:14:01.756 14733 14733 D Twilio  : [Platform](489632920824): Java_com_twilio_voice_MediaFactory_nativeCreate
06-27 18:14:01.778 14733 14948 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe542480): twilio::voice::AsyncDnsResolver::AsyncDnsResolver(std::weak_ptr<DnsResolverObserver>)
06-27 18:14:01.778 14733 14948 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe542480): AsyncDnsResolver resolving hostname = chunderm.gll.twilio.com
06-27 18:14:01.797 14733 14948 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe542480): virtual void twilio::voice::SipClient::onResolveResult(twilio::voice::AsyncDnsResolver *, std::string, int)
06-27 18:14:01.797 14733 14948 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe542480): onResolveResult for listen, hostname = sip:chunderm.gll.twilio.com:443;transport=tls, ip_addr = 35.157.179.227
06-27 18:14:01.866 14733 14955 I Twilio  : [Signaling](477491981488): RESIP::SIP: subjectAltName of TLS session cert contains DNS <chunderm.de1.twilio.com>
06-27 18:14:01.866 14733 14955 I Twilio  : [Signaling](477491981488): RESIP::SIP: subjectAltName of TLS session cert contains DNS <chunderm.gll.twilio.com>
06-27 18:14:01.866 14733 14955 I Twilio  : [Signaling](477491981488): RESIP::SIP: subjectAltName of TLS session cert contains DNS <chunderm-de1.twilio.com>
06-27 18:14:01.866 14733 14955 I Twilio  : [Signaling](477491981488): RESIP::TRANSPORT: Peer names - chunderm.de1.twilio.com, chunderm.gll.twilio.com, chunderm-de1.twilio.com
06-27 18:14:01.866 14733 14955 I Twilio  : [Signaling](477491981488): RESIP::TRANSPORT: TLS handshake done for peer chunderm.de1.twilio.com, chunderm.gll.twilio.com, chunderm-de1.twilio.com
06-27 18:14:01.866 14733 14955 I Twilio  : [Signaling](477491981488): RESIP::TRANSPORT: TLS handshake done for peer chunderm.de1.twilio.com, chunderm.gll.twilio.com, chunderm-de1.twilio.com
06-27 18:16:02.233 14733 14956 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=57981138_c3356d0b_02a15efd-39c7-4c71-9e26-a014a10e86a6
06-27 18:16:02.233 14733 14956 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=2dca2512
06-27 18:16:02.233 14733 14956 D Twilio  : X-Twilio-EdgeHost: chunderm1.de1.twilio.com
06-27 18:16:02.234 14733 14956 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=57981138_c3356d0b_02a15efd-39c7-4c71-9e26-a014a10e86a6
06-27 18:16:02.234 14733 14956 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=2dca2512
06-27 18:16:02.234 14733 14956 D Twilio  : X-Twilio-EdgeHost: chunderm1.de1.twilio.com
06-27 18:17:01.852 14733 14956 D Twilio  : [Core](475264048304): virtual void twilio::voice::SipCall::onFailure(resip::ClientInviteSessionHandle, const resip::SipMessage &)
06-27 18:17:01.853 14733 14956 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=63391f8b0f9ba1f128e9699cc089d52b-f07a0000
06-27 18:17:01.853 14733 14956 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=2dca2512
06-27 18:17:01.853 14733 14956 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=63391f8b0f9ba1f128e9699cc089d52b-f07a0000
06-27 18:17:01.853 14733 14956 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=2dca2512
06-27 18:17:01.853 14733 14956 D Twilio  : [Core](475264048304): virtual void twilio::voice::SipCall::onFailure(resip::ClientInviteSessionHandle, const resip::SipMessage &)
06-27 18:17:01.853 14733 14956 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=63391f8b0f9ba1f128e9699cc089d52b-f07a0000
06-27 18:17:01.853 14733 14956 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=2dca2512
06-27 18:17:01.853 14733 14956 D Twilio  : To: <sip:chunderm.gll.twilio.com:443;transport=tls>;tag=63391f8b0f9ba1f128e9699cc089d52b-f07a0000
06-27 18:17:01.853 14733 14956 D Twilio  : From: <sip:VoiceSDK@chunderm.gll.twilio.com>;tag=2dca2512
06-27 18:17:01.857 14733 14733 D Twilio  : [Platform](489632920824): Java_com_twilio_voice_CallInviteProxy_nativeRelease
06-27 18:17:02.085 14733 14948 D Twilio  : [Core](MediaFactoryImpl::signaling 0x0xb400006fbe542480): virtual twilio::voice::AsyncDnsResolver::~AsyncDnsResolver()
06-27 18:17:02.086 14733 14733 D Twilio  : [Platform](489632920824): Java_com_twilio_voice_MediaFactory_nativeRelease

Could I get other infos for you?

Thortoco commented 2 years ago

Hello @kbagchiGWC do you think I should also open a ticket on Twilio console?

kbagchiGWC commented 2 years ago

@Thortoco

The callsids you shared are not client calls. Here is what we see in our backend:

CA2fab5603a5138e9f0bc098afc1152612:

Twilio ID: CA2fab5603a5138e9f0bc098afc1152612
Direction: Carrier to Twilio
Status: completed
Provider: Twilio SIP
Start Time: 2022-06-27 14:20:18 UTC
Date Created: 2022-06-27 14:20:17 UTC
Duration: 218 seconds
From: sip:33xxxxxx35@voxbone.com
To: sip:+3xxxxxxxx609@aircall-staging-voxbone.sip.dublin.twilio.com

CAa9ec50ce3502db6fe7475f6d731a3354:

Twilio ID: CAa9ec50ce3502db6fe7475f6d731a3354
Direction: Carrier to Twilio
Status: completed
Provider: Twilio SIP
Start Time: 2022-06-27 14:24:41 UTC
Date Created: 2022-06-27 14:24:40 UTC
Duration: 195 seconds
From: sip:33xxxxxx35@voxbone.com
To: sip:+3xxxxxxxx609@aircall-staging-voxbone.sip.dublin.twilio.com

CA2fab5603a5138e9f0bc098afc1152612:

Twilio ID: CA671b4c61d8ecb8409bf3f7dbb48eeb75
Direction: Carrier to Twilio
Status: completed
Provider: Twilio SIP
Start Time: 2022-06-27 15:19:53 UTC
Date Created: 2022-06-27 15:19:53 UTC
Duration: 192 seconds
From: sip:33xxxxxx35@voxbone.com
To: sip:+3xxxxxxxx609@aircall-staging-voxbone.sip.dublin.twilio.com

The device log shared above is also partial, it does not include the sip messages to confirm the calls that need debugging. Please open a support ticket at your convenience. That way you can share the full log without any hesitation and one of our SEs will be able to help you.

kbagchiGWC commented 1 year ago

The call timeout issue has been fixed : https://www.twilio.com/docs/voice/sdks/android/3x-changelog#621