RTCIceChecking Timeout Triggered after 5000 milliseconds

[habib...@gmail.com]

I am having a strange problem and that only occurs when I make an outbound call. I tried using the SIP.js demo phone. When I dial an external number and the called party answers the call within 5 seconds then the media is established end to end but if the called party answers the call after 5 seconds then media from browser to asterisk is not established and its a one way audio call. Asterisk however plays MOH and DTMF.

Since the browser is running on https (self signed cert) the tcpdump on the server only traces the outside leg. Upon comparison I found no difference in signalling / SDP packets. Same was done at the client end browser. Signalling / SDP etc remains the same (or I wasn't able to find out) but SIP.js prints a log the says the following

------- in case of 1 way audio -------------
sip.js:36 Thu Aug 31 2017 19:02:11 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | stream added: default
sip.js:36 Thu Aug 31 2017 19:02:16 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | RTCIceChecking Timeout Triggered after 5000 milliseconds
sip.js:36 Thu Aug 31 2017 19:02:20 GMT+0500 (Pakistan Standard Time) | sip.transaction.ict | z9hG4bK3649713 | Timer B expired for INVITE client transaction z9hG4bK3649713
sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

------- in case of successful call -------------
sip.js:36 Thu Aug 31 2017 18:43:42 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | stream added: default
sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

I am attaching the browser SIP Logs from the console if anyone can help me out.

no-voice10.11.11.75-1504188160056.txt
10.11.11.75-1504187045459.txt

I tried playing with iceCheckingTimeout but nothing helped. My UA looks like

config : {
password : user.Pass,
displayName : user.Display,
uri : 'sip:'+user.User+'@'+user.Realm,
wsServers : user.WSServer,
// stunServers : [],
// usePreloadedRoute : true,
registerExpires : 600,
traceSip : true,
hackWssInTransport: true,
hackIpInContact: true,
log : {
level : 3,
},
rtcpMuxPolicy: "negotiate",
iceCheckingTimeout: 500 // iceCheckingTimeout: 60000
},

Any other logs required please let me know. I am told that it is an issue with Asterisk. Is it a configuration related issue. I am using Asterisk 11.25.1, would upgrading to Asterisk 14 help?

Thank you
Habib

------------successful call log on chrome Version 60.0.3112.113 ---------
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | acquiring local media
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | acquired local media streams
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | RTCIceGatheringState changed: gathering
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | ICE candidate received: candidate:980327951 1 udp 2122260223 192.168.50.50 63142 typ host generation 0 ufrag 7Szc network-id 1
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | ICE candidate received: candidate:980327951 2 udp 2122260222 192.168.50.50 63143 typ host generation 0 ufrag 7Szc network-id 1
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | ICE candidate received: candidate:3139868859 1 udp 1686052607 103.8.112.210 63142 typ srflx raddr 192.168.50.50 rport 63142 generation 0 ufrag 7Szc network-id 1
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | ICE candidate received: candidate:3139868859 2 udp 1686052606 103.8.112.210 63143 typ srflx raddr 192.168.50.50 rport 63143 generation 0 ufrag 7Szc network-id 1
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | ICE candidate received: candidate:1961714431 1 tcp 1518280447 192.168.50.50 9 typ host tcptype active generation 0 ufrag 7Szc network-id 1
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | ICE candidate received: candidate:1961714431 2 tcp 1518280446 192.168.50.50 9 typ host tcptype active generation 0 ufrag 7Szc network-id 1
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

INVITE sip:03228...@10.11.11.75 SIP/2.0
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK8164330
Max-Forwards: 70
To: <sip:03228...@10.11.11.75>
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
Call-ID: qotki1742sonfr93nuem
CSeq: 2628 INVITE
Contact: <sip:pd17...@192.0.2.184;transport=wss;ob>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Type: application/sdp
Content-Length: 1933

v=0
o=- 5041579879676527740 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS ipktelutyf0tcSm2UkmfWMqgFwt7ylE8VKM2
m=audio 63142 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 103.8.112.210
a=rtcp:63143 IN IP4 103.8.112.210
a=candidate:980327951 1 udp 2122260223 192.168.50.50 63142 typ host generation 0 network-id 1
a=candidate:980327951 2 udp 2122260222 192.168.50.50 63143 typ host generation 0 network-id 1
a=candidate:3139868859 1 udp 1686052607 103.8.112.210 63142 typ srflx raddr 192.168.50.50 rport 63142 generation 0 network-id 1
a=candidate:3139868859 2 udp 1686052606 103.8.112.210 63143 typ srflx raddr 192.168.50.50 rport 63143 generation 0 network-id 1
a=candidate:1961714431 1 tcp 1518280447 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=candidate:1961714431 2 tcp 1518280446 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=ice-ufrag:7Szc
a=ice-pwd:Vb4P7yRJ0nymxLixamU6dOaY
a=ice-options:trickle
a=fingerprint:sha-256 2E:A1:A6:98:23:78:A7:B9:35:BE:F9:88:9F:DE:B4:6F:E1:BF:28:B4:24:47:E8:E8:7A:62:03:4B:7F:BD:9A:0A
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=sendrecv
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:2451930517 cname:cuIvYT1MLcuN0wp8
a=ssrc:2451930517 msid:ipktelutyf0tcSm2UkmfWMqgFwt7ylE8VKM2 9ca9b92e-07c0-4afa-b943-c4e84d40c7e7
a=ssrc:2451930517 mslabel:ipktelutyf0tcSm2UkmfWMqgFwt7ylE8VKM2
a=ssrc:2451930517 label:9ca9b92e-07c0-4afa-b943-c4e84d40c7e7


sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | RTCIceGatheringState changed: complete
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 401 Unauthorized
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK8164330;received=103.8.112.210;rport=53579
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
To: <sip:03228...@10.11.11.75>;tag=as4607a594
Call-ID: qotki1742sonfr93nuem
CSeq: 2628 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="10.11.11.75", nonce="3cdff266"
Content-Length: 0



sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

ACK sip:03228...@10.11.11.75 SIP/2.0
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK8164330
To: <sip:03228...@10.11.11.75>;tag=as4607a594
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
Call-ID: qotki1742sonfr93nuem
Content-Length: 0
CSeq: 2628 ACK



sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

INVITE sip:03228...@10.11.11.75 SIP/2.0
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK7271512
Max-Forwards: 70
To: <sip:03228...@10.11.11.75>
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
Call-ID: qotki1742sonfr93nuem
CSeq: 2629 INVITE
Authorization: Digest algorithm=MD5, username="habib", realm="10.11.11.75", nonce="3cdff266", uri="sip:03228...@10.11.11.75", response="831ed1c1fbcdc3277b69f1e0271adbbb"
Contact: <sip:pd17...@192.0.2.184;transport=wss;ob>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Type: application/sdp
Content-Length: 1933

v=0
o=- 5041579879676527740 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS ipktelutyf0tcSm2UkmfWMqgFwt7ylE8VKM2
m=audio 63142 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 103.8.112.210
a=rtcp:63143 IN IP4 103.8.112.210
a=candidate:980327951 1 udp 2122260223 192.168.50.50 63142 typ host generation 0 network-id 1
a=candidate:980327951 2 udp 2122260222 192.168.50.50 63143 typ host generation 0 network-id 1
a=candidate:3139868859 1 udp 1686052607 103.8.112.210 63142 typ srflx raddr 192.168.50.50 rport 63142 generation 0 network-id 1
a=candidate:3139868859 2 udp 1686052606 103.8.112.210 63143 typ srflx raddr 192.168.50.50 rport 63143 generation 0 network-id 1
a=candidate:1961714431 1 tcp 1518280447 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=candidate:1961714431 2 tcp 1518280446 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=ice-ufrag:7Szc
a=ice-pwd:Vb4P7yRJ0nymxLixamU6dOaY
a=ice-options:trickle
a=fingerprint:sha-256 2E:A1:A6:98:23:78:A7:B9:35:BE:F9:88:9F:DE:B4:6F:E1:BF:28:B4:24:47:E8:E8:7A:62:03:4B:7F:BD:9A:0A
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=sendrecv
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:2451930517 cname:cuIvYT1MLcuN0wp8
a=ssrc:2451930517 msid:ipktelutyf0tcSm2UkmfWMqgFwt7ylE8VKM2 9ca9b92e-07c0-4afa-b943-c4e84d40c7e7
a=ssrc:2451930517 mslabel:ipktelutyf0tcSm2UkmfWMqgFwt7ylE8VKM2
a=ssrc:2451930517 label:9ca9b92e-07c0-4afa-b943-c4e84d40c7e7


sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.transaction.ict | z9hG4bK8164330 | Timer D expired for INVITE client transaction z9hG4bK8164330
sip.js:36 Thu Aug 31 2017 18:43:33 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 100 Trying
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK7271512;received=103.8.112.210;rport=53579
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
To: <sip:03228...@10.11.11.75>
Call-ID: qotki1742sonfr93nuem
CSeq: 2629 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03228...@10.11.11.75:5060;transport=WS>
Content-Length: 0



sip.js:36 Thu Aug 31 2017 18:43:37 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 183 Session Progress
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK7271512;received=103.8.112.210;rport=53579
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
To: <sip:03228...@10.11.11.75>;tag=as0496b8dd
Call-ID: qotki1742sonfr93nuem
CSeq: 2629 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03228...@10.11.11.75:5060;transport=WS>
Content-Type: application/sdp
Content-Length: 965

v=0
o=root 130089705 130089705 IN IP4 10.11.11.75
s=Asterisk PBX 11.25.1
c=IN IP4 10.11.11.75
t=0 0
m=audio 14268 RTP/SAVPF 8 0 126
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=fmtp:126 0-16
a=ptime:20
a=ice-ufrag:4545ef176f0edd81379e8b7a74c85b8f
a=ice-pwd:682923374e0e36215cc1979307a3d263
a=candidate:Ha0b0b4b 1 UDP 2130706431 10.11.11.75 14268 typ host
a=candidate:Hc0a8000c 1 UDP 2130706431 192.168.0.12 14268 typ host
a=candidate:S67087002 1 UDP 1694498815 103.8.112.2 14268 typ srflx raddr 10.11.11.75 rport 14268
a=candidate:Ha0b0b4b 2 UDP 2130706430 10.11.11.75 14269 typ host
a=candidate:Hc0a8000c 2 UDP 2130706430 192.168.0.12 14269 typ host
a=candidate:S67087002 2 UDP 1694498814 103.8.112.2 14269 typ srflx raddr 10.11.11.75 rport 14269
a=connection:new
a=setup:active
a=fingerprint:SHA-256 79:7F:71:4E:84:3B:4B:0C:AA:3C:F4:38:E4:E1:6C:DC:3D:E8:13:1B:4E:D4:7A:8A:BF:37:D4:C7:78:67:89:72
a=sendrecv


sip.js:36 Thu Aug 31 2017 18:43:37 GMT+0500 (Pakistan Standard Time) | sip.dialog | qotki1742sonfr93nuemh3jue3qja6as0496b8dd | new UAC dialog created with status EARLY
sip.js:36 Thu Aug 31 2017 18:43:42 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 200 OK
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK7271512;received=103.8.112.210;rport=53579
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
To: <sip:03228...@10.11.11.75>;tag=as0496b8dd
Call-ID: qotki1742sonfr93nuem
CSeq: 2629 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03228...@10.11.11.75:5060;transport=WS>
Content-Type: application/sdp
Content-Length: 965

v=0
o=root 130089705 130089705 IN IP4 10.11.11.75
s=Asterisk PBX 11.25.1
c=IN IP4 10.11.11.75
t=0 0
m=audio 14268 RTP/SAVPF 8 0 126
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=fmtp:126 0-16
a=ptime:20
a=ice-ufrag:4545ef176f0edd81379e8b7a74c85b8f
a=ice-pwd:682923374e0e36215cc1979307a3d263
a=candidate:Ha0b0b4b 1 UDP 2130706431 10.11.11.75 14268 typ host
a=candidate:Hc0a8000c 1 UDP 2130706431 192.168.0.12 14268 typ host
a=candidate:S67087002 1 UDP 1694498815 103.8.112.2 14268 typ srflx raddr 10.11.11.75 rport 14268
a=candidate:Ha0b0b4b 2 UDP 2130706430 10.11.11.75 14269 typ host
a=candidate:Hc0a8000c 2 UDP 2130706430 192.168.0.12 14269 typ host
a=candidate:S67087002 2 UDP 1694498814 103.8.112.2 14269 typ srflx raddr 10.11.11.75 rport 14269
a=connection:new
a=setup:active
a=fingerprint:SHA-256 79:7F:71:4E:84:3B:4B:0C:AA:3C:F4:38:E4:E1:6C:DC:3D:E8:13:1B:4E:D4:7A:8A:BF:37:D4:C7:78:67:89:72
a=sendrecv


sip.js:36 Thu Aug 31 2017 18:43:42 GMT+0500 (Pakistan Standard Time) | sip.dialog | qotki1742sonfr93nuemh3jue3qja6as0496b8dd | dialog qotki1742sonfr93nuemh3jue3qja6as0496b8dd changed to CONFIRMED state
sip.js:36 Thu Aug 31 2017 18:43:42 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

ACK sip:03228...@10.11.11.75:5060;transport=ws SIP/2.0
Via: SIP/2.0/WSS 192.0.2.184;branch=z9hG4bK3759645
Max-Forwards: 70
To: <sip:03228...@10.11.11.75>;tag=as0496b8dd
From: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
Call-ID: qotki1742sonfr93nuem
CSeq: 2629 ACK
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Length: 0



sip.js:36 Thu Aug 31 2017 18:43:42 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | stream added: default
sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

BYE sip:pd17...@192.0.2.184;transport=wss;ob SIP/2.0
Via: SIP/2.0/WS 10.11.11.75:5060;branch=z9hG4bK7ea6b80b;rport
Max-Forwards: 70
From: <sip:03228...@10.11.11.75>;tag=as0496b8dd
To: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
Call-ID: qotki1742sonfr93nuem
CSeq: 102 BYE
User-Agent: Asterisk PBX 11.25.1
Proxy-Authorization: Digest username="habib", realm="10.11.11.75", algorithm=MD5, uri="sip:10.11.11.75", nonce="3cdff266", response="b46f5f910a974a5ba568034e087a03b7"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0



sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

SIP/2.0 200 OK
Via: SIP/2.0/WS 10.11.11.75:5060;branch=z9hG4bK7ea6b80b;rport
To: <sip:ha...@10.11.11.75>;tag=h3jue3qja6
From: <sip:03228...@10.11.11.75>;tag=as0496b8dd
Call-ID: qotki1742sonfr93nuem
CSeq: 102 BYE
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Length: 0



sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.inviteclientcontext | closing INVITE session qotki1742sonfr93nuem74m4k726sf
sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | closing PeerConnection
sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.dialog | qotki1742sonfr93nuemh3jue3qja6as0496b8dd | dialog qotki1742sonfr93nuemh3jue3qja6as0496b8dd deleted
sip.js:36 Thu Aug 31 2017 18:43:45 GMT+0500 (Pakistan Standard Time) | sip.transaction.nist | z9hG4bK7ea6b80b | Timer J expired for non-INVITE server transaction z9hG4bK7ea6b80b
sip.js:36 Thu Aug 31 2017 18:43:47 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | qotki1742sonfr93nuem74m4k726sf | RTCIceChecking Timeout Triggered after 5000 milliseconds
sip.js:36 Thu Aug 31 2017 18:44:05 GMT+0500 (Pakistan Standard Time) | sip.transaction.ict | z9hG4bK7271512 | Timer B expired for INVITE client transaction z9hG4bK7271512
----------------------------------------------------------------
----------------------------------------------------------------
----------------------------------------------------------------
----- on way audio call log on chrome Version 60.0.3112.113 ------------
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | acquiring local media
app.js:127 f {RTCConstraints: {…}, inviteWithoutSdp: false, anonymous: false, renderbody: null, rendertype: "text/plain", …}
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | acquired local media streams
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | RTCIceGatheringState changed: gathering
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | ICE candidate received: candidate:980327951 1 udp 2122260223 192.168.50.50 54070 typ host generation 0 ufrag LLOq network-id 1
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | ICE candidate received: candidate:980327951 2 udp 2122260222 192.168.50.50 54071 typ host generation 0 ufrag LLOq network-id 1
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | ICE candidate received: candidate:3139868859 2 udp 1686052606 103.8.112.210 54071 typ srflx raddr 192.168.50.50 rport 54071 generation 0 ufrag LLOq network-id 1
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | ICE candidate received: candidate:3139868859 1 udp 1686052607 103.8.112.210 54070 typ srflx raddr 192.168.50.50 rport 54070 generation 0 ufrag LLOq network-id 1
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | ICE candidate received: candidate:1961714431 1 tcp 1518280447 192.168.50.50 9 typ host tcptype active generation 0 ufrag LLOq network-id 1
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | ICE candidate received: candidate:1961714431 2 tcp 1518280446 192.168.50.50 9 typ host tcptype active generation 0 ufrag LLOq network-id 1
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

INVITE sip:03218...@10.11.11.75 SIP/2.0
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK7235570
Max-Forwards: 70
To: <sip:03218...@10.11.11.75>
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 203 INVITE
Contact: <sip:rhv1...@192.0.2.131;transport=wss;ob>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Type: application/sdp
Content-Length: 1933

v=0
o=- 1572314673216529399 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS OVfZoqIF1fukCI0309kh1z5EEhOqB06oJvoI
m=audio 54070 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 103.8.112.210
a=rtcp:54071 IN IP4 103.8.112.210
a=candidate:980327951 1 udp 2122260223 192.168.50.50 54070 typ host generation 0 network-id 1
a=candidate:980327951 2 udp 2122260222 192.168.50.50 54071 typ host generation 0 network-id 1
a=candidate:3139868859 2 udp 1686052606 103.8.112.210 54071 typ srflx raddr 192.168.50.50 rport 54071 generation 0 network-id 1
a=candidate:3139868859 1 udp 1686052607 103.8.112.210 54070 typ srflx raddr 192.168.50.50 rport 54070 generation 0 network-id 1
a=candidate:1961714431 1 tcp 1518280447 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=candidate:1961714431 2 tcp 1518280446 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=ice-ufrag:LLOq
a=ice-pwd:vnSvoYSdFVYDP+hfqe3MIqsC
a=ice-options:trickle
a=fingerprint:sha-256 0C:18:EC:C2:FF:2E:E9:7C:97:F4:B9:D0:4B:47:71:AE:BD:30:0F:3B:55:9E:A5:35:A7:55:0F:A9:87:9E:C7:7C
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=sendrecv
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:2982177588 cname:f/d5EPfrdoxqMpck
a=ssrc:2982177588 msid:OVfZoqIF1fukCI0309kh1z5EEhOqB06oJvoI 3422b7a3-55c9-42fd-bd13-c01bcf17f66d
a=ssrc:2982177588 mslabel:OVfZoqIF1fukCI0309kh1z5EEhOqB06oJvoI
a=ssrc:2982177588 label:3422b7a3-55c9-42fd-bd13-c01bcf17f66d


sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | RTCIceGatheringState changed: complete
sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 401 Unauthorized
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK7235570;received=103.8.112.210;rport=56998
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
To: <sip:03218...@10.11.11.75>;tag=as77603073
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 203 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm="10.11.11.75", nonce="22c0f222"
Content-Length: 0



sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

ACK sip:03218...@10.11.11.75 SIP/2.0
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK7235570
To: <sip:03218...@10.11.11.75>;tag=as77603073
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
Call-ID: 5ht89pfuco7uopuuvnfv
Content-Length: 0
CSeq: 203 ACK



sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

INVITE sip:03218...@10.11.11.75 SIP/2.0
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK3649713
Max-Forwards: 70
To: <sip:03218...@10.11.11.75>
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 204 INVITE
Authorization: Digest algorithm=MD5, username="habib", realm="10.11.11.75", nonce="22c0f222", uri="sip:03218...@10.11.11.75", response="c59bdc808517a9c1ce1107844a5f57d2"
Contact: <sip:rhv1...@192.0.2.131;transport=wss;ob>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Type: application/sdp
Content-Length: 1933

v=0
o=- 1572314673216529399 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio
a=msid-semantic: WMS OVfZoqIF1fukCI0309kh1z5EEhOqB06oJvoI
m=audio 54070 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 103.8.112.210
a=rtcp:54071 IN IP4 103.8.112.210
a=candidate:980327951 1 udp 2122260223 192.168.50.50 54070 typ host generation 0 network-id 1
a=candidate:980327951 2 udp 2122260222 192.168.50.50 54071 typ host generation 0 network-id 1
a=candidate:3139868859 2 udp 1686052606 103.8.112.210 54071 typ srflx raddr 192.168.50.50 rport 54071 generation 0 network-id 1
a=candidate:3139868859 1 udp 1686052607 103.8.112.210 54070 typ srflx raddr 192.168.50.50 rport 54070 generation 0 network-id 1
a=candidate:1961714431 1 tcp 1518280447 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=candidate:1961714431 2 tcp 1518280446 192.168.50.50 9 typ host tcptype active generation 0 network-id 1
a=ice-ufrag:LLOq
a=ice-pwd:vnSvoYSdFVYDP+hfqe3MIqsC
a=ice-options:trickle
a=fingerprint:sha-256 0C:18:EC:C2:FF:2E:E9:7C:97:F4:B9:D0:4B:47:71:AE:BD:30:0F:3B:55:9E:A5:35:A7:55:0F:A9:87:9E:C7:7C
a=setup:actpass
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=sendrecv
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:2982177588 cname:f/d5EPfrdoxqMpck
a=ssrc:2982177588 msid:OVfZoqIF1fukCI0309kh1z5EEhOqB06oJvoI 3422b7a3-55c9-42fd-bd13-c01bcf17f66d
a=ssrc:2982177588 mslabel:OVfZoqIF1fukCI0309kh1z5EEhOqB06oJvoI
a=ssrc:2982177588 label:3422b7a3-55c9-42fd-bd13-c01bcf17f66d


sip.js:36 Thu Aug 31 2017 19:01:48 GMT+0500 (Pakistan Standard Time) | sip.transaction.ict | z9hG4bK7235570 | Timer D expired for INVITE client transaction z9hG4bK7235570
sip.js:36 Thu Aug 31 2017 19:01:49 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 100 Trying
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK3649713;received=103.8.112.210;rport=56998
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
To: <sip:03218...@10.11.11.75>
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 204 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03218...@10.11.11.75:5060;transport=WS>
Content-Length: 0



sip.js:36 Thu Aug 31 2017 19:01:53 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 180 Ringing
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK3649713;received=103.8.112.210;rport=56998
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
To: <sip:03218...@10.11.11.75>;tag=as3342e29e
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 204 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03218...@10.11.11.75:5060;transport=WS>
Content-Length: 0



sip.js:36 Thu Aug 31 2017 19:01:53 GMT+0500 (Pakistan Standard Time) | sip.dialog | 5ht89pfuco7uopuuvnfvlc3g5ojo7pas3342e29e | new UAC dialog created with status EARLY
sip.js:36 Thu Aug 31 2017 19:01:53 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 183 Session Progress
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK3649713;received=103.8.112.210;rport=56998
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
To: <sip:03218...@10.11.11.75>;tag=as3342e29e
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 204 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03218...@10.11.11.75:5060;transport=WS>
Content-Type: application/sdp
Content-Length: 967

v=0
o=root 1143828837 1143828837 IN IP4 10.11.11.75
s=Asterisk PBX 11.25.1
c=IN IP4 10.11.11.75
t=0 0
m=audio 14298 RTP/SAVPF 8 0 126
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=fmtp:126 0-16
a=ptime:20
a=ice-ufrag:71f8c2b471f82fe12df9b8c519ed25d7
a=ice-pwd:290c1b6542c7411b298b082642891fd9
a=candidate:Ha0b0b4b 1 UDP 2130706431 10.11.11.75 14298 typ host
a=candidate:Hc0a8000c 1 UDP 2130706431 192.168.0.12 14298 typ host
a=candidate:S67087002 1 UDP 1694498815 103.8.112.2 14298 typ srflx raddr 10.11.11.75 rport 14298
a=candidate:Ha0b0b4b 2 UDP 2130706430 10.11.11.75 14299 typ host
a=candidate:Hc0a8000c 2 UDP 2130706430 192.168.0.12 14299 typ host
a=candidate:S67087002 2 UDP 1694498814 103.8.112.2 14299 typ srflx raddr 10.11.11.75 rport 14299
a=connection:new
a=setup:active
a=fingerprint:SHA-256 79:7F:71:4E:84:3B:4B:0C:AA:3C:F4:38:E4:E1:6C:DC:3D:E8:13:1B:4E:D4:7A:8A:BF:37:D4:C7:78:67:89:72
a=sendrecv


sip.js:36 Thu Aug 31 2017 19:02:11 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

SIP/2.0 200 OK
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK3649713;received=103.8.112.210;rport=56998
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
To: <sip:03218...@10.11.11.75>;tag=as3342e29e
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 204 INVITE
Server: Asterisk PBX 11.25.1
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:03218...@10.11.11.75:5060;transport=WS>
Content-Type: application/sdp
Content-Length: 967

v=0
o=root 1143828837 1143828837 IN IP4 10.11.11.75
s=Asterisk PBX 11.25.1
c=IN IP4 10.11.11.75
t=0 0
m=audio 14298 RTP/SAVPF 8 0 126
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:126 telephone-event/8000
a=fmtp:126 0-16
a=ptime:20
a=ice-ufrag:71f8c2b471f82fe12df9b8c519ed25d7
a=ice-pwd:290c1b6542c7411b298b082642891fd9
a=candidate:Ha0b0b4b 1 UDP 2130706431 10.11.11.75 14298 typ host
a=candidate:Hc0a8000c 1 UDP 2130706431 192.168.0.12 14298 typ host
a=candidate:S67087002 1 UDP 1694498815 103.8.112.2 14298 typ srflx raddr 10.11.11.75 rport 14298
a=candidate:Ha0b0b4b 2 UDP 2130706430 10.11.11.75 14299 typ host
a=candidate:Hc0a8000c 2 UDP 2130706430 192.168.0.12 14299 typ host
a=candidate:S67087002 2 UDP 1694498814 103.8.112.2 14299 typ srflx raddr 10.11.11.75 rport 14299
a=connection:new
a=setup:active
a=fingerprint:SHA-256 79:7F:71:4E:84:3B:4B:0C:AA:3C:F4:38:E4:E1:6C:DC:3D:E8:13:1B:4E:D4:7A:8A:BF:37:D4:C7:78:67:89:72
a=sendrecv


sip.js:36 Thu Aug 31 2017 19:02:11 GMT+0500 (Pakistan Standard Time) | sip.dialog | 5ht89pfuco7uopuuvnfvlc3g5ojo7pas3342e29e | dialog 5ht89pfuco7uopuuvnfvlc3g5ojo7pas3342e29e changed to CONFIRMED state
sip.js:36 Thu Aug 31 2017 19:02:11 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

ACK sip:03218...@10.11.11.75:5060;transport=ws SIP/2.0
Via: SIP/2.0/WSS 192.0.2.131;branch=z9hG4bK4939446
Max-Forwards: 70
To: <sip:03218...@10.11.11.75>;tag=as3342e29e
From: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 204 ACK
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Length: 0



sip.js:36 Thu Aug 31 2017 19:02:11 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | stream added: default
sip.js:36 Thu Aug 31 2017 19:02:16 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | RTCIceChecking Timeout Triggered after 5000 milliseconds
sip.js:36 Thu Aug 31 2017 19:02:20 GMT+0500 (Pakistan Standard Time) | sip.transaction.ict | z9hG4bK3649713 | Timer B expired for INVITE client transaction z9hG4bK3649713
sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.transport | received WebSocket text message:

BYE sip:rhv1...@192.0.2.131;transport=wss;ob SIP/2.0
Via: SIP/2.0/WS 10.11.11.75:5060;branch=z9hG4bK4dd11430;rport
Max-Forwards: 70
From: <sip:03218...@10.11.11.75>;tag=as3342e29e
To: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 102 BYE
User-Agent: Asterisk PBX 11.25.1
Proxy-Authorization: Digest username="habib", realm="10.11.11.75", algorithm=MD5, uri="sip:10.11.11.75", nonce="22c0f222", response="82f71eedbe2ebdc1c8b20bc351d0d751"
X-Asterisk-HangupCause: Normal Clearing
X-Asterisk-HangupCauseCode: 16
Content-Length: 0



sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.transport | sending WebSocket message:

SIP/2.0 200 OK
Via: SIP/2.0/WS 10.11.11.75:5060;branch=z9hG4bK4dd11430;rport
To: <sip:ha...@10.11.11.75>;tag=lc3g5ojo7p
From: <sip:03218...@10.11.11.75>;tag=as3342e29e
Call-ID: 5ht89pfuco7uopuuvnfv
CSeq: 102 BYE
Supported: outbound
User-Agent: Intellicon-WebRTC
Content-Length: 0



sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.inviteclientcontext | closing INVITE session 5ht89pfuco7uopuuvnfvr6vgdksft0
sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.invitecontext.mediahandler | 5ht89pfuco7uopuuvnfvr6vgdksft0 | closing PeerConnection
sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.dialog | 5ht89pfuco7uopuuvnfvlc3g5ojo7pas3342e29e | dialog 5ht89pfuco7uopuuvnfvlc3g5ojo7pas3342e29e deleted
sip.js:36 Thu Aug 31 2017 19:02:28 GMT+0500 (Pakistan Standard Time) | sip.transaction.nist | z9hG4bK4dd11430 | Timer J expired for non-INVITE server transaction z9hG4bK4dd11430
sip.js:36 Thu Aug 31 2017 19:02:43 GMT+0500 (Pakistan Standard Time) | sip.transaction.ict | z9hG4bK3649713 | Timer M expired for INVITE client transaction z9hG4bK3649713
------------------------------------------------------------

[Eric Green]

The problem is almost definitely on the Asterisk side. We support Asterisk to the extent of our guide. Can you set up Asterisk as outlined in the guide and tell me if it is still happening?

Thanks,

-Eric Green

[jeremy...@gmail.com]

I encountering what might be the same issue with sip.js 0.8.3 (talking to freeswitch - so it's not asterisk-specific). What happens is that I get the "RTCIceChecking Timeout" error 5 seconds after the call is established.

I added some logging messages (log below) to track down what was happening and in summary:

- the timer is started when the first ICE candidate is discovered
- the timer is correctly stopped when ICE candidate gathering is complete
- the timer is then started *again* in peerConnection.oniceconnectionstatechange
- the timer is not stopped after this so it times out after 5s

What exactly is startIceCheckingTimer() really supposed to track? It seems to me it's to tied to *gathering candidates* ? It seems odd to be starting this timer when the *connection* state changes, especially as there is no symetric "stop" action.

Tue Nov 07 2017 12:08:52 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | ICE candidate received: candidate:858005057 1 tcp 1518214911 W.X.Y.Z 9 typ host tcptype active generation 0 ufrag wOho network-id 1 network-cost 10
sip.js:783 Tue Nov 07 2017 12:08:52 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | !!! startIceCheckingTimer !!!
sip.js:783 Tue Nov 07 2017 12:08:52 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | RTCIceGatheringState changed: complete
sip.js:783 Tue Nov 07 2017 12:08:52 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | !!! onIceCompleted !!!
sip.js:783 Tue Nov 07 2017 12:08:54 GMT+0100 (CET) | sip.dialog | new UAC dialog created with status EARLY
sip.js:783 Tue Nov 07 2017 12:09:07 GMT+0100 (CET) | sip.dialog | dialog etuq2umosb98pnj64gm3rshk7bhaircDaN8HyS2063D changed to CONFIRMED state
sip.js:783 Tue Nov 07 2017 12:09:07 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | !!! iceConnectionState: checking !!!
sip.js:783 Tue Nov 07 2017 12:09:07 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | !!! startIceCheckingTimer !!!
sip.js:783 Tue Nov 07 2017 12:09:07 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | Using deprecated stream API
LoggerFactory.print @ sip.js:783
LoggerFactory.(anonymous function) @ sip.js:800
Logger.(anonymous function) @ sip.js:794
peerConnection.onaddstream @ sip.js:8844
sip.js:783 Tue Nov 07 2017 12:09:07 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | stream added
sip.js:783 Tue Nov 07 2017 12:09:08 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | !!! iceConnectionState: connected !!!
sip.js:783 Tue Nov 07 2017 12:09:08 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | !!! iceConnectionState: completed !!!
sip.js:783 Tue Nov 07 2017 12:09:12 GMT+0100 (CET) | sip.invitecontext.sessionDescriptionHandler | RTCIceChecking Timeout Triggered after 5000 milliseconds

[Eric Green]

There is a block in the startIceCheckingTimer function that will only allow the timer to start once per peer connection.

The time is to help with "bad" connections that cannot be used for WebRTC anyways. If a candidate doesn't return within 5 seconds it will be impossible to use for a WebRTC media session. In reality, we set this to 1 second on our web phone that our customers use. Without this timeout you could wait a very long for ice candidates. 

That being said, it is completely configurable. If you think that it is your problem set it really high. If all your peers come back before the timeout, then the timeout does not matter. I can say, that this is most likely not your problem.

-Eric Green

[Jeremy Lainé]

Hi Eric,

Thanks for your reply! I think you misunderstood my email : the timer *is* being started again for the same peer connection, *after* candidates gathering is finished. I think the block of code you are referring to is :

https://github.com/onsip/SIP.js/blob/master/src/WebRTC/SessionDescriptionHandler.js#L384

This only checks if the timer is *currently running*, but iceCheckingTimer is reset to null here:

https://github.com/onsip/SIP.js/blob/master/src/WebRTC/SessionDescriptionHandler.js#L355

.. and then started again here:

https://github.com/onsip/SIP.js/blob/master/src/WebRTC/SessionDescriptionHandler.js#L416

Look at the sequence of events I sent in my previous email and it will become quite clear.

I still don't understand the logic behind iceCheckingTimer : is it supposed to limit the time spent gathering candidates (icegatheringstate), or establishing the connection(iceconnectionstate)? It's doubtful the same timer makes sense for both these kinds of events.

Jeremy

--
You received this message because you are subscribed to a topic in the Google Groups "SIP.js" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/sip_js/390W_HZpKxU/unsubscribe.
To unsubscribe from this group and all its topics, send an email to sip_js+unsubscribe@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/sip_js/97585688-fe07-4907-8938-7f0a1212a081%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Eric Green]

I see. Looks like you are correct, it should not be started again in the iceconnectionstatechange callback. The timeout is for gathering the candidates. I will get a commit together that fixes this. This is just an inefficiency and confusing logs. It should not be causing any adverse effects with media flow.

-Eric Green

[Eric Green]

I pushed f99c6b3 that should address this. It will not trigger a new release, but will get in our next release (expected within the next few weeks).

-Eric Green

[Jeremy Lainé]

Cool! One less benign warning to look at while investigating issues.

Jeremy

To view this discussion on the web visit https://groups.google.com/d/msgid/sip_js/4922087b-8177-4de2-b8b4-b6dbeec323ea%40googlegroups.com.

[jeremy...@gmail.com]

Digging into the code some more, it seems there are deeper issues with how icegatheringstate is being handled, specifically the "onIceCompleted" deferred. As a reminder, the only places we make any use of this promise are:

a/ to emit a signal

https://github.com/onsip/SIP.js/blob/f99c6b34d49296d630a0eaef7e2e7b1b3873ffb7/src/WebRTC/SessionDescriptionHandler.js#L351

(but this would be better handled in onicegatheringstatechange)

b/ to know when our local description has settled

https://github.com/onsip/SIP.js/blob/f99c6b34d49296d630a0eaef7e2e7b1b3873ffb7/src/WebRTC/SessionDescriptionHandler.js#L311

There are two main problems here:

a/ we do:

if (pc.iceGatheringState === 'complete' && (pc.iceConnectionState === 'connected' || pc.iceConnectionState === 'completed')) {
resolve();
} else {
self.onIceCompleted.promise.then(resolve);
}

This is not OK, we are testing two conditions : the icegatheringstate (which is the one we care about) and the iceconnectionstate (which is unrelated).

b/ onIceCompleted is a promise : it only resolves once. This does not accurately reflect how icegatheringstate works, it can revert back to "gathering" *after* "complete". This is for instance the case on Firefox when you use "hold". As a result of this, when you use hold on Firefox, getDescription never resolves (or rejects) when icegatheringstate finally goes back to "complete" for the second time.

c/ I have a feeling the timer is not doing us a favour at all. It's started upon receiving a candidate, so it doesn't even measure "how long did it take to go from gathering to complete".

All this could be handled by introducing a waitForIceGatheringComplete method which returns a (single use) promise which either resolves immediately (already complete) or when icegatheringstate does complete.

I would be quite happy to submit a pull request for this, but am wondering : do we really need the timer? It significantly complexifies the code, and I'm not sure what problem it's trying to address.

[Eric Green]

I agree that we really only care about the ice gathering state. When I did my refactor of this code, I tried to not touch a lot of this code that is "working". A PR cleaning it up would be appreciated.

The timer is absolutely needed. We have seen network configurations where users will have virtual adapters or VPN connections that cause ICE gathering to take upwards of 30 seconds to complete. This means that on an incoming call you accept it and then it would take SIP.js 30 seconds to actually send the 200 OK. This is unacceptable to users and like I stated previously candidates that come back at 30 seconds are unusable anyways. The correct answer here is to implement trickle ICE, but without that we need a maximum timeout here. The timer starting on the first candidate received is alright IMO, but if you wanted to change where it starts that would be fine too. Almost all users have a local candidate that comes back immediately, so moving it elsewhere would have little effect.

-Eric Green

[jeremy...@gmail.com]

OK, I've kept the timer and created a pull request here:

https://github.com/onsip/SIP.js/pull/467

[nguyenph...@gmail.com]

Vào 10:14:07 UTC+7 Thứ Tư, ngày 06 tháng 9 năm 2017, habib...@gmail.com đã viết:

I have resolve this problem: RTCIceChecking Timeout Triggered after 200 milliseconds, default settings are 5000 milliseconds
addDefaultIceCheckingTimeout: { writable: true, value: function addDefaultIceCheckingTimeout(peerConnectionOptions) {
if (peerConnectionOptions.iceCheckingTimeout === undefined) {
peerConnectionOptions.iceCheckingTimeout = 5000;
}
return peerConnectionOptions;
} },
This is my configure:
var configuration = {
// Replace this IP address with your FreeSWITCH IP address
displayName: 'your display name',
uri: 'yourUri',
// Replace sipjs.com with your domain name
// and replace the port with your FreeSWITCH wss port
authorizationUser: 'your user',
password: 'your password',
transport: 'tcp, udp,ws,wss',
transportOptions: {
wsServers: ['your freeswitch wss server']
},
hackIpInContact: true,
register: true,
//registerExpires: 1000,
traceSip: true,
sessionDescriptionHandlerFactoryOptions: {
peerConnectionOptions: {
rtcConfiguration: {
iceServers: [
{ urls: "stun:stun.l.google.com:19302" },
{
urls: "turn:turn-ip:443?transport=tcp",
username: "turnuser",
credential: "turnpass"
}
]
},
iceCheckingTimeout: 200,
}
}
};