Audio delay of 2s for incoming calls - "Answer() before Dial()" fixed it!?

terraformer · September 16, 2020, 10:23pm

Hi, I’m running a fresh Asterisk 16.13.0 install. The Asterisk server is behind double NAT in a local LAN. The phones are in the same LAN. I’ve multiple sip accounts and sip providers.
Problem: If I receive a call on one of my sip accounts, the audio from the external caller to the local phone is delayed by about 2s. Audio from local phone to external caller is not delayed!

I thought this is a firewall/NAT problem but looks like I was wrong. Adding an Answer() before Dial() the local phone fixes the problem.

; extension with 2s delay for incoming pstn-call
[sipprovider-in]
exten = _X.,1,NoOp(Provider 1)
same = n,Dial(PJSIP/201,20)
same = n,Hangup()

Here is the log for the delayed example:

– Executing [xxxxxxxxxx@sipprovider-in:2] Dial(“PJSIP/sipprovider-0000003a”, “PJSIP/201,20”) in new stack
– Called PJSIP/201
– PJSIP/201-0000003b is ringing
– PJSIP/201-0000003b is ringing
0x7fee8001b7f0 – Strict RTP learning after remote address set to: 192.168.1.14:12528
– PJSIP/201-0000003b answered PJSIP/sipprovider-0000003a
0x7fee80093680 – Strict RTP learning after remote address set to: 62.xxx.xxx.xxx:17810

As you can see, the second strict RTP happens after the answered-line. This seems to cause the 2s delay in the audio stream from external caller to local phone.

Accidentally, I found a simple solution.

; extension without 2s delay for incoming pstn-call
[sipprovider-in]
exten = _X.,1,NoOp(Provider 1)
same = n,Answer()
same = n,Dial(PJSIP/201,20)
same = n,Hangup()

Here is the log for the non-delayed example:

– Executing [xxxxxxxxxx@sipprovider-in:3] Dial(“PJSIP/sipprovider-00000038”, “PJSIP/201,20”) in new stack
– Called PJSIP/201
– PJSIP/201-00000039 is ringing
– PJSIP/201-00000039 is ringing
0x7fee8006dec0 – Strict RTP switching to RTP target address 62.xxx.xxx.xxx:17832 as source
0x7fee8008a7d0 – Strict RTP learning after remote address set to: 192.168.1.14:12526
– PJSIP/201-00000039 answered PJSIP/sipprovider-00000038

Both strict RTP happen before the answered-line and magically there is no delay.

Question: Any idea why this happens and what a cleaner solution might be?

Thanks in advance.

markosjal · September 17, 2020, 12:30am

I use SIP not PJSIP, and have noticed the same. I have multiple incoming providers, so it is definately on the asterisk end. Also Calling to the Echo Test for example I experience the same delay so the call is ansered to hear “…about to enter an echo test” and the “You are” is never heard. I had to set an intentional 2 second delay to an IVR menu on one inbound route too.

Answering the call is not a good solution and is only valid for inbounds. I was wondering if forcing the bridge type might make the connection happen faster, but do not know how to do this.

terraformer · September 17, 2020, 6:26am

Interestingly, the echo test does not send any audio unless I answer the external call explicitly. Internal calls on the other hand can use the echo test without Answer() before Echo().

Interesting idea to force the bridge somehow. I’ll have a look. If I find a solution, I’ll post back. I consider answering every call to my sip accounts as not ideal, too.
Best

david551 · September 17, 2020, 9:26am

That’s not surprising. Providers don’t like giving away free services and charging only normally starts when the call is answered. Consequently, it would be very surprising for early media to work when going through a provider.

terraformer · September 17, 2020, 9:49am

That sounds reasonable @david551

markosjal · September 21, 2020, 6:49am

I just reproduced this delay with two different hardware phones

Please see the code below and comments inline

;Calling 600 echo test fro Polycom 335
;(Immediate connection, normal)

  == Using SIP RTP CoS mark 5
       > 0x73c1d368 -- Strict RTP learning after remote address set to: 192.168.0.53:2226
    -- Executing [600@from-internal:1] Playback("SIP/5900-00000011", "demo-echotest") in new stack
       > 0x73c1d368 -- Strict RTP switching to RTP target address 192.168.0.53:2226 as source
    -- <SIP/5900-00000011> Playing 'demo-echotest.g722' (language 'en')
       > 0x73c1d368 -- Strict RTP learning complete - Locking on source address 192.168.0.53:2226
