search

onsip / SIP.js

A simple, intuitive, and powerful JavaScript signaling library
https://sipjs.com
MIT License
1.9k stars 702 forks source link

Stream base transport issues #818

Closed miladmeidanshahi closed 4 years ago

miladmeidanshahi commented 4 years ago

Describe the bug When you cancel an outgoing call, state Terminating just returned while Terminated should be returned after Terminating.

Logs According to https://github.com/onsip/SIP.js/blob/master/src/api/inviter.ts#L295 I think before return promise it should be this.stateTransition(SessionState.Terminated) called.

To Reproduce (if possible) Steps to reproduce the behavior:

  1. Make an invite.
  2. Before callee accepted, cancel the session.

Expected behavior After Terminating state in cancel, 'Terminated' should be returned.

Observed behavior 'Terminated' doesn't return after Terminating state in cancel.

Environment Information

Additional context Client and server log:

60  9.062662091 192.168.10.5    192.168.10.54   SIP/SDP 143 Request: INVITE sip:101@tmidomain1 | 
62  9.065097132 192.168.10.54   192.168.10.5    SIP 357 Status: 100 trying -- your call is important to us | 
66  9.272417664 192.168.10.54   192.168.10.5    SIP 674 Status: 180 Ringing | 
68  9.873305930 192.168.10.54   192.168.10.5    SIP 674 Status: 180 Ringing | 
72  13.572267621    192.168.10.5    192.168.10.54   SIP 370 Request: CANCEL sip:101@tmidomain1 | 
73  13.573423848    192.168.10.54   192.168.10.5    SIP 370 Status: 200 canceling | 
75  13.574347249    192.168.10.54   192.168.10.5    SIP 654 Status: 487 Request Terminated |

As you can see server sends me Status: 200 canceling and Status: 487 Request Terminated but sip.js doesn't return Terminated to a client.

miladmeidanshahi commented 4 years ago

Hi Eric, @egreenmachine Can you check this, please?

egreenmachine commented 4 years ago

Hi Milad, @miladmeidanshahi We are a small team here maintaining this library. This will get looked at and responded to when we have time to address it. There is no need to ping me on it.

john-e-riordan commented 4 years ago

Hi @miladmeidanshahi

When you cancel and outgoing call, the Session will transition to Terminating just before the CANCEL is sent. Once a negative final response to the INVITE is received (the 487), the Session will transition to Terminated. This behavior is intentional. The sent CANCEL does not guarantee or dictate that the Session has ended. For example, the CANCEL may not arrive at the far end or the far end may answer the call with a 200 Ok before the CANCEL arrives (in which case the API will send an ACK and then a BYE). Regardless, once the Session transitions to Terminating it will eventually transition to Terminated and your application may safely assume as much it that suits.

For more details, please see the documentation here: https://github.com/onsip/SIP.js/blob/master/docs/api/sip.js.sessionstate.md

@egreenmachine - not broken and there are multiple tests covering this case

miladmeidanshahi commented 4 years ago

Thanks @john-e-riordan, as you said Once a negative final response to the INVITE is received (the 487), the Session will transition to Terminated you can see in my log I got 487 but my Session transition is Terminating and never transition to Terminated.

john-e-riordan commented 4 years ago

Hey @miladmeidanshahi - please provide sip.js logs. The logs you provided are not sip.js logs and don't show any Session state transitions - they don't show a transition to Terminating or Terminated.

Below is an example sip.js log (from the tests) showing an example of what you should be looking for...

Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Inviter.onTrying
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.invite-dialog | INVITE dialog 7sqhrac0dgkbkq705ppnv1r8jckbsgmi0jbjo1no constructed
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Inviter.onProgress
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Inviter.cancel
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Session 7sqhrac0dgkbkq705ppnv1r8jckbsg transitioned to state Terminating
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | Alice | Emitted Terminating
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Transport | Alice Sending...
CANCEL sip:bob@example.com SIP/2.0
Via: SIP/2.0/FAKE stajsfi3jrbd.invalid;branch=z9hG4bK1431976
To: <sip:bob@example.com>
From: "Alice" <sip:alice@example.com>;tag=v1r8jckbsg
CSeq: 1 CANCEL
Call-ID: 7sqhrac0dgkbkq705ppn
Max-Forwards: 70
Supported: outbound, 100rel, replaces
User-Agent: SIP.js/0.16.1
Content-Length: 0

