Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OnTrack not getting called on SIP INVITE #2418

Closed
elm0 opened this issue Feb 18, 2023 · 1 comment
Closed

OnTrack not getting called on SIP INVITE #2418

elm0 opened this issue Feb 18, 2023 · 1 comment

Comments

@elm0
Copy link

elm0 commented Feb 18, 2023

Hi @Sean-Der

its been a minute, hope everything is good :-)

I am trying to accept an INVITE via SIP but OnTrack never gets called.

It would be great if you could have a look over my trace. (External ips replaced with letters)

Here we go with the INVITE:

INVITE sip:197d29d5-e957-449a-891d-e0cb9f615fd9@5acc3a15-f912-4547-b86a-4bbf132181cd.invalid;transport=ws SIP/2.0
Record-Route: <sip:aa.bb.cc.dd;transport=ws;r2=on;lr>
Record-Route: <sip:aa.bb.cc.dd;r2=on;lr>
Record-Route: <sip:172.20.40.6;lr>
Record-Route: <sip:ee.ff.gg.hh;lr>
Via: SIP/2.0/WSS aa.bb.cc.dd;branch=z9hG4bK66ee.c4724b4370ecb5c3dcc00ec41e74c938.0
Via: SIP/2.0/UDP 172.20.40.6;branch=z9hG4bK66ee.6baa531ca900f277614865f0fbdc46b0.0
Via: SIP/2.0/UDP ee.ff.gg.hh;branch=z9hG4bK66ee.3c2750b4807ad16cd2b9ace0cce05e17.0
Via: SIP/2.0/UDP ii.jj.kk.ll:5060;branch=z9hG4bK3c33b85b
Max-Forwards: 67
From: <sip:15@sip.sip>;tag=as038ab825
To: <sip:12@sip.sip>
Contact: <sip:15@ii.jj.kk.ll:5060>
Call-ID: abcdefghijklmnopqrstuvwxyz@sip.sip
CSeq: 103 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces
Content-Type: application/sdp
Content-Length: ...

v=0
o=root 2060111029 2060111030 IN IP4 mm.nn.oo.pp
s=sip.sip
c=IN IP4 mm.nn.oo.pp
t=0 0
m=audio 29590 RTP/SAVPF 9 8 0 3 97 18 112 101
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:112 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=sendrecv
a=rtcp:29591
a=rtcp-mux
a=setup:actpass
a=fingerprint:sha-256 B3:E4:5B:AD:F3:69:8C:E1:C9:1B:9A:AA:34:24:48:78:E2:84:96:83:A0:3E:85:84:6E:85:82:81:58:41:65:39
a=ptime:20
a=ice-ufrag:RVBcKy8v
a=ice-pwd:59emabongM8yrR9yqrLTo2TXOi
a=candidate:iGxmvPoGN4amefTD 1 UDP 2130706431 mm.nn.oo.pp 29590 typ host
 =candidate:iGxmvPoGN4amefTD 2 UDP 2130706430 mm.nn.oo.pp 29591 typ host

followed by these:

pc INFO: 2023/02/18 12:30:59 signaling state changed to have-remote-offer
ice TRACE: 12:30:59.376780 agent.go:583: Unset selected candidate pair
pc INFO: 2023/02/18 12:30:59 signaling state changed to stable

<-gatherComplete

ice DEBUG: 12:30:59.377138 agent.go:466: Started agent: isControlling? false, remoteUfrag: "RVBcKy8v", remotePwd: "59emabongM8yrR9yqrLTo2TXOi"
ice INFO: 2023/02/18 12:30:59 Setting new connection state: Checking
pc INFO: 2023/02/18 12:30:59 ICE connection state changed: checking
ice DEBUG: 12:30:59.377583 gather.go:197: GetConn by ufrag: GiTcDzZcHXCxQgjM
ice TRACE: 12:30:59.377658 agent.go:606: pinging all candidates
ice TRACE: 12:30:59.377838 agent.go:974: ping STUN from udp4 host 172.23.0.2:10008 to udp4 host mm.nn.oo.pp:29591
ice TRACE: 12:30:59.377977 agent.go:974: ping STUN from udp4 host 172.23.0.2:10008 to udp4 host mm.nn.oo.pp:29590
ice TRACE: 12:30:59.382827 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29591 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.382923 selection.go:231: Found valid candidate pair: prio 9151314436357619712 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29591 (remote, prio 2130706430)
ice TRACE: 12:30:59.384851 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29590 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.384923 selection.go:231: Found valid candidate pair: prio 9151314440652587007 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)
ice TRACE: 12:30:59.407757 agent.go:606: pinging all candidates
ice TRACE: 12:30:59.407865 agent.go:974: ping STUN from udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 to udp4 host mm.nn.oo.pp:29591
ice TRACE: 12:30:59.407976 agent.go:974: ping STUN from udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 to udp4 host mm.nn.oo.pp:29590

