RTP Timeout

[Mike Remski]

JsSIP in a node application, not running in a browser but using
node-wrtc to provide the webrtc bits.

Using the following options for the UA.call(), trying to use the
specified ice Server (plus an 'extraHeaders' item in option not shown)

var options = {
'eventHandlers' : eventHandlers,
'sessionTimersExpires' : 1800,
'mediaStream' : mStream,
'mediaConstraints' : { 'audio': true, 'video': false },
'pcConfig' : {
'iceServers' : [
{ 'urls' : ['stun:turn.server.company.net:3478'] }
] },
}

According to the server side (server uses Softil), the session is
connected, ICE is complete and DTLS is done, so it should be up.
But after about 16 secs, the JsSIP side throws a 408 RTP_TIMEOUT,
source shows it one place on ice connection state change to failed.

We've set JsSIP.debug.enable('JsSIP:*'); so we have as much debug logs
from JsSIP. I'm not seeing any SDP/SIP message sent from JsSIP that
includes the specified ice server from the options.

I feel like I'm missing something in either the options for the peer
connection or somewhere else.

Thanks for any insight.

console output below.

JsSIP:UA new() [configuration:{ sockets: [ NodeWebSocket { _url: 'ws://192.168.11.23:55080', _options: {}, _sipUri: 'sip:192.168.11.23:55080;transport=ws', _viaTransport: 'WS', _ws: null } ], uri: 'sip:test...@tester.domain.com', authorization_user: 'testUser1', display_name: 'testUser1', session_timers_refresh_method: 'invite', register: false }] +0ms
JsSIP:Transport new() +0ms
JsSIP:UA configuration parameters after validation: +6ms
JsSIP:UA - authorization_user: "testUser1" +0ms
JsSIP:UA - password: NOT SHOWN +0ms
JsSIP:UA - realm: null +0ms
JsSIP:UA - ha1: NOT SHOWN +0ms
JsSIP:UA - authorization_jwt: NOT SHOWN +1ms
JsSIP:UA - display_name: "testUser1" +0ms
JsSIP:UA - uri: sip:test...@tester.domain.com +0ms
JsSIP:UA - contact_uri: {"_parameters":{"transport":"ws"},"_headers":{},"_scheme":"sip","_user":"prr8uhqp","_host":"3hffj7oamvev.invalid","_port":null} +0ms
JsSIP:UA - instance_id: "86e977a0-2553-4209-a029-eccce29ad667" +0ms
JsSIP:UA - use_preloaded_route: false +0ms
JsSIP:UA - session_timers: true +0ms
JsSIP:UA - session_timers_refresh_method: "INVITE" +0ms
JsSIP:UA - session_timers_force_refresher: false +0ms
JsSIP:UA - no_answer_timeout: 60000 +0ms
JsSIP:UA - register: false +0ms
JsSIP:UA - register_expires: 600 +0ms
JsSIP:UA - registrar_server: sip:tester.domain.com +0ms
JsSIP:UA - connection_recovery_max_interval: 30 +0ms
JsSIP:UA - connection_recovery_min_interval: 2 +0ms
JsSIP:UA - via_host: "3hffj7oamvev.invalid" +0ms

JsSIP:UA start() +1ms
JsSIP:Transport connect() +2ms
connecting: {
socket: NodeWebSocket {
_url: 'ws://192.168.11.23:55080',
_options: {},
_sipUri: 'sip:192.168.11.23:55080;transport=ws',
_viaTransport: 'WS',
_ws: null
},
attempts: 0
}

