[asterisk-bugs] [JIRA] (ASTERISK-25039) getting major delays when connecting a call to a webrtc client
Marek Suscak (JIRA)
noreply at issues.asterisk.org
Tue May 19 09:46:33 CDT 2015
[ https://issues.asterisk.org/jira/browse/ASTERISK-25039?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=226262#comment-226262 ]
Marek Suscak commented on ASTERISK-25039:
-----------------------------------------
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 at 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}
> getting major delays when connecting a call to a webrtc client
> --------------------------------------------------------------
>
> Key: ASTERISK-25039
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-25039
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Addons/res_config_mysql, Core/RTP
> Affects Versions: 13.2.0
> Environment: Ubuntu 14.4.2 LTS, mysql 5.6.19, webrtc using sipml5
> Reporter: Christoph Hecht
> Assignee: Rusty Newton
> Attachments: ast13pcap.pcap, asterisk.conf, extensions_basic.conf, extensions.conf, log2904_rtp .txt, messages.txt, sip_basic.conf, sipml_registration.JPG, sipml_settings.JPG, trace_3004_rtp_log_short_ring.txt, trace_3004_sip.txt, users.conf.old
>
>
> 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
> [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'
> occasionally we also get this error
> [Apr 30 14:39:48] ERROR[23532][C-00000004]: netsock2.c:98 ast_sockaddr_stringify_fmt: getnameinfo(): ai_family not supported
> 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:
> [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 at 192.168.2.4:5060'. Giving up.
> 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
--
This message was sent by Atlassian JIRA
(v6.2#6252)
More information about the asterisk-bugs
mailing list