Generated `100 Trying` uses only request source instead of `Via` header as destination

[bv-ngv]

For SIP INVITEs, sipgo's server transaction automatically generates and sends a 100 Trying provisional response after the transaction's timer_1xx expires:

sipgo/sip/transaction_server_tx.go

Lines 55 to 66 in 3329965

	tx.timer_1xx = time.AfterFunc(Timer_1xx, func() {
	trying := NewResponseFromRequest(
	tx.Origin(),
	100,
	"Trying",
	nil,
	)
	// tx.Log().Trace("timer_1xx fired")
	if err := tx.Respond(trying); err != nil {
	tx.log.Error("send '100 Trying' response failed", "error", err, "tx", tx.Key())
	}
	})

However, this happens (in NewResponseFromRequest) solely based on the request's source address and does not take its Via header into account:

sipgo/sip/response.go

Line 252 in 3329965

res.SetDestination(req.Source())

Thus, the request's sender may not receive the 100 Trying at all if they are not reachable or ready to receive responses at the request's source address. Correct me if I'm wrong, but as far as I understand, all responses (including provisional ones) should use the Via header for this.

[emiago]

Hi @bv-ngv , yeah it is some leftover, but now I see it needs to be addressed. SIP has different recommendations depending on protocol. This will be covered in next commits. ALready have some fixes.

[emiago]

Hi @bv-ngv current main branch now has fixes, that is RFC 18.2.2 .
Normally your case is affected because of UDP, so it was overlooked.
This needs more testing, so pls give some feedbak

[bv-ngv]

Thanks for your quick response! I just gave 7aff731 a go, but it appears the changes introduced an issue when obtaining the server transaction's local address (that the request was received on).

We are implementing a SIP proxy and have this snippet in our codebase:

receivedOnAddress := serverTx.Connection().LocalAddr()

Our concrete use for this is so that we can include a parameter with the received-on address in the Path header added by our proxy to later refer back to (via the pre-loaded Route header) when routing requests from upstream to the UE via the interface it originally registered over (without having to hold state ourselves).

The snippet above now returns an empty Addr.

Anyway, working around this and focusing only on the updated 100 Trying handling, it seems like the raddr set here:

sipgo/sip/transport_layer.go

Line 418 in 7aff731

req.raddr = raddr

is nil by the time the provisional response is sent:

sipgo/sip/response.go

Lines 252 to 257 in 7aff731

	// If raddr is present this is resolved remote addr based on via header, otherwise use connection based source addr
	if req.raddr.IP != nil {
	res.SetDestination(req.raddr.String())
	} else {
	res.SetDestination(req.Source())
	}

This enters the second branch, causing the behavior to be unchanged compared to before.

When I set a breakpoint at line 170 in transaction_layer.go:

sipgo/sip/transaction_layer.go

Lines 160 to 172 in 7aff731

	func (txl *TransactionLayer) serverTxCreate(req *Request, key string) (*ServerTx, error) {
	// Connection must exist by transport layer or it will be created
	// What if connection setup can not be made fast enough?
	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
	defer cancel()
	conn, err := txl.tpl.serverRequestConnection(ctx, req)
	if err != nil {
	return nil, fmt.Errorf("server tx get connection failed: %w", err)
	}
	tx := NewServerTx(key, req, conn, txl.log)
	return tx, tx.Init()
	}

I can see that the raddr was indeed set correctly on req, but the tx's origin request (which is used for the 100 Trying) still has its raddr set to nil.

[emiago]

Now covered with test and fixed.

[bv-ngv]

It appears the 100 Trying is now correctly sent to the address in the Via header with f835338. 👍

The newly introduced issue regarding serverTx.Connection().LocalAddr() returning an empty Addr remains, however.

[emiago]

he newly introduced issue regarding serverTx.Connection().LocalAddr() returning an empty Addr remains, however.

I hardly see what this could influence, can you share more details. Which transport, how are you checking this.

[bv-ngv]

Sure! I'm basically creating a sipgo.UA, Server, and Client per the proxy example.

