search

livekit / sip

SIP to WebRTC bridge for LiveKit
124 stars 28 forks source link

Unhandled response with Telnyx outbound #49

Open bhbryant opened 10 months ago

bhbryant commented 10 months ago

Hi,

I'm attempting to connect over a Telnyx trunk to a my dev server.

The outgoing call works fine, but once connected I am receiving Unhandled sip response. UnhandledResponseHandler handler not added errors.

Any Suggestions / pointers on debuging?

Thanks, Ben

Logs

2024-01-12T15:36:19.013-0800    INFO    sip     sip/client.go:106       Updating SIP participant       {"nodeID": "NE_cygnRBcqnMLS", "roomName": "test-room", "participant": "SP_S7jCVkQAEMg5", "from": "+REDACTED", "to": "+REDACTED", "address": "sip.telnyx.com"}
2024-01-12T15:36:19.040-0800    INFO    logger/logger.go:250    received offer for subscriber  {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:19.066-0800    INFO    logger/logger.go:250    ICE connected   {"nodeID": "NE_cygnRBcqnMLS", "iceCandidatePair": "(local) udp6 host [fd8c:10a8:6c3e:3c55:14a8:dbf8:eb92:12c]:50227 <-> (remote) udp6 host [fd8c:10a8:6c3e:3c55:14a8:dbf8:eb92:12c]:56016"}
2024-01-12T15:36:19.094-0800    INFO    logger/logger.go:250    published track {"nodeID": "NE_cygnRBcqnMLS", "name": "test-caller", "source": "MICROPHONE"}
2024-01-12T15:36:19.243-0800    INFO    logger/logger.go:250    received offer for subscriber  {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:19.247-0800    INFO    logger/logger.go:250    successfully set publisher answer      {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:19.249-0800    INFO    logger/logger.go:250    track subscribed      {"nodeID": "NE_cygnRBcqnMLS", "participant": "test-user", "track": "TR_AM5HCubGH3ZuD7", "kind": "audio"}
2024-01-12T15:36:25.962-0800    INFO    sip     sip/outbound.go:152     Outbound SIP update complete   {"nodeID": "NE_cygnRBcqnMLS", "roomName": "test-room", "from": "+REDACTED", "to": "+REDACTED", "address": "sip.telnyx.com"}
2024-01-12T15:36:26.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:27.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:29.476-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:33.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:37.565-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:41.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:45.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:49.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:51.064-0800    INFO    logger/logger.go:250    received offer for subscriber  {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:53.540-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:36:57.462-0800    INFO    sip     sip/service.go:38       Unhandled sip response. UnhandledResponseHandler handler not added     {"nodeID": "NE_cygnRBcqnMLS"}
2024-01-12T15:37:16.411-0800    INFO    sip     sip/client.go:98        Disconnect SIP participant     {"nodeID": "NE_cygnRBcqnMLS", "roomName": "test-room", "participant": "SP_S7jCVkQAEMg5"}

Config Sip bridge config:

log_level: debug
api_key: devkey
api_secret: secret
ws_url: ws://localhost:7880
redis:
  address: localhost:6379

Trunk config:

{
    "inbound_addresses": [
        "192.76.120.10",
        "64.16.250.10"
    ],
    "outbound_address": "sip.telnyx.com",
    "outbound_number": "+REDACTED",
    "inbound_numbers_regex": [],
    "inbound_username": "",
    "inbound_password": "",
    "outbound_username": "REDACTED",
    "outbound_password": "REDACTED"
}

Add Partcipant:

{
    "sipTrunkId": "ST_HyDRZMFvH5hv",
    "sipCallTo": "+REDACTED",
    "roomName": "test-room",
    "participantIdentity": "test-caller"
}
dennwc commented 10 months ago

Thank you for a detailed report!

Usually these messages are BYE requests sent by remote after we terminate the call on our side. Because of the way we use sipgo library, it thinks of these as unhandled. Will eventually fix it. As long as the call works properly, nothing to worry about.

But it's definitely not nice that these logs appear. The fact that they repeat means that we do not ACK the message and the remote retries it. That's something we should do.

bhbryant commented 10 months ago

Thanks @dennwc -- really appreciate the quick response. Unfortunately, call is not working.

I see what you mean re. BYE and how sipgo responds to an unhandled response. It is the same mechanism producing to the unhandled error, but the source appears to be a problem elsewhere.

further observations I did some further digging, and it seems that the Telnyx trunk is sending multiple 200 OK responses to the INVITE sequence.

When, the first 200 response is receive, sipgo has a matching client transaction registered, and correctly returns an ACK message. This appears to be as expected.

However, it appears Telnyx continues to send the same INVITE message -- as the client transaction was previously cleared following the initial ACK, the repeat INVITE messages are unhandled and cause the error (as would be expected).

That said, I don't think this is the actual source of my call error, but rather a result of another error -- upon digging into the livekit-server logs, it appears there is a request error when updating the SIP participant that occurs a second or two earlier (soon after the outbound is initiated).

I haven't had time to fully dig into it, and imagine it's a configuration problem, but I'll pass it along the error log with the call stack on the off chance it's relevant.

Thanks again,

Ben

relevant SIP/SDP messages

SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.11:5060;rport=33733;received=REDACTED;branch=z9hG4bK.gxbWA4qd1L9IZyOh;alias
Record-Route: <sip:10.255.0.1;r2=on;lr>
Record-Route: <sip:192.76.120.10;r2=on;lr>
From: <sip:+REDACTED@192.168.1.11:5060>
To: <sip:+REDACTED@sip.telnyx.com:5060>;tag=3Qgrppjt7je9N
Call-ID: 1fc9f187-672c-4e36-be2d-10a9b2597329
CSeq: 1 INVITE
Contact: <sip:+REDACTED@10.13.177.4:5070;transport=udp>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REFER, NOTIFY
Supported: path
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 306

v=0
o=FreeSWITCH 1705081234 1705081235 IN IP4 64.16.227.45
s=FreeSWITCH
c=IN IP4 64.16.227.45
t=0 0
m=audio 22532 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=silenceSupp:off - - - -
a=ptime:20
a=mid:audio
a=rtcp:22533 IN IP4 64.16.227.45
ACK sip:+REDACTED@10.13.177.4:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.1.11:5060;alias;branch=z9hG4bK.UMQF1n1IhWHjZSax
Record-Route: <sip:192.76.120.10;r2=on;lr>
Record-Route: <sip:10.255.0.1;r2=on;lr>
Max-Forwards: 70
From: <sip:+REDACTED@192.168.1.11:5060>
To: <sip:+REDACTED@sip.telnyx.com:5060>;tag=3Qgrppjt7je9N
Call-ID: 1fc9f187-672c-4e36-be2d-10a9b2597329
CSeq: 1 ACK
Contact: <sip:+REDACTED@192.168.1.11:5060>
Content-Length: 0
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.11:5060;rport=33733;received=REDACTED;branch=z9hG4bK.gxbWA4qd1L9IZyOh;alias
Record-Route: <sip:10.255.0.1;r2=on;lr>
Record-Route: <sip:192.76.120.10;r2=on;lr>
From: <sip:+REDACTED@192.168.1.11:5060>
To: <sip:+REDACTED@sip.telnyx.com:5060>;tag=3Qgrppjt7je9N
Call-ID: 1fc9f187-672c-4e36-be2d-10a9b2597329
CSeq: 1 INVITE
Contact: <sip:+REDACTED@10.13.177.4:5070;transport=udp>
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REFER, NOTIFY
Supported: path
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 306

v=0
o=FreeSWITCH 1705081234 1705081235 IN IP4 64.16.227.45
s=FreeSWITCH
c=IN IP4 64.16.227.45
t=0 0
m=audio 22532 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
a=silenceSupp:off - - - -
a=ptime:20
a=mid:audio
a=rtcp:22533 IN IP4 64.16.227.45

Livekit Server: Update SIP participant error

2024-01-13T23:40:14.480-0800    ERROR   livekit service/sip.go:199      cannot update sip participant   {"error": "request timed out"}
github.com/livekit/livekit-server/pkg/service.(*SIPService).updateParticipant
        github.com/livekit/livekit-server/pkg/service/sip.go:199
github.com/livekit/livekit-server/pkg/service.(*SIPService).CreateSIPParticipant
        github.com/livekit/livekit-server/pkg/service/sip.go:175
github.com/livekit/protocol/livekit.(*sIPServer).serveCreateSIPParticipantProtobuf.func2
        github.com/livekit/protocol@v1.9.4-0.20231221100346-e9e5fcd7d371/livekit/livekit_sip.twirp.go:2443
github.com/livekit/protocol/livekit.(*sIPServer).serveCreateSIPParticipantProtobuf
        github.com/livekit/protocol@v1.9.4-0.20231221100346-e9e5fcd7d371/livekit/livekit_sip.twirp.go:2444
github.com/livekit/protocol/livekit.(*sIPServer).serveCreateSIPParticipant
        github.com/livekit/protocol@v1.9.4-0.20231221100346-e9e5fcd7d371/livekit/livekit_sip.twirp.go:2305
github.com/livekit/protocol/livekit.(*sIPServer).ServeHTTP
        github.com/livekit/protocol@v1.9.4-0.20231221100346-e9e5fcd7d371/livekit/livekit_sip.twirp.go:1197
net/http.(*ServeMux).ServeHTTP
        net/http/server.go:2514
github.com/urfave/negroni/v3.(*Negroni).UseHandler.Wrap.func1
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:59
github.com/urfave/negroni/v3.HandlerFunc.ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:33
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:51
net/http.HandlerFunc.ServeHTTP
        net/http/server.go:2136
github.com/livekit/livekit-server/pkg/service.(*APIKeyAuthMiddleware).ServeHTTP
        github.com/livekit/livekit-server/pkg/service/auth.go:99
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:51
github.com/rs/cors.(*Cors).ServeHTTP
        github.com/rs/cors@v1.10.1/cors.go:316
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:51
github.com/urfave/negroni/v3.(*Recovery).ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/recovery.go:210
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:51
github.com/urfave/negroni/v3.(*Negroni).ServeHTTP
        github.com/urfave/negroni/v3@v3.0.0/negroni.go:111
net/http.serverHandler.ServeHTTP
        net/http/server.go:2938
net/http.(*conn).serve
        net/http/server.go:2009
juberti commented 9 months ago

@bhbryant did you ever try to get inbound calls (from user to a hosted phone number) routed from Telnyx to LiveKit? It sounds like you're just focused on outbound here but wondering if you were also able to get inbound working.

bhbryant commented 9 months ago

@juberti -- it's on my todo list, but I haven't tried setting up yet.