[Home]

Summary:ASTERISK-25039: getting major delays when connecting a call to a webrtc client
Reporter:Christoph Hecht (Christoph Hecht)Labels:
Date Opened:2015-04-30 08:10:30Date Closed:2016-10-26 09:50:41
Priority:MajorRegression?
Status:Closed/CompleteComponents:Addons/res_config_mysql Core/RTP
Versions:13.2.0 Frequency of
Occurrence		Frequent
Related
Issues:
Environment:Ubuntu 14.4.2 LTS, mysql 5.6.19, webrtc using sipml5Attachments:( 0) ast13pcap.pcap
( 1) asterisk.conf
( 2) extensions_basic.conf
( 3) extensions.conf
( 4) log2904_rtp_.txt
( 5) messages.txt
( 6) sip_basic.conf
( 7) sipml_registration.JPG
( 8) sipml_settings.JPG
( 9) trace_3004_rtp_log_short_ring.txt
(10) trace_3004_sip.txt
(11) users.conf.old
Description:Hi,
we have issues using Asterisk 13.2 and webrtc. Browser in use is Chrome 42.

I am working on this a few months now, but can't get rid of some errors that occur since our first attempts. (We also did an upgrade from Asterisk 12 to 13)

When doing inbound calls to a queue we have from the moment of taking/accepting the call to actually connecting the call a delay of 5-7 seconds. Until then the connection is not opened.The caller just hears a ringtone or queue_prompts.
This occurs also when calling the webrtc user directly (not using the queue).
Following errors occur according to our logs:

We get these two errors, in case the call is ringing in the webrtc softphone
{noformat}
[Apr 30 14:37:30] ERROR[23511][C-00000003]: netsock2.c:303 ast_sockaddr_resolve: getaddrinfo("df7jal23ls0d.invalid", "(null)", ...): Name or service not known
[Apr 30 14:37:30] WARNING[23511][C-00000003]: chan_sip.c:16158 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : 'df7jal23ls0d.invalid'
{noformat}
occasionally we also get this error
{noformat}
[Apr 30 14:39:48] ERROR[23532][C-00000004]: netsock2.c:98 ast_sockaddr_stringify_fmt: getnameinfo(): ai_family not supported
{noformat}
but each time we have this delay of 5-7 seconds.


Additionally we have realized that sometimes a call rings just 1 second and get this error in our logs:
{noformat}
[Apr 29 16:12:08] WARNING[1809][C-00000000]: chan_sip.c:24306 handle_response: Remote host can't match request ACK to call '5b767ff2701119437f444c090b123e                                                     f8@192.168.2.4:5060'. Giving up.
{noformat}


Worth mentioning is maybe that we use Static Realtime for user and queue configuration.
In SIPML browser logs we don't find errors or warnings either.

There errors only occur when using Webrtc clients. In case we use hardphones or other softphone clients without encryption we have no problems.

could you have a look at the attached logfiles/traces.

Thanks for any help!

Best Regards
Christoph Hecht
Comments:By: Rusty Newton (rnewton) 2015-04-30 19:18:13.927-0500

In this sort of case it is usually better if you can also provide the exact Asterisk configs and client configuration you are using to reproduce the issue. Then we can take a look at it in real time.

Can you reproduce the issue with the SIPML5 demo client and a simple Asterisk config?
By: Christoph Hecht (Christoph Hecht) 2015-05-05 08:14:34.584-0500

i have attached now my extensions.conf file and asterisk.conf
what i have to mention is that we use asterisk gui for call switching/routing and static realtime to define users and queues.

i have to cut down our configuration and will make some tests with basic config.
By: Christoph Hecht (Christoph Hecht) 2015-05-05 08:23:44.745-0500

when we didn't use static realtime with mysql we used the attached version of users.conf
There we had the same issues as described.
By: Christoph Hecht (Christoph Hecht) 2015-05-05 09:24:20.359-0500

i changed our settings now to a very basic version of extensions.conf and sip.conf. I can say that we have the same behaviour here. it takes 5-7 seconds that the call is establed and we are getting the mentioned errors like before. i attached now the basic .conf files.

