Unhandled response with Telnyx outbound

[bhbryant]

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]

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]

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:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=3Qgrppjt7je9N
Call-ID: 1fc9f187-672c-4e36-be2d-10a9b2597329
CSeq: 1 INVITE
Contact: <sip:[email protected]: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:[email protected]: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:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=3Qgrppjt7je9N
Call-ID: 1fc9f187-672c-4e36-be2d-10a9b2597329
CSeq: 1 ACK
Contact: <sip:[email protected]: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:[email protected]:5060>
To: <sip:[email protected]:5060>;tag=3Qgrppjt7je9N
Call-ID: 1fc9f187-672c-4e36-be2d-10a9b2597329
CSeq: 1 INVITE
Contact: <sip:[email protected]: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/[email protected]/livekit/livekit_sip.twirp.go:2443
github.com/livekit/protocol/livekit.(*sIPServer).serveCreateSIPParticipantProtobuf
        github.com/livekit/[email protected]/livekit/livekit_sip.twirp.go:2444
github.com/livekit/protocol/livekit.(*sIPServer).serveCreateSIPParticipant
        github.com/livekit/[email protected]/livekit/livekit_sip.twirp.go:2305
github.com/livekit/protocol/livekit.(*sIPServer).ServeHTTP
        github.com/livekit/[email protected]/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/[email protected]/negroni.go:59
github.com/urfave/negroni/v3.HandlerFunc.ServeHTTP
        github.com/urfave/negroni/[email protected]/negroni.go:33
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/[email protected]/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/[email protected]/negroni.go:51
github.com/rs/cors.(*Cors).ServeHTTP
        github.com/rs/[email protected]/cors.go:316
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/[email protected]/negroni.go:51
github.com/urfave/negroni/v3.(*Recovery).ServeHTTP
        github.com/urfave/negroni/[email protected]/recovery.go:210
github.com/urfave/negroni/v3.middleware.ServeHTTP
        github.com/urfave/negroni/[email protected]/negroni.go:51
github.com/urfave/negroni/v3.(*Negroni).ServeHTTP
        github.com/urfave/negroni/[email protected]/negroni.go:111
net/http.serverHandler.ServeHTTP
        net/http/server.go:2938
net/http.(*conn).serve
        net/http/server.go:2009

[juberti]

@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]

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