maybe the problem is in my OK message and thats why no audio is coming from the gateway:

SIP/2.0 200 OK
Via: SIP/2.0/WSS aa.bb.cc.dd;branch=z9hG4bK66ee.c4724b4370ecb5c3dcc00ec41e74c938.0
Via: SIP/2.0/UDP 172.20.40.6;branch=z9hG4bK66ee.6baa531ca900f277614865f0fbdc46b0.0
Via: SIP/2.0/UDP ee.ff.gg.hh;branch=z9hG4bK66ee.3c2750b4807ad16cd2b9ace0cce05e17.0
Via: SIP/2.0/UDP ii.jj.kk.ll:5060;branch=z9hG4bK3c33b85b
From: <sip:15@sip.sip>;tag=as038ab825
Call-ID: abcdefghijklmnopqrstuvwxyz@sip.sip
CSeq: 103 INVITE
Content-Type: application/sdp
Contact: <sip:197d29d5-e957-449a-891d-e0cb9f615fd9@5acc3a15-f912-4547-b86a-4bbf132181cd.invalid;transport=ws>
Record-Route: <sip:aa.bb.cc.dd;transport=ws;r2=on;lr>
Record-Route: <sip:aa.bb.cc.dd;r2=on;lr>
Record-Route: <sip:172.20.40.6;lr>
Record-Route: <sip:ee.ff.gg.hh;lr>
Supported: path, replaces, outbound, timer, norefersub, ice
To: <sip:12@sip.sip>;tag=f0bc1b17-e3ff-4ba3-bea8-06a6201f569e
Content-Length: ...

v=0
o=- 720493735151942694 1676723459 IN IP4 0.0.0.0
s=-
t=0 0
a=fingerprint:sha-256 6D:22:F6:6D:77:69:3A:FA:CA:28:9A:EF:D4:3C:D7:90:C7:BC:3B:DF:33:65:B6:92:32:3B:8D:D1:1F:05:B3:12
a=group:BUNDLE 0
m=audio 9 UDP/TLS/RTP/SAVPF 0
c=IN IP4 0.0.0.0
a=setup:active
a=mid:0
a=ice-ufrag:GiTcDzZcHXCxQgjM
a=ice-pwd:RbeMTqzXvouYXWTlNHyojnICSuJnRBQL
a=rtcp-mux
a=rtcp-rsize
a=rtpmap:0 PCMU/8000
a=ssrc:1917240452 cname:BbINqxxFMkzdNqlH
a=ssrc:1917240452 msid:BbINqxxFMkzdNqlH NaVfZFMdzVimUwIA
a=ssrc:1917240452 mslabel:BbINqxxFMkzdNqlH
a=ssrc:1917240452 label:NaVfZFMdzVimUwIA
a=msid:BbINqxxFMkzdNqlH NaVfZFMdzVimUwIA
a=sendrecv
a=candidate:4237655428 1 udp 2130706431 172.23.0.2 10008 typ host
a=candidate:4237655428 2 udp 2130706431 172.23.0.2 10008 typ host
a=candidate:4073560724 1 udp 1694498815 ww.xx.yy.zz 10092 typ srflx raddr 0.0.0.0 rport 10092
a=candidate:4073560724 2 udp 1694498815 ww.xx.yy.zz 10092 typ srflx raddr 0.0.0.0 rport 10092
 =end-of-candidates