session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Transport | Bob Sending...
SIP/2.0 200 OK
Via: SIP/2.0/FAKE stajsfi3jrbd.invalid;branch=z9hG4bK1431976
From: "Alice" <sip:alice@example.com>;tag=v1r8jckbsg
To: <sip:bob@example.com>;tag=eh4occsntq
CSeq: 1 CANCEL
Call-ID: 7sqhrac0dgkbkq705ppn
Supported: outbound, 100rel, replaces
User-Agent: SIP.js/0.16.1
Content-Length: 0

session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Invitation | Invitation._onCancel
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Transport | Bob Sending...
SIP/2.0 487 Request Terminated
Via: SIP/2.0/FAKE stajsfi3jrbd.invalid;branch=z9hG4bK1431976
From: "Alice" <sip:alice@example.com>;tag=v1r8jckbsg
To: <sip:bob@example.com>;tag=mi0jbjo1no
CSeq: 1 INVITE
Call-ID: 7sqhrac0dgkbkq705ppn
Supported: outbound, 100rel, replaces
User-Agent: SIP.js/0.16.1
Content-Length: 0

session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Invitation | Session 7sqhrac0dgkbkq705ppnv1r8jckbsg transitioned to state Terminated
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | Bob | Emitted Terminated
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Invitation | Session 7sqhrac0dgkbkq705ppnv1r8jckbsg in state Terminated is being disposed
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Transport | Alice Sending...
ACK sip:bob@example.com SIP/2.0
Via: SIP/2.0/FAKE stajsfi3jrbd.invalid;branch=z9hG4bK1431976
To: <sip:bob@example.com>;tag=mi0jbjo1no
From: "Alice" <sip:alice@example.com>;tag=v1r8jckbsg
Call-ID: 7sqhrac0dgkbkq705ppn
CSeq: 1 ACK
Max-Forwards: 70
Content-Length: 0

session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.invite-dialog | INVITE dialog 7sqhrac0dgkbkq705ppnv1r8jckbsgmi0jbjo1no destroyed
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Inviter.onReject
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Session 7sqhrac0dgkbkq705ppnv1r8jckbsg transitioned to state Terminated
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | Alice | Emitted Terminated
session.spec.js:8825 Mon Jun 01 2020 20:15:39 GMT-0400 (Eastern Daylight Time) | sip.Inviter | Session 7sqhrac0dgkbkq705ppnv1r8jckbsg in state Terminated is being disposed
session.spec.js:8825
miladmeidanshahi commented 4 years ago

here is my log:

Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.invite
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | SessionDescriptionHandlerOptions: {}
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | initPeerConnection
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | New peer connection created
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | acquiring local media
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | acquired local media streams
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | createOffer
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | resetIceGatheringComplete
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | Setting local sdp.
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | sdp is v=0
o=- 5115209940452336662 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic: WMS Uk49IgKoL7FQiTAA0TjUXQGOh7FVSlX1lzOz
m=audio 9 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 0.0.0.0
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:Qmhp
a=ice-pwd:uONzn2e8wV74oGX3uaj+knPO
a=ice-options:trickle
a=fingerprint:sha-256 D8:98:49:B8:5E:2B:54:12:DC:A1:78:0B:53:FC:70:7B:6F:35:1A:6E:96:5E:44:65:A9:8E:7E:1B:25:7B:CD:95
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:Uk49IgKoL7FQiTAA0TjUXQGOh7FVSlX1lzOz 89785d19-5ea4-44e4-b4ca-75f8549d9efc
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:3314830801 cname:OC37l3NHpNWZ7pTr
a=ssrc:3314830801 msid:Uk49IgKoL7FQiTAA0TjUXQGOh7FVSlX1lzOz 89785d19-5ea4-44e4-b4ca-75f8549d9efc
a=ssrc:3314830801 mslabel:Uk49IgKoL7FQiTAA0TjUXQGOh7FVSlX1lzOz
a=ssrc:3314830801 label:89785d19-5ea4-44e4-b4ca-75f8549d9efc

logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | waitForIceGatheringComplete
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE is not complete. Returning promise
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | RTCIceGatheringState changed: gathering
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:211156821 1 udp 2122260223 192.168.1.5 33253 typ host generation 0 ufrag Qmhp network-id 1
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:532163938 1 udp 2122194687 192.168.10.5 33721 typ host generation 0 ufrag Qmhp network-id 2
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:1108738981 1 tcp 1518280447 192.168.1.5 9 typ host tcptype active generation 0 ufrag Qmhp network-id 1
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:1362874770 1 tcp 1518214911 192.168.10.5 9 typ host tcptype active generation 0 ufrag Qmhp network-id 2
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:3920123062 1 udp 1685987071 178.131.121.29 33721 typ srflx raddr 192.168.10.5 rport 33721 generation 0 ufrag Qmhp network-id 2
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:2781507712 1 udp 1686052607 178.131.121.29 33253 typ srflx raddr 192.168.1.5 rport 33253 generation 0 ufrag Qmhp network-id 1
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | RTCIceGatheringState changed: complete
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.Inviter | Session cdad030lgk51f2mo7j9odasais5lek transitioned to state Establishing
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate gathering complete
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.onTrying
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE Connection State changed to iceConnectionChecking
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.invite-dialog | INVITE dialog cdad030lgk51f2mo7j9odasais5lekd9b324cf-2ece-4144-a826-fe61a0e32a01 constructed
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:50 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.onProgress
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:51 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.onProgress
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:53 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.cancel
logger-factory.js?e52b:93 Sat Jun 06 2020 11:09:53 GMT+0430 (Iran Daylight Time) | sip.Inviter | Session cdad030lgk51f2mo7j9odasais5lek transitioned to state Terminating
john-e-riordan commented 4 years ago

Your log shows the CANCEL being sent and the transition to Terminating, but it does not show the receipt of the 487 to the INVITE. Until the 487 arrives, there will be no transition to Terminated (the INVITE transaction will also timeout eventually if no response is received).

You can turn on SIP message logging with the UserAgentOptions.transportOptions.sipTrace = true when creating the UserAgent. That's on by default in the most recent version, but the SIP messages are not showing up in your log.

Finally, this is not an issue/bug, please use the Google Group for support on this issue going forward - https://groups.google.com/forum/#!forum/sip_js

Thanks

miladmeidanshahi commented 4 years ago

My new log

Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.invite
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | SessionDescriptionHandlerOptions: {}
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | initPeerConnection
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | New peer connection created
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | acquiring local media
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | acquired local media streams
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | createOffer
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | resetIceGatheringComplete
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | Setting local sdp.
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | sdp is v=0
o=- 8115261592705885000 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic: WMS lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me
m=audio 9 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 0.0.0.0
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:XWFy
a=ice-pwd:BjGE0x1PALEXwrIwEODND99Q
a=ice-options:trickle
a=fingerprint:sha-256 AB:36:21:E7:50:BF:76:C5:99:E9:DE:8F:53:D5:D4:A3:2B:74:56:66:12:1B:99:55:11:02:C0:92:23:8A:7B:E6
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me 073e323a-7b9d-4b3b-8ef4-42995290c4cf
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:2628913229 cname:HfjLB9yneooerJVg
a=ssrc:2628913229 msid:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me 073e323a-7b9d-4b3b-8ef4-42995290c4cf
a=ssrc:2628913229 mslabel:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me
a=ssrc:2628913229 label:073e323a-7b9d-4b3b-8ef4-42995290c4cf

Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | waitForIceGatheringComplete
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE is not complete. Returning promise
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | RTCIceGatheringState changed: gathering
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:211156821 1 udp 2122260223 192.168.1.5 39883 typ host generation 0 ufrag XWFy network-id 1
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:532163938 1 udp 2122194687 192.168.10.5 60355 typ host generation 0 ufrag XWFy network-id 2
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:1108738981 1 tcp 1518280447 192.168.1.5 9 typ host tcptype active generation 0 ufrag XWFy network-id 1
Sat Jun 13 2020 16:16:01 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:1362874770 1 tcp 1518214911 192.168.10.5 9 typ host tcptype active generation 0 ufrag XWFy network-id 2
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:3920123062 1 udp 1685987071 188.212.247.95 13195 typ srflx raddr 192.168.10.5 rport 60355 generation 0 ufrag XWFy network-id 2
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate received: candidate:2781507712 1 udp 1686052607 188.212.247.95 49445 typ srflx raddr 192.168.1.5 rport 39883 generation 0 ufrag XWFy network-id 1
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | RTCIceGatheringState changed: complete
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Inviter | Session rjnfeo4o3dv6r3ou67b6n6qivssfac transitioned to state Establishing

