search

livekit / sip

SIP to WebRTC bridge for LiveKit
119 stars 27 forks source link

Unable to originate outbound calls #110

Closed vlxdisluv closed 4 months ago

vlxdisluv commented 4 months ago

I configured Twilio following the LiveKit quick start documentation, except for the Dispatch Rule, which I understood is only needed for inbound calls. Everything is configured locally in Docker. I received the error "transaction failed to complete" after trying to run an outbound call using livekit-cli create-sip-participant --request sipParticipant.json. My logs are as follows:

2024-06-17T15:09:39.933Z    INFO    sip sip/client.go:118   Creating SIP participant    {"nodeID": "NE_WfjFk34ZLTjX", "roomName": "my-sip-room", "from": "+15306257766", "to": "+77056550833", "address": "test-call-agent.pstn.twilio.com"}
2024-06-17T15:09:39.935Z    DEBUG   sip sip/outbound.go:184 begin listening on UDP  {"nodeID": "NE_WfjFk34ZLTjX", "port": 10034}
2024-06-17T15:09:39.964Z    DEBUG   logger/logger.go:256    Using ICE servers   {"nodeID": "NE_WfjFk34ZLTjX", "servers": [{"urls":["stun:global.stun.twilio.com:3478","stun:stun.l.google.com:19302","stun:stun1.l.google.com:19302"]}]}
2024-06-17T15:09:39.965Z    DEBUG   logger/logger.go:256    received offer for subscriber   {"nodeID": "NE_WfjFk34ZLTjX"}
2024-06-17T15:09:39.967Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:2828497386 1 udp 2130706431 172.18.0.3 30005 typ host"}
2024-06-17T15:09:39.967Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:358875146 1 tcp 1671430143 172.18.0.3 7881 typ host tcptype passive"}
2024-06-17T15:09:39.967Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:448245242 1 udp 2130706431 172.18.0.4 53496 typ host"}
2024-06-17T15:09:40.036Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 26423 typ srflx raddr 0.0.0.0 rport 55394"}
2024-06-17T15:09:40.037Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 55294 typ srflx raddr 0.0.0.0 rport 36437"}
2024-06-17T15:09:40.039Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 22980 typ srflx raddr 0.0.0.0 rport 36168"}
2024-06-17T15:09:40.039Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 12196 typ srflx raddr 0.0.0.0 rport 45172"}
2024-06-17T15:09:40.053Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 27709 typ srflx raddr 0.0.0.0 rport 45338"}
2024-06-17T15:09:40.055Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "SUBSCRIBER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 10337 typ srflx raddr 0.0.0.0 rport 42859"}
2024-06-17T15:09:41.064Z    DEBUG   logger/logger.go:256    ICE connected   {"nodeID": "NE_WfjFk34ZLTjX", "iceCandidatePair": "(local) udp4 host 172.18.0.4:53496 <-> (remote) udp4 host 172.18.0.3:30005"}
2024-06-17T15:09:41.067Z    INFO    logger/logger.go:260    published track {"nodeID": "NE_WfjFk34ZLTjX", "name": "Test call", "source": "MICROPHONE"}
2024-06-17T15:09:41.217Z    DEBUG   logger/logger.go:256    starting to negotiate   {"nodeID": "NE_WfjFk34ZLTjX"}
2024-06-17T15:09:41.219Z    DEBUG   logger/logger.go:256    create offer    {"nodeID": "NE_WfjFk34ZLTjX", "offer": "v=0\r\no=- 7744285721304771371 1718636981 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=fingerprint:sha-256 AC:DB:E3:86:8B:63:DF:3E:CD:3A:0E:CD:7F:A2:DD:5E:D0:1F:1F:4F:8F:D8:80:59:F6:D1:EA:4C:29:23:6C:D8\r\na=extmap-allow-mixed\r\na=group:BUNDLE 0 1\r\nm=audio 9 UDP/TLS/RTP/SAVPF 111 9 0 8\r\nc=IN IP4 0.0.0.0\r\na=setup:actpass\r\na=mid:0\r\na=ice-ufrag:sQzGtWeViPbBJIJt\r\na=ice-pwd:ETCPagNBCZnHnEFQGIGhnFbIOgMzISzK\r\na=rtcp-mux\r\na=rtcp-rsize\r\na=rtpmap:111 opus/48000/2\r\na=fmtp:111 minptime=10;useinbandfec=1\r\na=rtcp-fb:111 transport-cc \r\na=rtpmap:9 G722/8000\r\na=rtcp-fb:9 transport-cc \r\na=rtpmap:0 PCMU/8000\r\na=rtcp-fb:0 transport-cc \r\na=rtpmap:8 PCMA/8000\r\na=rtcp-fb:8 transport-cc \r\na=extmap:4 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01\r\na=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level\r\na=ssrc:320214751 cname:pion\r\na=ssrc:320214751 msid:pion audio\r\na=ssrc:320214751 mslabel:pion\r\na=ssrc:320214751 label:audio\r\na=msid:pion audio\r\na=sendonly\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 0.0.0.0\r\na=setup:actpass\r\na=mid:1\r\na=sendrecv\r\na=sctp-port:5000\r\na=ice-ufrag:sQzGtWeViPbBJIJt\r\na=ice-pwd:ETCPagNBCZnHnEFQGIGhnFbIOgMzISzK\r\n"}
2024-06-17T15:09:41.219Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:448245242 1 udp 2130706431 172.18.0.4 40257 typ host"}
2024-06-17T15:09:41.223Z    DEBUG   logger/logger.go:256    successfully set publisher answer   {"nodeID": "NE_WfjFk34ZLTjX"}
2024-06-17T15:09:41.225Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:2828497386 1 udp 2130706431 172.18.0.3 30006 typ host"}
2024-06-17T15:09:41.225Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:358875146 1 tcp 1671430143 172.18.0.3 7881 typ host tcptype passive"}
2024-06-17T15:09:41.291Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 49211 typ srflx raddr 0.0.0.0 rport 51823"}
2024-06-17T15:09:41.294Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 62057 typ srflx raddr 0.0.0.0 rport 35085"}
2024-06-17T15:09:41.295Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 14898 typ srflx raddr 0.0.0.0 rport 60756"}
2024-06-17T15:09:41.298Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 22251 typ srflx raddr 0.0.0.0 rport 41563"}
2024-06-17T15:09:41.307Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 14344 typ srflx raddr 0.0.0.0 rport 43804"}
2024-06-17T15:09:41.307Z    DEBUG   logger/logger.go:256    local ICE candidate {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 57876 typ srflx raddr 0.0.0.0 rport 43276"}
2024-06-17T15:10:13.234Z    ERROR   sip sip/outbound.go:300 SIP invite failed{"nodeID": "NE_WfjFk34ZLTjX", "error": "transaction failed to complete"}
github.com/livekit/sip/pkg/sip.(*outboundCall).sipSignal
    /workspace/pkg/sip/outbound.go:300
github.com/livekit/sip/pkg/sip.(*outboundCall).updateSIP
    /workspace/pkg/sip/outbound.go:214
github.com/livekit/sip/pkg/sip.(*outboundCall).UpdateSIP
    /workspace/pkg/sip/outbound.go:163
github.com/livekit/sip/pkg/sip.(*Client).CreateSIPParticipant.func1
    /workspace/pkg/sip/client.go:132
2024-06-17T15:10:13.235Z    ERROR   sip sip/client.go:141   SIP call failed {"nodeID": "NE_WfjFk34ZLTjX", "roomName": "my-sip-room", "from": "+15306257766", "to": "+77056550833", "address": "test-call-agent.pstn.twilio.com", "error": "update SIP failed: transaction failed to complete"}
github.com/livekit/sip/pkg/sip.(*Client).CreateSIPParticipant.func1
    /workspace/pkg/sip/client.go:141

Do you have any ideas on what might be causing this issue and how to fix it? Or is it necessary to deploy everything on a server to make such calls?

Sometimes, the logs look as follows:

2024-06-17T15:36:46.305Z    DEBUG   logger/logger.go:256    remote ICE candidate    {"nodeID": "NE_WfjFk34ZLTjX", "target": "PUBLISHER", "candidate": "candidate:1665556344 1 udp 1694498815 5.34.4.2 50129 typ srflx raddr 0.0.0.0 rport 59246"}
2024-06-17T15:36:47.451Z    ERROR   sip sip/outbound.go:300 SIP invite failed{"nodeID": "NE_WfjFk34ZLTjX", "error": "Unexpected StatusCode from INVITE response 403"}
github.com/livekit/sip/pkg/sip.(*outboundCall).sipSignal
    /workspace/pkg/sip/outbound.go:300
github.com/livekit/sip/pkg/sip.(*outboundCall).updateSIP
    /workspace/pkg/sip/outbound.go:214
github.com/livekit/sip/pkg/sip.(*outboundCall).UpdateSIP
    /workspace/pkg/sip/outbound.go:163
github.com/livekit/sip/pkg/sip.(*Client).CreateSIPParticipant.func1
    /workspace/pkg/sip/client.go:132
2024-06-17T15:36:47.451Z    ERROR   sip sip/client.go:141   SIP call failed {"nodeID": "NE_WfjFk34ZLTjX", "roomName": "my-sip-room", "from": "+15306257766", "to": "+77056550833", "address": "test-call-agent.pstn.twilio.com", "error": "update SIP failed: Unexpected StatusCode from INVITE response 403"}
github.com/livekit/sip/pkg/sip.(*Client).CreateSIPParticipant.func1
    /workspace/pkg/sip/client.go:141
dennwc commented 4 months ago

Or is it necessary to deploy everything on a server to make such calls?

It's not necessary to run on a server, but you need to port-forward SIP signaling port and media port range from your router to your machine. The first part of the logs looks like the port is not open/forwarded.

The second one looks different, though. You can see in the logs that the server you are dialing responds with status 403 (Forbidden). It probably means you haven't set authentication correctly in the Trunk or Trunk Provider.

vlxdisluv commented 4 months ago

@dennwc thanks, you are right. I should have opened the port on my router and specified the IP in the ACL of the SIP trunk provider.