connected: {
socket: Transport {
status: 0,
socket: NodeWebSocket {
_url: 'ws://192.168.11.23:55080',
_options: {},
_sipUri: 'sip:192.168.11.23:55080;transport=ws',
_viaTransport: 'WS',
_ws: [W3CWebSocket],
onconnect: [Function: bound _onConnect],
ondisconnect: [Function: bound _onDisconnect],
ondata: [Function: bound _onData]
},
sockets: [ [Object] ],
recovery_options: { max_interval: 30, min_interval: 2 },
recover_attempts: 0,
recovery_timer: null,
close_requested: false,
textDecoder: TextDecoder { encoding: 'utf-8', fatal: false, ignoreBOM: false },
onconnecting: [Function: bound onTransportConnecting],
onconnect: [Function: bound onTransportConnect],
ondisconnect: [Function: bound onTransportDisconnect],
ondata: [Function: bound onTransportData]
}
}
JsSIP:UA call() +128ms
JsSIP:RTCSession new +0ms
JsSIP:RTCSession connect() +1ms
JsSIP:RTCSession emit "peerconnection" +9ms
peerconnection undefined
JsSIP:RTCSession newRTCSession() +1ms
JsSIP:RTCSession session connecting +4ms
JsSIP:RTCSession emit "connecting" +0ms
connecting
JsSIP:RTCSession createLocalDescription() +1ms
icecandidate undefined
icecandidate undefined
icecandidate undefined
icecandidate undefined
icecandidate undefined
icecandidate undefined
icecandidate undefined
icecandidate undefined
icecandidate undefined
JsSIP:RTCSession emit "sdp" +6s
sdp local offer
JsSIP:RTCSession emit "sending" [request:InitialOutgoingInviteRequest { ua: <ref *1> UA { _events: [Object: null prototype] { connecting: [Function (anonymous)], connected: [Function (anonymous)], disconnected: [Function (anonymous)] }, _eventsCount: 3, _maxListeners: undefined, _cache: { credentials: {} }, _configuration: { authorization_user: 'testUser1', password: null, realm: null, ha1: null, authorization_jwt: null, display_name: 'testUser1', uri: [URI], contact_uri: [URI], instance_id: '86e977a0-2553-4209-a029-eccce29ad667', use_preloaded_route: false, session_timers: true, session_timers_refresh_method: 'INVITE', session_timers_force_refresher: false, no_answer_timeout: 60000, register: false, register_expires: 600, registrar_server: [URI], connection_recovery_max_interval: 30, connection_recovery_min_interval: 2, via_host: '3hffj7oamvev.invalid', jssip_id: 'gnn18', hostport_params: 'tester.domain.com' }, _dynConfiguration: { register: false }, _dialogs: {}, _applicants: {}, _sessions: { gnn187hi1pqski3gc1b4lmro1dhmib: [RTCSession] }, _transport: Transport { status: 0, socket: [NodeWebSocket], sockets: [Array], recovery_options: [Object], recover_attempts: 0, recovery_timer: null, close_requested: false, textDecoder: [TextDecoder], onconnecting: [Function: bound onTransportConnecting], onconnect: [Function: bound onTransportConnect], ondisconnect: [Function: bound onTransportDisconnect], ondata: [Function: bound onTransportData] }, _contact: { pub_gruu: null, temp_gruu: null, uri: [URI], toString: [Function: toString] }, _status: 1, _error: null, _transactions: { nist: {}, nict: {}, ist: {}, ict: {} }, _data: {}, _closeTimer: null, _registrator: Registrator { _reg_id: 1, _ua: [Circular *1], _transport: undefined, _registrar: [URI], _expires: 600, _call_id: 'bpq0jhtafmecic1pf7c24v', _cseq: 0, _to_uri: [URI], _registrationTimer: null, _registering: false, _registered: false, _contact: '<sip:prr8...@3hffj7oamvev.invalid;transport=ws>;+sip.ice;reg-id=1;+sip.instance="<urn:uuid:86e977a0-2553-4209-a029-eccce29ad667>"', _extraHeaders: [], _extraContactParams: '', _sipInstance: '"<urn:uuid:86e977a0-2553-4209-a029-eccce29ad667>"' }, [Symbol(kCapture)]: false }, headers: { Via: [ '' ], 'Max-Forwards': [ 69 ], To: [ '<sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>' ], From: [ '"testUser1" <sip:test...@tester.domain.com>;tag=lmro1dhmib' ], 'Call-ID': [ 'gnn187hi1pqski3gc1b4' ], CSeq: [ '3310 INVITE' ] }, method: 'INVITE', ruri: URI { _parameters: {}, _headers: {}, _scheme: 'sip', _user: 'media_a88b3ceb-03f9-471b-8b3c-eb03f9371bd8_dev360-e2_1-0-0', _host: 'sip.dev360.company.net', _port: undefined }, body: 'v=0\r\n' + 'o=- 2596609101018909117 2 IN IP4 127.0.0.1\r\n' + 's=-\r\n' + 't=0 0\r\n' + 'a=group:BUNDLE 0\r\n' + 'a=msid-semantic: WMS f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3\r\n' + 'm=audio 59473 UDP/TLS/RTP/SAVPF 111 103 104 9 102 0 8 106 105 13 110 112 113 126\r\n' + 'c=IN IP4 47.187.194.85\r\n' + 'a=rtcp:9 IN IP4 0.0.0.0\r\n' + 'a=candidate:25350228 1 udp 2122260223 192.168.254.15 59473 typ host generation 0 network-id 4 network-cost 50\r\n' + 'a=candidate:3851333459 1 udp 2122194687 192.168.9.16 35722 typ host generation 0 network-id 3 network-cost 50\r\n' + 'a=candidate:559267639 1 udp 2122136831 ::1 33911 typ host generation 0 network-id 2\r\n' + 'a=candidate:1510613869 1 udp 2122063615 127.0.0.1 39765 typ host generation 0 network-id 1\r\n' + 'a=candidate:1325477028 1 tcp 1518280447 192.168.254.15 57785 typ host tcptype passive generation 0 network-id 4 network-cost 50\r\n' + 'a=candidate:2869777315 1 tcp 1518214911 192.168.9.16 53937 typ host tcptype passive generation 0 network-id 3 network-cost 50\r\n' + 'a=candidate:1876313031 1 tcp 1518157055 ::1 57573 typ host tcptype passive generation 0 network-id 2\r\n' + 'a=candidate:344579997 1 tcp 1518083839 127.0.0.1 52085 typ host tcptype passive generation 0 network-id 1\r\n' + 'a=candidate:3440373703 1 udp 1686052607 47.187.194.85 59473 typ srflx raddr 192.168.254.15 rport 59473 generation 0 network-id 4 network-cost 50\r\n' + 'a=ice-ufrag:rlYO\r\n' + 'a=ice-pwd:UDw0KsCJy55vZisLkySEfA6L\r\n' + 'a=ice-options:trickle\r\n' + 'a=fingerprint:sha-256 0F:AC:D2:CF:E3:F2:10:4F:94:D4:4F:51:7B:CC:80:D1:F8:93:FB:30:72:9C:1D:A0:2A:28:DB:08:9D:66:43:18\r\n' + 'a=setup:actpass\r\n' + 'a=mid:0\r\n' + 'a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\n' + 'a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time\r\n' + 'a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\n' + 'a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid\r\n' + 'a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id\r\n' + 'a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id\r\n' + 'a=sendrecv\r\n' + 'a=msid:f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3 a393782e-0d46-4222-a895-886d5e596341\r\n' + 'a=rtcp-mux\r\n' + 'a=rtpmap:111 opus/48000/2\r\n' + 'a=rtcp-fb:111 transport-cc\r\n' + 'a=fmtp:111 minptime=10;useinbandfec=1\r\n' + 'a=rtpmap:103 ISAC/16000\r\n' + 'a=rtpmap:104 ISAC/32000\r\n' + 'a=rtpmap:9 G722/8000\r\n' + 'a=rtpmap:102 ILBC/8000\r\n' + 'a=rtpmap:0 PCMU/8000\r\n' + 'a=rtpmap:8 PCMA/8000\r\n' + 'a=rtpmap:106 CN/32000\r\n' + 'a=rtpmap:105 CN/16000\r\n' + 'a=rtpmap:13 CN/8000\r\n' + 'a=rtpmap:110 telephone-event/48000\r\n' + 'a=rtpmap:112 telephone-event/32000\r\n' + 'a=rtpmap:113 telephone-event/16000\r\n' + 'a=rtpmap:126 telephone-event/8000\r\n' + 'a=ssrc:3961550081 cname:WEZKDax43F4JI5jw\r\n' + 'a=ssrc:3961550081 msid:f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3 a393782e-0d46-4222-a895-886d5e596341\r\n' + 'a=ssrc:3961550081 mslabel:f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3\r\n' + 'a=ssrc:3961550081 label:a393782e-0d46-4222-a895-886d5e596341\r\n', extraHeaders: [ 'X-DEVICE-UUID: device:3fbea7d5-1afb-422a-bea7-d51afb922ae7:dev360-e2:1-0-0', 'Authorization: Bearer Token=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJSYW1hbkF5eWFyQGRldnRlc3QiLCJjdHMiOiJPQVVUSDJfU1RBVEVMRVNTX0dSQU5UIiwiYXV0aF9sZXZlbCI6MCwiYXVkaXRUcmFja2luZ0lkIjoiMDRjYTNjMjgtOWU4YS00NzcwLWEyNzItNDQxMjY0NGU5ZDRlLTEwODY5NDg0IiwiaXNzIjoiaHR0cHM6Ly9sbmszNjAuZGV2MzYwLm11dHVhbGluay5uZXQvbXV0L29hdXRoMiIsInRva2VuTmFtZSI6ImFjY2Vzc190b2tlbiIsInRva2VuX3R5cGUiOiJCZWFyZXIiLCJhdXRoR3JhbnRJZCI6Ik43LTBEQ1V3SDhya3YzaEU5NmtyMzlXTUo2USIsImF1ZCI6IjNlYzI1ZWI0LTlmNWQtNGU0Yy04NDIxLTcwZGM3M2Y4ZTEwNSIsIm5iZiI6MTY1MTE1NjgyOSwiZ3JhbnRfdHlwZSI6InJlZnJlc2hfdG9rZW4iLCJzY29wZSI6WyJvcGVuaWQiLCJwcm9maWxlIiwiZW1haWwiXSwiYXV0aF90aW1lIjoxNjUwOTI3Nzk0LCJyZWFsbSI6Ii9pZGVudGl0aWVzIiwiZXhwIjoxNjUxMTYwNDI5LCJpYXQiOjE2NTExNTY4MjksImV4cGlyZXNfaW4iOjM2MDAsImp0aSI6IlR6dUlHOTdrMkYxdU0yeEMtU3lpZDJablQxSSJ9.5E1flmBmcYdF7PztiTJ7bW0K7kWqRH85WVPbOjqX6wU', 'Contact: <sip:prr8...@3hffj7oamvev.invalid;transport=ws;ob>', 'Content-Type: application/sdp', 'Session-Expires: 1800' ], to: NameAddrHeader { _uri: URI { _parameters: {}, _headers: {}, _scheme: 'sip', _user: 'media_a88b3ceb-03f9-471b-8b3c-eb03f9371bd8_dev360-e2_1-0-0', _host: 'sip.dev360.company.net', _port: undefined }, _parameters: {}, _display_name: null }, from: NameAddrHeader { _uri: URI { _parameters: {}, _headers: {}, _scheme: 'sip', _user: 'testUser1', _host: 'tester.domain.com', _port: undefined }, _parameters: { tag: 'lmro1dhmib' }, _display_name: 'testUser1' }, call_id: 'gnn187hi1pqski3gc1b4', cseq: 3310, transaction: null }] +1ms
sending
JsSIP:Transport send() +6s
JsSIP:Transport sending message:
JsSIP:Transport
JsSIP:Transport INVITE sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net SIP/2.0
JsSIP:Transport Via: SIP/2.0/WS 3hffj7oamvev.invalid;branch=z9hG4bK6997661
JsSIP:Transport Max-Forwards: 69
JsSIP:Transport To: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>
JsSIP:Transport From: "testUser1" <sip:test...@tester.domain.com>;tag=lmro1dhmib
JsSIP:Transport Call-ID: gnn187hi1pqski3gc1b4
JsSIP:Transport CSeq: 3310 INVITE
JsSIP:Transport X-DEVICE-UUID: device:3fbea7d5-1afb-422a-bea7-d51afb922ae7:dev360-e2:1-0-0
JsSIP:Transport Authorization: Bearer Token=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJSYW1hbkF5eWFyQGRldnRlc3QiLCJjdHMiOiJPQVVUSDJfU1RBVEVMRVNTX0dSQU5UIiwiYXV0aF9sZXZlbCI6MCwiYXVkaXRUcmFja2luZ0lkIjoiMDRjYTNjMjgtOWU4YS00NzcwLWEyNzItNDQxMjY0NGU5ZDRlLTEwODY5NDg0IiwiaXNzIjoiaHR0cHM6Ly9sbmszNjAuZGV2MzYwLm11dHVhbGluay5uZXQvbXV0L29hdXRoMiIsInRva2VuTmFtZSI6ImFjY2Vzc190b2tlbiIsInRva2VuX3R5cGUiOiJCZWFyZXIiLCJhdXRoR3JhbnRJZCI6Ik43LTBEQ1V3SDhya3YzaEU5NmtyMzlXTUo2USIsImF1ZCI6IjNlYzI1ZWI0LTlmNWQtNGU0Yy04NDIxLTcwZGM3M2Y4ZTEwNSIsIm5iZiI6MTY1MTE1NjgyOSwiZ3JhbnRfdHlwZSI6InJlZnJlc2hfdG9rZW4iLCJzY29wZSI6WyJvcGVuaWQiLCJwcm9maWxlIiwiZW1haWwiXSwiYXV0aF90aW1lIjoxNjUwOTI3Nzk0LCJyZWFsbSI6Ii9pZGVudGl0aWVzIiwiZXhwIjoxNjUxMTYwNDI5LCJpYXQiOjE2NTExNTY4MjksImV4cGlyZXNfaW4iOjM2MDAsImp0aSI6IlR6dUlHOTdrMkYxdU0yeEMtU3lpZDJablQxSSJ9.5E1flmBmcYdF7PztiTJ7bW0K7kWqRH85WVPbOjqX6wU
JsSIP:Transport Contact: <sip:prr8...@3hffj7oamvev.invalid;transport=ws;ob>
JsSIP:Transport Content-Type: application/sdp
JsSIP:Transport Session-Expires: 1800
JsSIP:Transport Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
JsSIP:Transport Supported: timer,ice,replaces,outbound
JsSIP:Transport User-Agent: JsSIP 3.9.0
JsSIP:Transport Content-Length: 2703
JsSIP:Transport
JsSIP:Transport v=0
JsSIP:Transport o=- 2596609101018909117 2 IN IP4 127.0.0.1
JsSIP:Transport s=-
JsSIP:Transport t=0 0
JsSIP:Transport a=group:BUNDLE 0
JsSIP:Transport a=msid-semantic: WMS f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3
JsSIP:Transport m=audio 59473 UDP/TLS/RTP/SAVPF 111 103 104 9 102 0 8 106 105 13 110 112 113 126
JsSIP:Transport c=IN IP4 47.187.194.85
JsSIP:Transport a=rtcp:9 IN IP4 0.0.0.0
JsSIP:Transport a=candidate:25350228 1 udp 2122260223 192.168.254.15 59473 typ host generation 0 network-id 4 network-cost 50
JsSIP:Transport a=candidate:3851333459 1 udp 2122194687 192.168.9.16 35722 typ host generation 0 network-id 3 network-cost 50
JsSIP:Transport a=candidate:559267639 1 udp 2122136831 ::1 33911 typ host generation 0 network-id 2
JsSIP:Transport a=candidate:1510613869 1 udp 2122063615 127.0.0.1 39765 typ host generation 0 network-id 1
JsSIP:Transport a=candidate:1325477028 1 tcp 1518280447 192.168.254.15 57785 typ host tcptype passive generation 0 network-id 4 network-cost 50
JsSIP:Transport a=candidate:2869777315 1 tcp 1518214911 192.168.9.16 53937 typ host tcptype passive generation 0 network-id 3 network-cost 50
JsSIP:Transport a=candidate:1876313031 1 tcp 1518157055 ::1 57573 typ host tcptype passive generation 0 network-id 2
JsSIP:Transport a=candidate:344579997 1 tcp 1518083839 127.0.0.1 52085 typ host tcptype passive generation 0 network-id 1
JsSIP:Transport a=candidate:3440373703 1 udp 1686052607 47.187.194.85 59473 typ srflx raddr 192.168.254.15 rport 59473 generation 0 network-id 4 network-cost 50
JsSIP:Transport a=ice-ufrag:rlYO
JsSIP:Transport a=ice-pwd:UDw0KsCJy55vZisLkySEfA6L
JsSIP:Transport a=ice-options:trickle
JsSIP:Transport a=fingerprint:sha-256 0F:AC:D2:CF:E3:F2:10:4F:94:D4:4F:51:7B:CC:80:D1:F8:93:FB:30:72:9C:1D:A0:2A:28:DB:08:9D:66:43:18
JsSIP:Transport a=setup:actpass
JsSIP:Transport a=mid:0
JsSIP:Transport a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
JsSIP:Transport a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
JsSIP:Transport a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
JsSIP:Transport a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
JsSIP:Transport a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
JsSIP:Transport a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
JsSIP:Transport a=sendrecv
JsSIP:Transport a=msid:f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3 a393782e-0d46-4222-a895-886d5e596341
JsSIP:Transport a=rtcp-mux
JsSIP:Transport a=rtpmap:111 opus/48000/2
JsSIP:Transport a=rtcp-fb:111 transport-cc
JsSIP:Transport a=fmtp:111 minptime=10;useinbandfec=1
JsSIP:Transport a=rtpmap:103 ISAC/16000
JsSIP:Transport a=rtpmap:104 ISAC/32000
JsSIP:Transport a=rtpmap:9 G722/8000
JsSIP:Transport a=rtpmap:102 ILBC/8000
JsSIP:Transport a=rtpmap:0 PCMU/8000
JsSIP:Transport a=rtpmap:8 PCMA/8000
JsSIP:Transport a=rtpmap:106 CN/32000
JsSIP:Transport a=rtpmap:105 CN/16000
JsSIP:Transport a=rtpmap:13 CN/8000
JsSIP:Transport a=rtpmap:110 telephone-event/48000
JsSIP:Transport a=rtpmap:112 telephone-event/32000
JsSIP:Transport a=rtpmap:113 telephone-event/16000
JsSIP:Transport a=rtpmap:126 telephone-event/8000
JsSIP:Transport a=ssrc:3961550081 cname:WEZKDax43F4JI5jw
JsSIP:Transport a=ssrc:3961550081 msid:f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3 a393782e-0d46-4222-a895-886d5e596341
JsSIP:Transport a=ssrc:3961550081 mslabel:f3cd2dca-2407-4e70-9fa8-bbc15d3f68e3
JsSIP:Transport a=ssrc:3961550081 label:a393782e-0d46-4222-a895-886d5e596341
JsSIP:Transport
JsSIP:Transport +0ms
JsSIP:Transport received text message:
JsSIP:Transport
JsSIP:Transport SIP/2.0 100 Trying
JsSIP:Transport From: "testUser1"<sip:test...@tester.domain.com>;tag=lmro1dhmib
JsSIP:Transport To: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>
JsSIP:Transport Call-ID: gnn187hi1pqski3gc1b4
JsSIP:Transport CSeq: 3310 INVITE
JsSIP:Transport Via: SIP/2.0/WS 3hffj7oamvev.invalid;received=172.17.0.2;branch=z9hG4bK6997661
JsSIP:Transport Supported: timer
JsSIP:Transport Contact: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>
JsSIP:Transport Content-Length: 0
JsSIP:Transport
JsSIP:Transport
JsSIP:Transport +60ms
JsSIP:RTCSession receiveInviteResponse() +71ms
JsSIP:Transport received text message:
JsSIP:Transport
JsSIP:Transport SIP/2.0 200 OK
JsSIP:Transport From: "testUser1"<sip:test...@tester.domain.com>;tag=lmro1dhmib
JsSIP:Transport To: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>;tag=d80138b-6fc512b8-165c4-7f2ac32d5420-0-13c4-764
JsSIP:Transport Call-ID: gnn187hi1pqski3gc1b4
JsSIP:Transport CSeq: 3310 INVITE
JsSIP:Transport Session-Expires: 1800;refresher=uac
JsSIP:Transport Via: SIP/2.0/WS 3hffj7oamvev.invalid;received=172.17.0.2;branch=z9hG4bK6997661
JsSIP:Transport Supported: timer
JsSIP:Transport Contact: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>
JsSIP:Transport Session-Expires: 1800;refresher=uas
JsSIP:Transport Content-Type: application/sdp
JsSIP:Transport Content-Length: 508
JsSIP:Transport
JsSIP:Transport v=0
JsSIP:Transport o=company.net 959997302 485560281 IN IP4 108.7.45.177
JsSIP:Transport s=Company-Edge
JsSIP:Transport t=0 0
JsSIP:Transport a=group:BUNDLE 0
JsSIP:Transport a=ice-ufrag:+GKdFSkN
JsSIP:Transport a=ice-pwd:S6jW1pwTkqKq7oNtyTYQXh4z
JsSIP:Transport m=audio 57982 UDP/TLS/RTP/SAVPF 0
JsSIP:Transport c=IN IP4 108.7.45.177
JsSIP:Transport a=rtcp:57982 IN IP4 108.7.45.177
JsSIP:Transport a=mid:0
JsSIP:Transport a=sendrecv
JsSIP:Transport a=rtcp-mux
JsSIP:Transport a=rtpmap:0 PCMU/8000
JsSIP:Transport a=fingerprint:SHA-256 62:35:D3:82:0A:A8:C0:09:85:8D:A0:2B:6E:62:35:EE:EA:33:92:37:B8:0D:18:4F:49:87:4E:80:1E:54:84:66
JsSIP:Transport a=candidate:265 1 UDP 2130706431 108.7.45.177 57982 typ host
JsSIP:Transport a=setup:passive
JsSIP:Transport
JsSIP:Transport +72ms
JsSIP:RTCSession receiveInviteResponse() +73ms
JsSIP:Dialog new UAC dialog created with status CONFIRMED +0ms
JsSIP:RTCSession emit "sdp" +2ms
sdp remote answer
JsSIP:RTCSession session accepted +8ms
JsSIP:RTCSession emit "accepted" +1ms
JsSIP:RTCSession sendRequest() +0ms
JsSIP:Transport send() +20ms
JsSIP:Transport sending message:
JsSIP:Transport
JsSIP:Transport ACK sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net SIP/2.0
JsSIP:Transport Via: SIP/2.0/WS 3hffj7oamvev.invalid;branch=z9hG4bK7634179
JsSIP:Transport Max-Forwards: 69
JsSIP:Transport To: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>;tag=d80138b-6fc512b8-165c4-7f2ac32d5420-0-13c4-764
JsSIP:Transport From: "testUser1" <sip:test...@tester.domain.com>;tag=lmro1dhmib
JsSIP:Transport Call-ID: gnn187hi1pqski3gc1b4
JsSIP:Transport CSeq: 3310 ACK
JsSIP:Transport Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
JsSIP:Transport Supported: outbound
JsSIP:Transport User-Agent: JsSIP 3.9.0
JsSIP:Transport Content-Length: 0
JsSIP:Transport
JsSIP:Transport
JsSIP:Transport +1ms
JsSIP:RTCSession session confirmed +3ms
JsSIP:RTCSession emit "confirmed" +1ms
call confirmed
JsSIP:RTCSession terminate() +16s
JsSIP:RTCSession terminating session +0ms
JsSIP:RTCSession sendRequest() +0ms
JsSIP:Transport send() +16s
JsSIP:Transport sending message:
JsSIP:Transport
JsSIP:Transport BYE sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net SIP/2.0
JsSIP:Transport Via: SIP/2.0/WS 3hffj7oamvev.invalid;branch=z9hG4bK5876337
JsSIP:Transport Max-Forwards: 69
JsSIP:Transport To: <sip:media_a88b3ceb-03f9-471b-8b3c...@sip.dev360.company.net>;tag=d80138b-6fc512b8-165c4-7f2ac32d5420-0-13c4-764
JsSIP:Transport From: "testUser1" <sip:test...@tester.domain.com>;tag=lmro1dhmib
JsSIP:Transport Call-ID: gnn187hi1pqski3gc1b4
JsSIP:Transport CSeq: 3311 BYE
JsSIP:Transport Reason: SIP ;cause=408; text="RTP Timeout"
JsSIP:Transport Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
JsSIP:Transport Supported: outbound
JsSIP:Transport User-Agent: JsSIP 3.9.0
JsSIP:Transport Content-Length: 0
JsSIP:Transport
JsSIP:Transport
JsSIP:Transport +1ms
JsSIP:RTCSession session ended +4ms
JsSIP:RTCSession close() +0ms
JsSIP:Dialog dialog gnn187hi1pqski3gc1b4lmro1dhmibd80138b-6fc512b8-165c4-7f2ac32d5420-0-13c4-764 deleted +16s
JsSIP:RTCSession emit "ended" +3ms
call ended: local null RTP Timeout