and the trace following that:

ice TRACE: 12:30:59.412887 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29590 to udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092
ice TRACE: 12:30:59.412932 selection.go:231: Found valid candidate pair: prio 7277816996102668288 (local, prio 1694498815) udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)
ice TRACE: 12:30:59.414639 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29591 to udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092
ice TRACE: 12:30:59.414677 selection.go:231: Found valid candidate pair: prio 7277816996102668286 (local, prio 1694498815) udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 <-> udp4 host mm.nn.oo.pp:29591 (remote, prio 2130706430)
ice TRACE: 12:30:59.416288 agent.go:1124: inbound STUN (Request) from mm.nn.oo.pp:29591 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.416413 agent.go:974: ping STUN from udp4 host 172.23.0.2:10008 to udp4 host mm.nn.oo.pp:29591
ice TRACE: 12:30:59.421301 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29591 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.421338 selection.go:231: Found valid candidate pair: prio 9151314436357619712 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29591 (remote, prio 2130706430)
ice TRACE: 12:30:59.424724 agent.go:1124: inbound STUN (Request) from mm.nn.oo.pp:29590 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.424853 agent.go:974: ping STUN from udp4 host 172.23.0.2:10008 to udp4 host mm.nn.oo.pp:29590

receiving the remote ACK in between:

ACK sip:197d29d5-e957-449a-891d-e0cb9f615fd9@5acc3a15-f912-4547-b86a-4bbf132181cd.invalid;transport=ws SIP/2.0
Via: SIP/2.0/WSS aa.bb.cc.dd;branch=z9hG4bK66ee.1132227567a53f185249d7ff0d113ab3.0
Via: SIP/2.0/UDP 172.20.40.6;branch=z9hG4bK66ee.ea8f57a0bf28b48a3393353e39b62947.0
Via: SIP/2.0/UDP ee.ff.gg.hh;branch=z9hG4bK66ee.b92327116414ef5921a1236e0693cb6f.0
Via: SIP/2.0/UDP ii.jj.kk.ll:5060;branch=z9hG4bK4db1f45f
Max-Forwards: 67
From: <sip:15@sip.sip>;tag=as038ab825
To: <sip:12@sip.sip>;tag=f0bc1b17-e3ff-4ba3-bea8-06a6201f569e
Contact: <sip:15@ii.jj.kk.ll:5060>
Call-ID: abcdefghijklmnopqrstuvwxyz@sip.sip
CSeq: 103 ACK
Content-Length: 0

and more TRACEs:

ice TRACE: 12:30:59.431696 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29590 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.431733 selection.go:231: Found valid candidate pair: prio 9151314440652587007 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)
ice TRACE: 12:30:59.444637 agent.go:1124: inbound STUN (Request) from mm.nn.oo.pp:29591 to udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092
ice TRACE: 12:30:59.444757 agent.go:974: ping STUN from udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 to udp4 host mm.nn.oo.pp:29591
ice TRACE: 12:30:59.451734 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29591 to udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092
ice TRACE: 12:30:59.451771 selection.go:231: Found valid candidate pair: prio 7277816996102668286 (local, prio 1694498815) udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 <-> udp4 host mm.nn.oo.pp:29591 (remote, prio 2130706430)
ice TRACE: 12:30:59.462843 agent.go:1124: inbound STUN (Request) from mm.nn.oo.pp:29590 to udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092
ice TRACE: 12:30:59.462968 agent.go:974: ping STUN from udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 to udp4 host mm.nn.oo.pp:29590
ice TRACE: 12:30:59.468088 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29590 to udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092
ice TRACE: 12:30:59.468126 selection.go:231: Found valid candidate pair: prio 7277816996102668288 (local, prio 1694498815) udp4 srflx ww.xx.yy.zz:10092 related 0.0.0.0:10092 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)
ice TRACE: 12:30:59.531822 agent.go:1124: inbound STUN (Request) from mm.nn.oo.pp:29590 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.531880 agent.go:589: Set selected candidate pair: prio 9151314440652587007 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)
ice INFO: 2023/02/18 12:30:59 Setting new connection state: Connected
ice TRACE: 12:30:59.532073 agent.go:974: ping STUN from udp4 host 172.23.0.2:10008 to udp4 host mm.nn.oo.pp:29590
dtls TRACE: 12:30:59.532169 handshaker.go:173: [handshake:client] Flight 1: Preparing
dtls TRACE: 12:30:59.532226 handshaker.go:173: [handshake:client] Flight 1: Sending
pc INFO: 2023/02/18 12:30:59 ICE connection state changed: connected
dtls TRACE: 12:30:59.532276 conn.go:397: [handshake:client] -> ClientHello (epoch: 0, seq: 0)