I then register a handler on the server using server.On<Method>(HandleRequest) and bind it to multiple local addresses for both UDP and TCP via ListenAndServe() (in goroutines, as that call itself is blocking).

Within the handler, I do the following:

func HandleRequest(req *sip.Request, serverTransaction sip.ServerTransaction) {
    // `Connection()` is defined only on the concrete `ServerTx` struct,
    // not the interface, so we need a type assertion
    serverTx, ok := serverTransaction.(*sip.ServerTx)
    if !ok {
        panic("variable `serverTransaction` is not of type `*sip.ServerTx`")
    }

    // The local address the request was received on
    receivedOnAddress := serverTx.Connection().LocalAddr()

    // Forwarding logic involving the local address...
}

This worked fine with v1.0.0-beta-3 (for both UDP and TCP), but starting with 10879e9, Connection().LocalAddr() returns an Addr with 0.0.0.0 and a seemingly random port for UDP. TCP still works as expected; sorry for not testing that earlier.

[emiago]

Hi. It is now fixed in main.

So to comply RFC 3263, source addr is chosen over via header.
This mostly avoids creating new Connection for UDP, and I think this will solve your problem. Please close if issue is resolved.

[bv-ngv]

With 9e49107 and UDP, I'm unfortunately still seeing the same behavior of the local address the request was received on being 0.0.0.0 and a seemingly random port.

To recap, I do the following as the first thing in my registered request handler:

func HandleRequest(req *sip.Request, serverTransaction sip.ServerTransaction) {
    serverTx, _ := serverTransaction.(*sip.ServerTx)
    connection := serverTx.Connection()  // sip.Connection | *sip.UDPConnection
    localAddr := connection.LocalAddr()  // net.Addr | *net.UDPAddr

    // ...
}

My server ListenAndServe()s on multiple addresses, one of which is 127.20.1.1:5060.

For a request sent to that address over TCP, we get the expected local address:

localAddr.String()  // => "127.20.1.1:5060"

For UDP, we still get only an "empty" address with a presumably random port:

localAddr.String()  // => "0.0.0.0:46669"

The improved 100 Trying handling is still working, however. 🙂 Let me know if I should open a new issue for this regression.

[emiago]

Hi @bv-ngv . If you could get me some SIP traces this would be good. Just set sip.SIPDEBUG=true and turn on debug logging level. I will try to replicate in meantime.

[bv-ngv]

I put together the following minimal reproducible example:

package main

import (
	"context"
	"fmt"
	"log/slog"
	"os"

	"github.com/emiago/sipgo"
	"github.com/emiago/sipgo/sip"
)

var listenAddresses = []string{
	"127.0.0.1:5060",
	"127.0.0.2:5060",
}

func main() {
	sip.SIPDebug = true

	logLevel := new(slog.LevelVar)
	logLevel.Set(slog.LevelDebug)
	logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
		Level: logLevel,
	}))
	slog.SetDefault(logger)

	ua, _ := sipgo.NewUA()
	server, _ := sipgo.NewServer(ua)
	// No client is needed for this example, although it's normally present
	//client, _ := sipgo.NewClient(ua)

	server.OnNoRoute(HandleRequest)

	ctx := context.Background()
	errCh := make(chan error, 1)

	for _, listenAddress := range listenAddresses {
		for _, transportProto := range []string{"udp", "tcp"} {
			go func() {
				errCh <- server.ListenAndServe(ctx, transportProto, listenAddress)
			}()
		}
	}

	select {
	case err := <-errCh:
		panic(fmt.Sprintf("failed to start server: %s", err.Error()))
	}
}

func HandleRequest(req *sip.Request, serverTransaction sip.ServerTransaction) {
	serverTx, _ := serverTransaction.(*sip.ServerTx)
	connection := serverTx.Connection()
	localAddr := connection.LocalAddr()

	println(fmt.Sprintf(
		"Received %s request on: %s (%s)",
		req.Method, localAddr.String(), req.Transport(),
	))
}

In this test, I sent a basic unauthorized REGISTER request to the second server address (127.0.0.2:5060)...

Over UDP:

time=2025-12-11T13:27:25.532+01:00 level=DEBUG msg="begin listening" caller=TransportLayer caller=Transport<UDP> network=UDP addr=127.0.0.2:5060
time=2025-12-11T13:27:25.532+01:00 level=DEBUG msg="begin listening on" caller=TransportLayer caller=Transport<TCP> network=TCP laddr=127.0.0.2:5060
time=2025-12-11T13:27:25.533+01:00 level=DEBUG msg="begin listening on" caller=TransportLayer caller=Transport<TCP> network=TCP laddr=127.0.0.1:5060
time=2025-12-11T13:27:25.533+01:00 level=DEBUG msg="begin listening" caller=TransportLayer caller=Transport<UDP> network=UDP addr=127.0.0.1:5060
time=2025-12-11T13:27:29.182+01:00 level=DEBUG msg="UDP read from 127.0.0.2:5060 <- 127.0.0.10:1070:\nREGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0\r\nAuthorization: Digest username=\"001010000000001@ims.mnc001.mcc001.3gppnetwork.org\", realm=\"ims.mnc001.mcc001.3gppnetwork.org\", nonce=\"\", uri=\"sip:ims.mnc001.mcc001.3gppnetwork.org\", response=\"\"\r\nCseq: 1 REGISTER\r\nCall-ID: f94384564c254d3fa20c2e49f737d67f\r\nContact: <sip:127.0.0.10:1060>\r\nExpires: 600000\r\nFrom: <sip:orig-ue@ims.mnc001.mcc001.3gppnetwork.org>;tag=a2657200df3242f9ac5bbd71645b91e2\r\nMax-Forwards: 70\r\nSupported: 100rel,path,replaces\r\nTo: <sip:orig-ue@ims.mnc001.mcc001.3gppnetwork.org>\r\nVia: SIP/2.0/UDP 127.0.0.10:1060;branch=z9hG4bK-2482e69dee7144e8831779a9377\r\nContent-Length: 0\r\n\r\n"
time=2025-12-11T13:27:29.182+01:00 level=DEBUG msg="Creating server connection" caller=TransportLayer laddr=:0 raddr=127.0.0.10:1060 network=udp
time=2025-12-11T13:27:29.182+01:00 level=DEBUG msg="New connection" caller=TransportLayer caller=Transport<UDP> raddr=127.0.0.10:1060
time=2025-12-11T13:27:29.182+01:00 level=DEBUG msg="Server transaction initialized" caller=TransactionLayer tx=z9hG4bK-2482e69dee7144e8831779a9377__127.0.0.10__1060__REGISTER
time=2025-12-11T13:27:29.182+01:00 level=DEBUG msg="Server transaction terminating" caller=TransactionLayer tx=z9hG4bK-2482e69dee7144e8831779a9377__127.0.0.10__1060__REGISTER
time=2025-12-11T13:27:29.182+01:00 level=DEBUG msg="Server transaction destroyed" caller=TransactionLayer tx=z9hG4bK-2482e69dee7144e8831779a9377__127.0.0.10__1060__REGISTER
Received REGISTER request on: 0.0.0.0:60443 (UDP)  <== Incorrect

And over TCP:

time=2025-12-11T13:27:03.523+01:00 level=DEBUG msg="begin listening" caller=TransportLayer caller=Transport<UDP> network=UDP addr=127.0.0.1:5060
time=2025-12-11T13:27:03.523+01:00 level=DEBUG msg="begin listening on" caller=TransportLayer caller=Transport<TCP> network=TCP laddr=127.0.0.2:5060
time=2025-12-11T13:27:03.523+01:00 level=DEBUG msg="begin listening on" caller=TransportLayer caller=Transport<TCP> network=TCP laddr=127.0.0.1:5060
time=2025-12-11T13:27:03.523+01:00 level=DEBUG msg="begin listening" caller=TransportLayer caller=Transport<UDP> network=UDP addr=127.0.0.2:5060
time=2025-12-11T13:27:10.822+01:00 level=DEBUG msg="New connection" caller=TransportLayer caller=Transport<TCP> raddr=127.0.0.10:1070
time=2025-12-11T13:27:10.822+01:00 level=DEBUG msg="TCP reference increment" ip=127.0.0.2:5060 dst=127.0.0.10:1070 ref=2
time=2025-12-11T13:27:10.822+01:00 level=DEBUG msg="TCP reference increment" ip=127.0.0.2:5060 dst=127.0.0.10:1070 ref=2
time=2025-12-11T13:27:10.851+01:00 level=DEBUG msg="TCP read from 127.0.0.2:5060 <- 127.0.0.10:1070:\nREGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0\r\nAuthorization: Digest username=\"001010000000001@ims.mnc001.mcc001.3gppnetwork.org\", realm=\"ims.mnc001.mcc001.3gppnetwork.org\", nonce=\"\", uri=\"sip:ims.mnc001.mcc001.3gppnetwork.org\", response=\"\"\r\nCseq: 1 REGISTER\r\nCall-ID: 1799fd8a04dc41abaa46884239866647\r\nContact: <sip:127.0.0.10:1060>\r\nExpires: 600000\r\nFrom: <sip:orig-ue@ims.mnc001.mcc001.3gppnetwork.org>;tag=6328f183bdfa4ae6aa5f24215f1932f8\r\nMax-Forwards: 70\r\nSupported: 100rel,path,replaces\r\nTo: <sip:orig-ue@ims.mnc001.mcc001.3gppnetwork.org>\r\nVia: SIP/2.0/TCP 127.0.0.10:1060;branch=z9hG4bK-f42e5d2d09d34b6b85a83ce9909\r\nContent-Length: 0\r\n\r\n"
time=2025-12-11T13:27:10.851+01:00 level=DEBUG msg="TCP reference increment" ip=127.0.0.2:5060 dst=127.0.0.10:1070 ref=3
time=2025-12-11T13:27:10.851+01:00 level=DEBUG msg="Server transaction initialized" caller=TransactionLayer tx=z9hG4bK-f42e5d2d09d34b6b85a83ce9909__127.0.0.10__1060__REGISTER
time=2025-12-11T13:27:10.851+01:00 level=DEBUG msg="Server transaction terminating" caller=TransactionLayer tx=z9hG4bK-f42e5d2d09d34b6b85a83ce9909__127.0.0.10__1060__REGISTER
time=2025-12-11T13:27:10.851+01:00 level=DEBUG msg="Server transaction destroyed" caller=TransactionLayer tx=z9hG4bK-f42e5d2d09d34b6b85a83ce9909__127.0.0.10__1060__REGISTER
Received REGISTER request on: 127.0.0.2:5060 (TCP)
time=2025-12-11T13:27:10.923+01:00 level=DEBUG msg="TCP read from 127.0.0.2:5060 <- 127.0.0.10:1070:\n"
time=2025-12-11T13:27:10.923+01:00 level=DEBUG msg="connection was closed" caller=TransportLayer caller=Transport<TCP> error=EOF
time=2025-12-11T13:27:10.923+01:00 level=DEBUG msg="TCP reference decrement" ip=127.0.0.2:5060 dst=127.0.0.10:1070 ref=2
time=2025-12-11T13:27:10.923+01:00 level=DEBUG msg="TCP doing hard close" ip=127.0.0.2:5060 dst=127.0.0.10:1070 ref=0

I should also mention that the behavior is exactly the same with just one ListenAndServe() / server address.

[emiago]

So it is trying to sent back request based on Via header.
Client normally needs to set rport to be received back over source addr.
https://datatracker.ietf.org/doc/html/rfc3581

Yes previous versions had by default sending back over same connection, but latest fixes try to follow more RFC.
https://datatracker.ietf.org/doc/html/rfc3261#section-18.2.2

So per RFC only reliable connection by default should use same connection while UDP decides based on Via values.
Generally it is routable to reuse current connection and I think this is where problem happens.

I will check more arround this behavior, but I already know what should be fixed

[emiago]

Ok I think now went more correctly with this.
Please check main branch. It should use your server connection unless it really has no other choice.
I think confusion was with remote addr decision.

Do not close issue. Fix needs some regression testing for this.