[Mike Remski]

Probably something that can be ignored.  Spent a bunch of time going over packet capture, and realized that testing there is a VPN up and sending STUN Binding Requests sourced from the tunnel interface but never receiving responses for them and that appears to be causing the RTP_TIMEOUT.   Binding requests sent out the normal host interface are correctly receiving responses.

So now to figure that out.

[José Luis Millán]

The reason why you are getting a RTP_TIMEOUT error is because the PR iceconnectionstatechange event fires with 'failed' state. Why the WebRTC stack fires it I can't know.

https://github.com/versatica/JsSIP/blob/master/lib/RTCSession.js#L1855

--
You received this message because you are subscribed to the Google Groups "JsSIP" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jssip+un...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jssip/20220429053004.6d244081%40FBSDNUC.

--

José Luis Millán

[Mike Remski]

> > 'ws:// 192.168.11.23:55080', _options: {}, _sipUri:

Thank you. That's what I was concluding, but it's good to have it
confirmed. Means I understand the code.

Now to track down on the WebRTC stack why. Packet capture is clearly
showing ICE succeeding on one of the other interfaces, but something
thinks the VPN interface is the one that should be used.

Again, thank you.

[Mike Remski]

Sorry I never followed up on this thread, but the issue turned out to be the STUN/ICE communications.  I don't recall all the exact details, but the issue was how the STUN server was talking to the JsSIP parts.  JsSIP was expecting a certain message type the STUN server was not sending.  The STUN RFCs was a little unclear on was the message type a shall or was it a may, but fixing the STUN server fixed the problem.  packet caps showed that the STUN process was successfully completing but it was keeping it alive that failed.