here the OnICEConnectionStateChange gets called and is connected

dtls TRACE: 12:30:59.532440 handshaker.go:173: [handshake:client] Flight 1: Waiting
ice TRACE: 12:30:59.538784 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29590 to udp4 host 172.23.0.2:10008
ice TRACE: 12:30:59.538819 selection.go:231: Found valid candidate pair: prio 9151314440652587007 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)
dtls TRACE: 12:30:59.539771 flight3handler.go:87: [handshake] use cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
dtls TRACE: 12:30:59.540246 handshaker.go:289: [handshake:client] Flight 1 -> Flight 5
dtls TRACE: 12:30:59.540268 handshaker.go:173: [handshake:client] Flight 5: Preparing
dtls TRACE: 12:30:59.541104 handshaker.go:241: [handshake:client] -> changeCipherSpec (epoch: 1)
dtls TRACE: 12:30:59.541129 handshaker.go:173: [handshake:client] Flight 5: Sending
dtls TRACE: 12:30:59.541146 conn.go:397: [handshake:client] -> TypeCertificate (epoch: 0, seq: 1)
dtls TRACE: 12:30:59.541177 conn.go:397: [handshake:client] -> ClientKeyExchange (epoch: 0, seq: 2)
dtls TRACE: 12:30:59.541196 conn.go:397: [handshake:client] -> CertificateVerify (epoch: 0, seq: 3)
dtls TRACE: 12:30:59.541222 conn.go:397: [handshake:client] -> Finished (epoch: 1, seq: 4)
dtls TRACE: 12:30:59.541394 handshaker.go:173: [handshake:client] Flight 5: Waiting
dtls TRACE: 12:30:59.549608 conn.go:753: client: <- ChangeCipherSpec (epoch: 1)
dtls TRACE: 12:30:59.549735 handshaker.go:289: [handshake:client] Flight 5 -> Flight 5
dtls TRACE: 12:30:59.549760 handshaker.go:173: [handshake:client] Flight 5: Finished
dtls TRACE: 12:30:59.549791 conn.go:226: Handshake Completed
pc INFO: 2023/02/18 12:30:59 peer connection state changed: connected

now the OnConnectionStateChange is also connected

i am getting one of these:

ice TRACE: 12:30:59.609017 selection.go:173: checking keepalive

and those keep repeating until CTRL-C

ice TRACE: 12:31:01.610210 selection.go:173: checking keepalive
ice TRACE: 12:31:01.610332 agent.go:974: ping STUN from udp4 host 172.23.0.2:10008 to udp4 host mm.nn.oo.pp:29590
ice TRACE: 12:31:01.617072 selection.go:221: inbound STUN (SuccessResponse) from udp4 host mm.nn.oo.pp:29590 to udp4 host 172.23.0.2:10008
ice TRACE: 12:31:01.617112 selection.go:231: Found valid candidate pair: prio 9151314440652587007 (local, prio 2130706431) udp4 host 172.23.0.2:10008 <-> udp4 host mm.nn.oo.pp:29590 (remote, prio 2130706431)

Any help is highly appreciated!

Thanks in advance and keep up the amazing work!
@Sean-Der
Copy link
Member

Sean-Der commented May 9, 2024

Really sorry @elm0 that I didn't respond to this sooner! Hopefully you were able to get it working.

If not I would love to help debug. I will do a better job of staying on top of this bug tracker going forward.

@Sean-Der Sean-Der closed this as not planned Won't fix, can't repro, duplicate, stale May 9, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@elm0 @Sean-Der