INVITE sip:884@tmidomain1 SIP/2.0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK1726733;rport
To: <sip:884@tmidomain1>
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
CSeq: 1 INVITE
Call-ID: rjnfeo4o3dv6r3ou67b6
Max-Forwards: 70
Contact: <sip:l545j2jf@gagqp0ia2iec.invalid;transport=ws;ob>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER
Supported: outbound
User-Agent: milad
Content-Type: application/sdp
Content-Length: 2321

v=0
o=- 8115261592705885000 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic: WMS lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me
m=audio 13195 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 188.212.247.95
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:211156821 1 udp 2122260223 192.168.1.5 39883 typ host generation 0 network-id 1
a=candidate:532163938 1 udp 2122194687 192.168.10.5 60355 typ host generation 0 network-id 2
a=candidate:1108738981 1 tcp 1518280447 192.168.1.5 9 typ host tcptype active generation 0 network-id 1
a=candidate:1362874770 1 tcp 1518214911 192.168.10.5 9 typ host tcptype active generation 0 network-id 2
a=candidate:3920123062 1 udp 1685987071 188.212.247.95 13195 typ srflx raddr 192.168.10.5 rport 60355 generation 0 network-id 2
a=candidate:2781507712 1 udp 1686052607 188.212.247.95 49445 typ srflx raddr 192.168.1.5 rport 39883 generation 0 network-id 1
a=ice-ufrag:XWFy
a=ice-pwd:BjGE0x1PALEXwrIwEODND99Q
a=ice-options:trickle
a=fingerprint:sha-256 AB:36:21:E7:50:BF:76:C5:99:E9:DE:8F:53:D5:D4:A3:2B:74:56:66:12:1B:99:55:11:02:C0:92:23:8A:7B:E6
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me 073e323a-7b9d-4b3b-8ef4-42995290c4cf
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:2628913229 cname:HfjLB9yneooerJVg
a=ssrc:2628913229 msid:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me 073e323a-7b9d-4b3b-8ef4-42995290c4cf
a=ssrc:2628913229 mslabel:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me
a=ssrc:2628913229 label:073e323a-7b9d-4b3b-8ef4-42995290c4cf

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE candidate gathering complete
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Transport | Received WebSocket binary message:

SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK1726733;rport=59160;received=192.168.10.5
To: <sip:884@tmidomain1>;tag=9dd61ff61e802d8e2bef5f14621ef3c2.7e5f
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
CSeq: 1 INVITE
Call-ID: rjnfeo4o3dv6r3ou67b6
Proxy-Authenticate: Digest realm="tmidomain1", nonce="XuS9pl7kvHo1tQkTKkmaFVXXNfOK80ku"
Content-Length: 0

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Transport | Sending Socket message:

ACK sip:884@tmidomain1 SIP/2.0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK1726733;rport
To: <sip:884@tmidomain1>;tag=9dd61ff61e802d8e2bef5f14621ef3c2.7e5f
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
Call-ID: rjnfeo4o3dv6r3ou67b6
CSeq: 1 ACK
Max-Forwards: 70
Content-Length: 0

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Transport | Sending Socket message:

INVITE sip:884@tmidomain1 SIP/2.0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK38976;rport
To: <sip:884@tmidomain1>
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
CSeq: 2 INVITE
Call-ID: rjnfeo4o3dv6r3ou67b6
Max-Forwards: 70
Proxy-Authorization: Digest algorithm=MD5, username="103", realm="tmidomain1", nonce="XuS9pl7kvHo1tQkTKkmaFVXXNfOK80ku", uri="sip:884@tmidomain1", response="6aa586440d22a2d8bcd793c4436ff1d3"
Contact: <sip:l545j2jf@gagqp0ia2iec.invalid;transport=ws;ob>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER
Supported: outbound
User-Agent: milad
Content-Type: application/sdp
Content-Length: 2321