we have now two users ycuser1 (6001) and ycuser2 (6002) and are using basic sipml5 client.
When i do a call from 6002 to 6001, it takes a while (4-5 sec.) until asterisk log writes:


 == Using SIP RTP CoS mark 5
   -- Executing [6001@YC_users:1] Dial("SIP/ycuser2-00000002", "SIP/ycuser1,20") in new stack
 == Using SIP RTP CoS mark 5


in the moment the other client rings we get these messages:


[May  5 16:12:31] ERROR[30040][C-00000001]: netsock2.c:303 ast_sockaddr_resolve: getaddrinfo("df7jal23ls0d.invalid", "(null)", ...): Name or service not known
[May  5 16:12:31] WARNING[30040][C-00000001]: chan_sip.c:16158 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : 'df7jal23ls0d.invalid'
   -- Called SIP/ycuser1
   -- SIP/ycuser1-00000003 is ringing
 == Spawn extension (YC_users, 6001, 1) exited non-zero on 'SIP/ycuser2-00000002'
[May  5 16:12:36] WARNING[30034][C-00000001]: chan_sip.c:24306 handle_response: Remote host can't match request ACK to call '7200d2a27840cc8909b9318271528f71@192.168.2.4:5060'. Giving up.

By: Christoph Hecht (Christoph Hecht) 2015-05-07 04:31:09.136-0500

i added additional comments and attachments
By: Rusty Newton (rnewton) 2015-05-07 18:02:40.970-0500

Thanks. In the future, please remove all the sample comments from your config files. We don't need the sample comments in order to reproduce the issue. It just makes things painful to look at.

Can you describe the networking scenario between Asterisk and the host machines of the SIPML5 clients?

Can you also provide screenshots of the SIPML5 configuration (in the client itself)?
By: Christoph Hecht (Christoph Hecht) 2015-05-08 03:31:04.322-0500

Sorry i see, i will delete the comments in future.

The network scenario looks like this:
we have two subnets in use. subnet 1 is where we use our sipml clients and subnet 2 is where asterisk is running. Asterisk is installed on a virtual ubuntu 14.4 machine.
between both nets there is no restriction concerning communication from or to asterisk.

screenshots of sipml config and registration details are added.

if you need addtional info concerning the network scenario please let me know.
By: Christoph Hecht (Christoph Hecht) 2015-05-12 02:43:12.812-0500

we also tested a fresh installation now on a local virtual machine again with basic configuration and it came again to the stated issues.
By: Marek Suscak (mareksuscak) 2015-05-14 06:57:11.006-0500

i have tested webrtc setup with Asterisk 11.17.1, 12.8.2 and 13.3.2 and with all versions I've experienced the same issue - 5 to 10 seconds delay when making a call from webrtc phone (in-browser) to phonerlite (connected as legacy SIP client)

we've used SIPml 1.5.222 (the latest version to date) as a webrtc client, tried to also use jssip but i keep getting "incompatible sdp" error message when making a call from the jssip client to phonerlite, the other way around it works incredibly fast though

then i found the following:
https://code.google.com/p/sipml5/issues/detail?id=137
https://groups.google.com/forum/#!topic/doubango/vlrnZUjMZmw

it seems that the problem is somewhere in sipml and not in asterisk
By: Marek Suscak (mareksuscak) 2015-05-19 09:46:26.844-0500