____________________________________________________________________
;Calling 600 echo test from RCA IP160 
;(note that playbeck begins then after playback we see "Strict RTP Switching..."

  == Using SIP RTP CoS mark 5
       > 0x73c27258 -- Strict RTP learning after remote address set to: 192.168.0.52:18010
    -- Executing [600@from-internal:1] Playback("SIP/501-00000012", "demo-echotest") in new stack
    -- <SIP/501-00000012> Playing 'demo-echotest.g722' (language 'en')
       > 0x73c27258 -- Strict RTP switching to RTP target address 192.168.0.52:18010 as source
       > 0x73c27258 -- Strict RTP learning complete - Locking on source address 192.168.0.52:18010

You can see the difference in the order. This problem is not unique to the RCA phones as I have seen it too on Grandstream Wave Softphone and other hard phones

terraformer · September 21, 2020, 7:40am

@markosjal, thank you for sharing. This is pretty interesting.
Do I assume correctly that the Polycom 335 (SIP/59000) has the same endpoint settings like the RCA IP160 (SIP/501)?
Moreover, I doubt this is coincidentally but reproducible, hence, phone-implementation specific?
If we can trace the difference between your two examples, maybe we can find the reason for this behavior. What do you think?
Thanks & best

david551 · September 21, 2020, 9:36am

I think we need to have detailed RTP level timing to be able to work out what is really happening here.

This might be the result of particular phones reacting badly to the way in in which Asterisk indicates media source changes. so I think we also need most of the RTP meta data.

markosjal · September 21, 2020, 7:36pm

I am going to work with conforming all settings between the two phones and see what happens. It will be a couple of days before I can do it and post here.

Ok, I confrmed the settings as follows

[5900]
dtmfmode=rfc2833
secret=Password
type=friend
regexten=5900                   
callerid="Polycom" <5900>
host=dynamic                    
directmedia=nonat
disallow=all
allow=g722
allow=ulaw
allow=alaw
context=from-internal
qualify=no

[501]; 1.Desk
dtmfmode=rfc2833
secret=Password
type=friend
regexten=501            
callerid="1.Desk" <501>
host=dynamic                    
directmedia=nonat                  
disallow=all                       
allow=g722
allow=ulaw
allow=alaw
context=from-internal
qualify=no

I also went through and conformed the two phone’s settings as much as posible and tried many tweaks to get one to behave like the other with no luck . I could not get a delayed connection on the Polycom , nor could I get the RCA to connect faster.

terraformer · October 7, 2020, 8:22am

Unfortunately, the delay is back even when I Answer() early. I’m not aware of any changes in the dialplan.
Interestingly, when picking up the called phone, I immediately see this on CLI:

[2020-10-07 10:07:58.918] VERBOSE[2355][C-00000035] app_dial.c: PJSIP/201-0000006b answered PJSIP/provider1-0000006a
[2020-10-07 10:07:58.921] VERBOSE[2358][C-00000035] bridge_channel.c: Channel PJSIP/201-0000006b joined 'simple_bridge' basic-bridge <146bc125-73d4-4eba-95d2-71bd411d7f0a>
[2020-10-07 10:07:58.923] VERBOSE[2355][C-00000035] bridge_channel.c: Channel PJSIP/provider1-0000006a joined 'simple_bridge' basic-bridge <146bc125-73d4-4eba-95d2-71bd411d7f0a>
[2020-10-07 10:07:58.923] VERBOSE[2355][C-00000035] bridge.c: Bridge 146bc125-73d4-4eba-95d2-71bd411d7f0a: switching from simple_bridge technology to native_rtp
[2020-10-07 10:07:58.923] VERBOSE[2355][C-00000035] bridge_native_rtp.c: Locally RTP bridged 'PJSIP/provider1-0000006a' and 'PJSIP/201-0000006b' in stack
[2020-10-07 10:07:59.208] VERBOSE[2358][C-00000035] res_rtp_asterisk.c: 0x7ff2d00219b0 -- Strict RTP switching to RTP target address 192.168.1.14:12434 as source
[2020-10-07 10:08:03.928] VERBOSE[2358][C-00000035] res_rtp_asterisk.c: 0x7ff2d00219b0 -- Strict RTP learning complete - Locking on source address 192.168.1.14:12434

But the calling phone gets connected 2 seconds later.

A delay free connection with a different provider looks like that:

[2020-10-07 10:15:18.815] VERBOSE[2419][C-00000037] app_dial.c: PJSIP/201-0000006f answered PJSIP/provider2-0000006e
[2020-10-07 10:15:18.818] VERBOSE[2422][C-00000037] bridge_channel.c: Channel PJSIP/201-0000006f joined 'simple_bridge' basic-bridge <08e52c9b-af16-48a9-b110-a76ca685311c>
[2020-10-07 10:15:18.820] VERBOSE[2419][C-00000037] bridge_channel.c: Channel PJSIP/sipgate_dirk-0000006e joined 'simple_bridge' basic-bridge <08e52c9b-af16-48a9-b110-a76ca685311c>
[2020-10-07 10:15:18.820] VERBOSE[2419][C-00000037] bridge.c: Bridge 08e52c9b-af16-48a9-b110-a76ca685311c: switching from simple_bridge technology to native_rtp
[2020-10-07 10:15:18.820] VERBOSE[2419][C-00000037] bridge_native_rtp.c: Remotely bridged 'PJSIP/provider2-0000006e' and 'PJSIP/201-0000006f' - media will flow directly between them
[2020-10-07 10:15:18.850] VERBOSE[1931] res_rtp_asterisk.c: 0x7ff2d4051740 -- Strict RTP learning after remote address set to: 192.168.1.14:12436
[2020-10-07 10:15:19.079] VERBOSE[2422][C-00000037] res_rtp_asterisk.c: 0x7ff2d4051740 -- Strict RTP switching to RTP target address 192.168.1.14:12436 as source

I was wondering why the delayed example shows the “switching RTP target” before “learning” like in the delay free example with provider 2

@david551
What do you mean with “RTP level timing”?
I’d be happy to provide what data might help solving this issue.

Thanks & best

system · November 6, 2020, 8:23am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.