[Tanzeel Ahmed]

Hi there Mike!

I really appreciate your response. So, I am passing the empty array to iceServer.

pcConfig: {

        iceServers: [],

    },

When I make the call. 

For caller (on nodejs server),

the iceconnectionstatechange event is fired in the following order: checking=> completed => completed 

For callee (on nodejs server),

the iceconnectionstatechange event is fired in the following order: checking=> connected => completed 

But after some time, the event is fired for any one of them in the following order:

disconnected=>failed.

Do you think this issue is similar to the one that you faced? Why is it even able to start the call at the first place?
Otherwise, I will open a new thread.

[Tanzeel Ahmed]

For callee (on nodejs server),

the iceconnectionstatechange event is fired in the following order: checking=> connected ** 

[Mike Remski]

Not sure what JsSIP is doing if you pass in empty array for iceservers, but could it be similar?  Maybe.   Have you tried not passing in any iceservers or passing in null for it?

I'm not an expert in the JsSIP code but ICE is simply part of the overall state machine for SIP,  a lot of things have to happen prior to the datapath (RTP) getting setup/connected.  Things like SDP, codec negotiation happen before or at the same time as STUN resolution.

[Tanzeel Ahmed]

In my case, a proper BYE is sent from Callee stating the cause is RTP Timeout. Neither do I get icecandidate undefined logs when I place the call.

And the call disconnects after around 30-35 seconds. I'll open up a new thread regarding this issue.

[Raman Ayyar]

Hi All,

I am giving additional information to what Mike Remski mentioned about STUN messaging.

Please check the far end about support of STUN "Binding Request" vs "Binding Indication".

In earlier systems (prior to webRtc), after the ICE negotiations the keepalive for STUN is done using

"Binding Indication" This was the case in our system.

JsSip/WebRTC expects "Binding Request" and "Binding Response" to continue as the keepalive.

Since our Media Server was transitioning to "Binding Indication" and quitting responding to "Binding Request" our calls were failing.

We made the change in our Media Server to continue with "Binding Request" and "Binding Response" for SIP over Websocket.

We use "Binding Indication" for SIP over TLS.

Hope this might help. You can check this with the pcap.

Thanks

Raman

To view this discussion on the web visit https://groups.google.com/d/msgid/jssip/b571f2fb-aa0c-45ed-9280-95c458d4b2e2n%40googlegroups.com.