v=0
o=- 8115261592705885000 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic: WMS lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me
m=audio 13195 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126
c=IN IP4 188.212.247.95
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:211156821 1 udp 2122260223 192.168.1.5 39883 typ host generation 0 network-id 1
a=candidate:532163938 1 udp 2122194687 192.168.10.5 60355 typ host generation 0 network-id 2
a=candidate:1108738981 1 tcp 1518280447 192.168.1.5 9 typ host tcptype active generation 0 network-id 1
a=candidate:1362874770 1 tcp 1518214911 192.168.10.5 9 typ host tcptype active generation 0 network-id 2
a=candidate:3920123062 1 udp 1685987071 188.212.247.95 13195 typ srflx raddr 192.168.10.5 rport 60355 generation 0 network-id 2
a=candidate:2781507712 1 udp 1686052607 188.212.247.95 49445 typ srflx raddr 192.168.1.5 rport 39883 generation 0 network-id 1
a=ice-ufrag:XWFy
a=ice-pwd:BjGE0x1PALEXwrIwEODND99Q
a=ice-options:trickle
a=fingerprint:sha-256 AB:36:21:E7:50:BF:76:C5:99:E9:DE:8F:53:D5:D4:A3:2B:74:56:66:12:1B:99:55:11:02:C0:92:23:8A:7B:E6
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id
a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id
a=sendrecv
a=msid:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me 073e323a-7b9d-4b3b-8ef4-42995290c4cf
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:2628913229 cname:HfjLB9yneooerJVg
a=ssrc:2628913229 msid:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me 073e323a-7b9d-4b3b-8ef4-42995290c4cf
a=ssrc:2628913229 mslabel:lkAHmLaVZWNcyMSJ24SS6cgnJkohdowzC6Me
a=ssrc:2628913229 label:073e323a-7b9d-4b3b-8ef4-42995290c4cf

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Transport | Received WebSocket binary message:

SIP/2.0 100 trying -- your call is important to us
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK38976;rport=59160;received=192.168.10.5
To: <sip:884@tmidomain1>
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
CSeq: 2 INVITE
Call-ID: rjnfeo4o3dv6r3ou67b6
Content-Length: 0

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.onTrying
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.SessionDescriptionHandler | ICE Connection State changed to iceConnectionChecking
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Transport | Received WebSocket binary message:

SIP/2.0 180 Ringing
Call-ID: rjnfeo4o3dv6r3ou67b6
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
To: <sip:884@tmidomain1>;tag=2059cde3-3d74-4da3-a5af-f7fd43bc50e7
CSeq: 2 INVITE
Server: TMI
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Length:  0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;received=192.168.10.5;branch=z9hG4bK38976;rport=59160
Contact: <sip:atpsh-5ee4bc06-6b87-2@192.168.10.54;transport=tcp>

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.invite-dialog | INVITE dialog rjnfeo4o3dv6r3ou67b6n6qivssfac2059cde3-3d74-4da3-a5af-f7fd43bc50e7 constructed
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.onProgress
Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Transport | Received WebSocket binary message:

SIP/2.0 180 Ringing
Call-ID: rjnfeo4o3dv6r3ou67b6
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
To: <sip:884@tmidomain1>;tag=2059cde3-3d74-4da3-a5af-f7fd43bc50e7
CSeq: 2 INVITE
Server: TMI
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Length:  0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;received=192.168.10.5;branch=z9hG4bK38976;rport=59160
Contact: <sip:atpsh-5ee4bc06-6b87-2@192.168.10.54;transport=tcp>

Sat Jun 13 2020 16:16:02 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.onProgress
Sat Jun 13 2020 16:16:04 GMT+0430 (Iran Daylight Time) | sip.Inviter | Inviter.cancel
Sat Jun 13 2020 16:16:04 GMT+0430 (Iran Daylight Time) | sip.Inviter | Session rjnfeo4o3dv6r3ou67b6n6qivssfac transitioned to state Terminating
Sat Jun 13 2020 16:16:04 GMT+0430 (Iran Daylight Time) | sip.Transport | Sending Socket message:

CANCEL sip:884@tmidomain1 SIP/2.0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK38976;rport
To: <sip:884@tmidomain1>
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
CSeq: 2 CANCEL
Call-ID: rjnfeo4o3dv6r3ou67b6
Max-Forwards: 70
Supported: outbound
User-Agent: milad
Content-Length: 0

Sat Jun 13 2020 16:16:04 GMT+0430 (Iran Daylight Time) | sip.Transport | Received WebSocket binary message:

SIP/2.0 200 canceling
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;branch=z9hG4bK38976;rport=59160;received=192.168.10.5
To: <sip:884@tmidomain1>;tag=a6a1c5f60faecf035a1ae5b6e96e979a-7e5f
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
CSeq: 2 CANCEL
Call-ID: rjnfeo4o3dv6r3ou67b6
Content-Length: 0

SIP/2.0 487 Request Terminated
Call-ID: rjnfeo4o3dv6r3ou67b6
From: "Milad" <sip:103@tmidomain1>;tag=n6qivssfac
To: <sip:884@tmidomain1>;tag=2059cde3-3d74-4da3-a5af-f7fd43bc50e7
CSeq: 2 INVITE
Server: TMI
Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
Content-Length:  0
Via: SIP/2.0/TCP gagqp0ia2iec.invalid;received=192.168.10.5;branch=z9hG4bK38976;rport=59160
Contact: <sip:atpsh-5ee4bc06-6b87-2@192.168.10.54;transport=tcp>
john-e-riordan commented 4 years ago

At the very end of your log it appears like your server has sent the 200 and the 487 in the same WebSocket message. That's invalid. From the RFC: https://tools.ietf.org/html/rfc7118#section-5

   Each SIP message MUST be carried within a single WebSocket message,
   and a WebSocket message MUST NOT contain more than one SIP message.
   Because the WebSocket transport preserves message boundaries, the use
   of the Content-Length header in SIP messages is not necessary when
   they are transported using the WebSocket subprotocol.

The 487 will not get processed if this is the case and It would explain why the 487 is not resulting in state changing to established.

In any event, please use the Google Group for support on this issue going forward - https://groups.google.com/forum/#!forum/sip_js

miladmeidanshahi commented 4 years ago

OK I will post of google group, but I'm using TCP socket not web socket I debug this things many time and i understand that TCP is stream and because of that some packet merged in one message and i think sip.js parser should be able to parse multiple packet in one message.

john-e-riordan commented 4 years ago

Ah - I did not realize you were attempting to use TCP sockets.

In short, we don't currently support stream-oriented transports...

From the RFC: https://tools.ietf.org/html/rfc3261#section-18.3

   In the case of message-oriented transports (such as UDP), if the
   message has a Content-Length header field, the message body is
   assumed to contain that many bytes.  If there are additional bytes in
   the transport packet beyond the end of the body, they MUST be
   discarded.  If the transport packet ends before the end of the
   message body, this is considered an error.  If the message is a
   response, it MUST be discarded.  If the message is a request, the
   element SHOULD generate a 400 (Bad Request) response.  If the message
   has no Content-Length header field, the message body is assumed to
   end at the end of the transport packet.

   In the case of stream-oriented transports such as TCP, the Content-
   Length header field indicates the size of the body.  The Content-
   Length header field MUST be used with stream oriented transports.

The current sip.js Transport interface only supports "message-oriented" transports.

To handle a message (message transport packet), we have: https://github.com/onsip/SIP.js/blob/0.16.1/src/api/transport.ts#L88

  /**
   * Callback on receipt of a message.
   *
   * @remarks
   * When the `UserAgent` is constructed, this property is set.
   * The `state` MUST be "Connected" when this is called.
   */
  onMessage: ((message: string) => void) | undefined;

For "stream-oriented" we would need perhaps some kind of onStreamData equivalent for "stream-oriented" transports to "pump" the stream to the parser. And as you point out the parsing should be able to handle reads including multiple SIP messages (and partial SIP messages), but it not setup to handle parsing streams currently so there is work there too. A pull request would be welcome.

Alternatively you might be able to write a TCP Transport which converts the stream to messages without using a full parser? It would be kind of a hack - perhaps search for the Content-Length header and the beginning of the body etc etc. Not sure how well that would work out?

Regardless, I'll add supporting stream-oriented transports (i.e. TCP) to the TODO.