well i have tested it with simple [SIP.js|http://sipjs.com] demo app with the same result (5 to 10 seconds delay for webrtc to legacy sip client scenario and no delay the other way around)
SIP.js provides pretty good insights on what's actually happening and it seems that it is stuck on gathering ICE candidates step or something that happens afterwards because a few candidates are gathered very quickly, then it stops for a while and then it continues without finding any new candidates, here's the log with my comments:

{code}
Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | configuration parameters after validation:
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · viaHost: "12fgll84bqeb.invalid"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · uri: sip:6001@192.168.56.101
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · wsServers: [{"ws_uri":"ws://192.168.56.101:8088/ws","sip_uri":"<sip:192.168.56.101:8088;transport=ws;lr>","weight":0,"status":0,"scheme":"WS"}]
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · password: NOT SHOWN
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · registerExpires: 600
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · register: true
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · registrarServer: sip:192.168.56.101
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · wsServerMaxReconnection: 3
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · wsServerReconnectionTimeout: 4
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · connectionRecoveryMinInterval: 2
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · connectionRecoveryMaxInterval: 30
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · usePreloadedRoute: false
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · userAgentString: "SIP.js/0.7.0"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · iceCheckingTimeout: 5000
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · noAnswerTimeout: 60000
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · stunServers: ["stun:stun.l.google.com:19302"]
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · turnServers: []
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · traceSip: false
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · hackViaTcp: false
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · hackIpInContact: false
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · hackWssInTransport: false
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · autostart: true
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · rel100: "none"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · replaces: "none"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · mediaHandlerFactory: function (a,c){return new b(a,c)}
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · authenticationFactory: undefined
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · authorizationUser: "6001"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · displayName: "6001"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · instanceId: "fc27e87d-3afb-495b-be55-cc1f01ae04b4"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · sipjsId: "1kje2"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · hostportParams: "192.168.56.101"
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | · media: undefined
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | user requested startup...
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.transport | connecting to WebSocket ws://192.168.56.101:8088/ws
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.transport | WebSocket ws://192.168.56.101:8088/ws connected
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.ua | connection state set to 0
sip.min.js:36 Tue May 19 2015 16:43:30 GMT+0200 (W. Europe Daylight Time) | sip.transaction.nist | Timer J expired for non-INVITE server transaction z9hG4bK1c353ffa
sip.min.js:36 Tue May 19 2015 16:43:42 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | acquiring local media // HERE I WAS ASKED TO CONFIRM THE USAGE OF A MIC
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | acquired local media streams
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:2593301058 1 udp 2122260223 192.168.5.17 49623 typ host generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:2593301058 2 udp 2122260223 192.168.5.17 49623 typ host generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:2999745851 1 udp 2122194687 192.168.56.1 49624 typ host generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:2999745851 2 udp 2122194687 192.168.56.1 49624 typ host generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:3557908146 1 tcp 1518280447 192.168.5.17 0 typ host tcptype active generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:3557908146 2 tcp 1518280447 192.168.5.17 0 typ host tcptype active generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:4233069003 1 tcp 1518214911 192.168.56.1 0 typ host tcptype active generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:4233069003 2 tcp 1518214911 192.168.56.1 0 typ host tcptype active generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:1820515222 1 udp 1686052607 195.12.152.90 49623 typ srflx raddr 192.168.5.17 rport 49623 generation 0
sip.min.js:36 Tue May 19 2015 16:43:48 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | ICE candidate received: candidate:1820515222 2 udp 1686052607 195.12.152.90 49623 typ srflx raddr 192.168.5.17 rport 49623 generation 0 // HERE IT WAS STUCK FOR 5 TO 10 SECONDS AND THEN IT CONTINUED WITH THE NEXT LINE
sip.min.js:36 Tue May 19 2015 16:43:57 GMT+0200 (W. Europe Daylight Time) | sip.transaction.ict | Timer D expired for INVITE client transaction z9hG4bK587962
sip.min.js:36 Tue May 19 2015 16:43:57 GMT+0200 (W. Europe Daylight Time) | sip.dialog | new UAC dialog created with status EARLY
sip.min.js:36 Tue May 19 2015 16:44:01 GMT+0200 (W. Europe Daylight Time) | sip.dialog | dialog 1kje2mglhmru909id5gul9l16vcplaas08b32e14  changed to CONFIRMED state
sip.min.js:36 Tue May 19 2015 16:44:01 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | stream added: default
sip.min.js:36 Tue May 19 2015 16:44:06 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | RTCIceChecking Timeout Triggered after 5000 micro seconds
sip.min.js:36 Tue May 19 2015 16:44:06 GMT+0200 (W. Europe Daylight Time) | sip.inviteclientcontext | closing INVITE session 1kje2mglhmru909id5guuv9ejjqa8s
sip.min.js:36 Tue May 19 2015 16:44:06 GMT+0200 (W. Europe Daylight Time) | sip.invitecontext.mediahandler | closing PeerConnection
sip.min.js:36 Tue May 19 2015 16:44:06 GMT+0200 (W. Europe Daylight Time) | sip.dialog | dialog 1kje2mglhmru909id5gul9l16vcplaas08b32e14 deleted
sip.min.js:36 Tue May 19 2015 16:44:06 GMT+0200 (W. Europe Daylight Time) | sip.transaction.nist | Timer J expired for non-INVITE server transaction z9hG4bK2a73d653
{code}
By: Rusty Newton (rnewton) 2015-06-25 08:30:58.260-0500

I'm curious if the patch here https://gerrit.asterisk.org/#/c/679/ may affect the issue. Please try with this patch and report back.
By: Christoph Hecht (Christoph Hecht) 2015-07-07 04:50:27.201-0500

I made tests now with this patch but unfortuantely i get all the same errors and the same behaviour as before.

So again i get these errors when the call is allocated to the webrtc user

[Jul  7 10:32:09] ERROR[11510][C-00000000]: netsock2.c:303 ast_sockaddr_resolve: getaddrinfo("df7jal23ls0d.invalid", "(null)", ...): Name or service not known
[Jul  7 10:32:09] WARNING[11510][C-00000000]: chan_sip.c:16158 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : 'df7jal23ls0d.invalid'

is there anything i have to do additionally to patching chan_sip.c  and restart asterisk ?

thank you
Best Regards
Christoph Hecht
By: Christoph Hecht (Christoph Hecht) 2015-07-07 04:52:50.613-0500

Again we have this delay of 5-7 seconds till the call is connected on both sides.
By: Rusty Newton (rnewton) 2015-07-08 08:22:47.155-0500

{quote}
is there anything i have to do additionally to patching chan_sip.c and restart asterisk ?
{quote}

After patching, you must rebuild and reinstall Asterisk.
By: Christoph Hecht (Christoph Hecht) 2015-07-15 03:40:51.307-0500

Hi,
i rebuilt and reinstalled Asterisk now with the patched file.
But i get all the same errors and the same behaviour again.

This 5-7 seconds delay till the call is connected still occurs.

[Jul 14 11:58:22] ERROR[22965][C-0000000e]: netsock2.c:303 ast_sockaddr_resolve: getaddrinfo("df7jal23ls0d.invalid", "(null)", ...): Name or service not known
[Jul 14 11:58:22] WARNING[22965][C-0000000e]: chan_sip.c:16158 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : 'df7jal23ls0d.invalid'

the same thing happens after core reloads and internal calls.


Best Regards
Christoph Hecht

By: Rusty Newton (rnewton) 2015-08-12 17:16:10.344-0500

When calling from SIPML5 (latest live demo) to a remote Asterisk server behind NAT/firewall I get the same delay, an approximate 5 to 6 second delay.

The delay occurs before any SIP traffic hits Asterisk at all, so it appears this delay is happening outside of Asterisk.

Calling from Asterisk to the SIPML5 client occurs pretty much instantly.

Is this the same as the delay that you see?

From your description it sounds like your delay may occur after the call is answered within a queue?

For testing, can have inbound calls come directly to a single phone to see if you still get the delay in that case?

Please observe "sip set debug on" output to see if the delay happens before the INVITE hits your box or not.
By: Asterisk Team (asteriskteam) 2015-08-27 12:00:19.844-0500

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Christoph Hecht (Christoph Hecht) 2015-09-03 04:15:46.300-0500

sorry for my late response:
our delay occurs when calling from PSTN or internal Asterisk to Webrtc Client.
Yes you are right our delay occurs after the call is answered within a queue.

we have tested now incoming calls directly to a user connected with webrtc live demo.

All SIP traffic is comming in and as i mentioned it is ringing, but from the time when we accept the call (take off) to the moment both endpoints hear each other lasts about 5-7 seconds.

here is the trace output
The thing is that we get SIP messages and everything. Otherwise the incoming call from PSTN wouldn't ring in webrtc client anyway.


 == Using SIP RTP CoS mark 5
   -- Executing [6031@DLPN_DialPlan1:1] Dial("SIP/Audiocodes-0000001a", "SIP/6031") in new stack
 == Using SIP RTP CoS mark 5
[Sep  3 10:41:00] ERROR[12760][C-0000000d]: netsock2.c:303 ast_sockaddr_resolve: getaddrinfo("df7jal23ls0d.invalid", "(null)", ...): Name or service not known
[Sep  3 10:41:00] WARNING[12760][C-0000000d]: chan_sip.c:16161 __set_address_from_contact: Invalid host name in Contact: (can't resolve in DNS) : 'df7jal23ls0d.invalid'
   -- Called SIP/6031
   -- SIP/6031-0000001b is ringing
   -- SIP/6031-0000001b answered SIP/Audiocodes-0000001a
   -- Channel SIP/Audiocodes-0000001a joined 'simple_bridge' basic-bridge <5304aa6b-4f4c-4058-a94e-aa0427f3f55f>
   -- Channel SIP/6031-0000001b joined 'simple_bridge' basic-bridge <5304aa6b-4f4c-4058-a94e-aa0427f3f55f>
      > 0x7faf1c02c040 -- Probation passed - setting RTP source address to 192.168.2.71:6230
      > 0x7faf200558a0 -- Probation passed - setting RTP source address to 192.168.1.214:64866
-------
FROM THIS MOMENT ON AUDIO CONNECTION IS ESTABLISHED ON BOTH SIDES
------
   -- Channel SIP/Audiocodes-0000001a left 'simple_bridge' basic-bridge <5304aa6b-4f4c-4058-a94e-aa0427f3f55f>
   -- Channel SIP/6031-0000001b left 'simple_bridge' basic-bridge <5304aa6b-4f4c-4058-a94e-aa0427f3f55f>
 == Spawn extension (DLPN_DialPlan1, 6031, 1) exited non-zero on 'SIP/Audiocodes-0000001a'

By: Asterisk Team (asteriskteam) 2015-09-03 04:15:47.357-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: Rusty Newton (rnewton) 2015-09-03 19:03:54.075-0500

Well, it seems that I'm not able to reproduce your issue then. It is also odd that you do not see the delay that I see. Very odd that we get a very similarly timed delay but at different points in the calling process.

One difference in my reproduce is that I did not go as far as setting up static realtime with MySQL.

Are you able to reproduce the issue on a test system with using straight flat file configuration?
By: Christoph Hecht (Christoph Hecht) 2015-09-04 07:39:11.872-0500

I think i can see the delay you mentioned when calling out from webrtc live demo. I can also see 3-4 seconds delay and there is no sip traffic/invite in these seconds shown in asterisk trace.
But this delay is not such a problem like it is when you call in to webrtc.
The agent answers the phone and wants to speak, but the other side is still hearing "ringtone" or "queue-announcements". Only after 5-7 seconds audio connection is on both sides.

in case you call to webrtc client you get no such delay. Can you hear the other side right after answering the call?

We already made test with basic asterisk configuration. So we just had 2 users configured and were using flat file configuration. The same issues occured.
We tested this in May.

Could "ice candidate gathering" have anything to do with our issue? like Marek said?


By: Joshua C. Colp (jcolp) 2015-09-04 07:42:23.750-0500

Yes. Without trickle ICE all candidates have to be gathered at once, which can take a bit of time as it enumerates all interfaces, does STUN requests, etc.
By: Rusty Newton (rnewton) 2015-09-04 10:00:04.625-0500

In my testing once the call comes into the system there is no further delay. I had the call routed in a variety of scenarios including queue distribution and a direct call. I couldn't reproduce any delay other than the delay seen before the original INVITE ever reached the Asterisk system. On answering audio was always established with no perceived delay. I had audio both directions.
By: Christoph Hecht (Christoph Hecht) 2015-09-07 08:48:07.699-0500

we will do some tests into tickle ICE direction, maybe we can get rid of this delay by using it
By: Joshua C. Colp (jcolp) 2015-09-07 08:51:43.787-0500

res_rtp_asterisk does not support trickle ICE at this time.
By: Christoph Hecht (Christoph Hecht) 2015-09-08 02:24:45.111-0500

so in case its gathering ice candidates, we can't do anything to get rid of the delay?
But my question is why Rusty isn't experiencing this specific delay ..  we use basic configuration and basic webrtc live demo
and it stops when gathering ice candidates...

is trickle ICE supported in a future Asterisk release?
By: Joshua C. Colp (jcolp) 2015-09-08 05:35:54.564-0500

I know of noone currently working on trickle ICE support.

As to why it can be different different machines can have different interfaces, different number of IPs, different STUN servers in use, lots of stuff.
By: Asterisk Team (asteriskteam) 2015-09-22 12:00:19.309-0500

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines
By: Asterisk Team (asteriskteam) 2015-10-07 12:00:19.135-0500

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines