Different events triggered when cancelling an INVITE before vs. after 32 seconds (T6)

[shokoban]

Hi SIPSorcery team,

First of all, thank you for providing and maintaining such a fantastic OSS library. It has been incredibly helpful for studying and prototyping SIP applications!

Goal of this question

I am experiencing an issue where the event triggered upon cancelling an outgoing call (INVITE) changes depending on whether the cancellation occurs before or after 32 seconds have passed since the initial INVITE.
I would like to know if this is the intended behavior by design, or if it is an unintended side effect of the transaction cleanup logic.

Environment

• OS: Linux / Windows
• Framework: .NET 8.0
• SIPSorcery Version: 8.0.23
• SIP Server: FreePBX 17.0.25

What I did (Steps to reproduce)

I created a simple SIP client that sends an INVITE and waits in the Ringing state. I then compared the behavior of cancelling the call (CancelCall()) in two scenarios:

1. Cancelling before 32 seconds (e.g., at 10 seconds).
2. Cancelling after 32 seconds (e.g., at 35 seconds).

Actual behavior

When cancelling before 32 seconds, the 487 Request Terminated response matches the INVITE transaction, and the call ends gracefully (UACInviteTransactionFinalResponseReceived event is triggered).
However, when cancelling after 32 seconds, the INVITE transaction seems to be removed immediately upon cancellation, causing the subsequent 487 response to be unmatched, which leads to a different event (SIPTransportResponseReceived) being triggered.

Logs (Before 32s):

[00:00:00.005] Simple SIP Terminal RTP TX/RX (SIPSorcery)
[00:00:00.019] Listening on UDP 5060
[00:00:00.063] Commands: call <sip-uri>, cancel, answer, reject, hangup, hold, resume, hold status, unregister, rtp on, rtp off, rtp music, rtp silence, rtp stats, rtp reset, quit
[00:00:00.063] > [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:00.129] [SIP-IN] 401 Unauthorized for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:00.136] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:00.139] [SIP-IN] 200 OK for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:00.142] Registered: sip:1003@172.21.100.102
[00:00:05.077] call sip:1001@172.21.100.102
[00:00:05.079] Dialing sip:1001@172.21.100.102...
[00:00:05.079] > [SIP-OUT] INVITE sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:05.118] [SIP-IN] 401 Unauthorized for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:05.120] [SIP-OUT] ACK sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:05.122] [SIP-OUT] INVITE sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:05.124] [SIP-IN] 100 Trying for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:05.126] [UAC] TRYING 100 Trying
[00:00:05.148] [SIP-IN] 180 Ringing for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:05.149] [UAC] RINGING 180 Ringing
[00:00:05.206] [SIP-IN] 180 Ringing for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:05.206] [UAC] RINGING 180 Ringing
[00:00:18.437] cancel
[00:00:19.936] Outgoing call cancel requested.
[00:00:19.936] > [SIP-OUT] CANCEL sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:19.938] [UAC] FAILED Call cancelled by user. 
[00:00:19.938] Call failed or cancelled.
[00:00:19.939] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:19.940] [SIP-OUT] ACK sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:19.941] [UAC-FINAL] 487 Request Terminated
[00:00:19.941] [UAC-FINAL] UACInviteTransactionFinalResponseReceived for transaction q9KAiF7LjzdEBirGxRaXUz/El5k= (INVITE)
[00:00:32.298] quit
[00:00:33.245] Sending unregister before shutdown...
[00:00:33.246] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:33.248] [SIP-IN] 401 Unauthorized for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:33.249] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:33.250] [SIP-IN] 200 OK for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:33.251] Unregister completed.

Logs (After 32s):

[00:00:00.063] > [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:00.124] [SIP-IN] 401 Unauthorized for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:00.130] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:00.133] [SIP-IN] 200 OK for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:00.136] Registered: sip:1003@172.21.100.102
[00:00:04.629] call sip:1001@172.21.100.102
[00:00:04.631] Dialing sip:1001@172.21.100.102...
[00:00:04.631] > [SIP-OUT] INVITE sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:04.670] [SIP-IN] 401 Unauthorized for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:04.672] [SIP-OUT] ACK sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:04.674] [SIP-OUT] INVITE sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:04.676] [SIP-IN] 100 Trying for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:04.678] [UAC] TRYING 100 Trying
[00:00:04.697] [SIP-IN] 180 Ringing for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:04.698] [UAC] RINGING 180 Ringing
[00:00:04.769] [SIP-IN] 180 Ringing for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:04.770] [UAC] RINGING 180 Ringing
[00:00:43.359] cancel
[00:00:43.359] Outgoing call cancel requested.
[00:00:43.359] > [SIP-OUT] CANCEL sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:43.361] [UAC] FAILED Call cancelled by user. 
[00:00:43.362] Call failed or cancelled.
[00:00:43.363] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:43.364] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:43.364] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:00:43.863] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:43.863] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:43.864] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:00:44.863] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:44.863] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:44.863] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:00:46.864] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:46.864] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:46.864] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:00:50.864] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:50.864] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:50.864] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:00:54.864] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:54.865] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:54.865] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:00:58.864] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:58.864] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:58.864] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:01:02.864] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:02.864] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:02.865] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:01:06.865] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:06.865] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:06.866] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:01:10.866] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:10.866] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:10.866] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:01:14.865] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:14.865] [SIP-UNMATCHED] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:14.865] [SIP-UNMATCHED] SIPTransportResponseReceived for transaction INVITE (INVITE)
[00:01:34.406] quit
[00:01:34.406] Sending unregister before shutdown...
[00:01:34.408] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:01:34.410] [SIP-IN] 401 Unauthorized for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:34.410] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:01:34.412] [SIP-IN] 200 OK for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:34.412] Unregister completed.

Proposed fix

Upon investigating the source code, I found that in SIPTransactionEngine.cs, transactions are cleaned up based on Created >= m_t6 (where T6 is 32 seconds). When a call is cancelled after 32 seconds, since Created is already older than T6, it gets immediately removed by the engine's cleanup loop.
The state becomes Cancelled, but it seems this issue occurs because there is no specific handling for the Cancelled state.

To prevent this, I tried modifying the logic to track the cancellation time (CancelledAt) and keep the transaction alive for a short period after cancellation so it can catch the 487 response.

Modifications:

1. Added CancelledAt property to SIPTransaction.cs and set it when the state changes to Cancelled.
2. Modified SIPTransactionEngine.cs to check CancelledAt instead of Created for Cancelled transactions.

SIPTransaction.cs

Before

namespace SIPSorcery.SIP
{
    // ...
    public class SIPTransaction
    {
        protected void UpdateTransactionState(SIPTransactionStatesEnum transactionState)
        {
            m_transactionState = transactionState;

            if (transactionState == SIPTransactionStatesEnum.Confirmed ||
                transactionState == SIPTransactionStatesEnum.Terminated ||
                transactionState == SIPTransactionStatesEnum.Cancelled)
            {
                DeliveryPending = false;
            }
            else if (transactionState == SIPTransactionStatesEnum.Completed)
            {
                CompletedAt = DateTime.Now;
            }

            TransactionStateChanged?.Invoke(this);
            TransactionTraceMessage?.Invoke(this, $"Transaction state changed to {this.TransactionState}.");
        }
        // ...
    }
}

After

namespace SIPSorcery.SIP
{
    public class SIPTransaction
    {
        // ...
        public DateTime CancelledAt;  // Property to record the cancellation time

        protected void UpdateTransactionState(SIPTransactionStatesEnum transactionState)
        {
            m_transactionState = transactionState;

            if (transactionState == SIPTransactionStatesEnum.Confirmed ||
                transactionState == SIPTransactionStatesEnum.Terminated ||
                transactionState == SIPTransactionStatesEnum.Cancelled)
            {
                if (transactionState == SIPTransactionStatesEnum.Cancelled && CancelledAt == DateTime.MinValue) // Set only if cancellation time is not set
                {
                    CancelledAt = DateTime.Now; // Record the cancellation time
                }

                DeliveryPending = false;
            }
            else if (transactionState == SIPTransactionStatesEnum.Completed)
            {
                CompletedAt = DateTime.Now;
            }

            TransactionStateChanged?.Invoke(this);
            TransactionTraceMessage?.Invoke(this, $"Transaction state changed to {this.TransactionState}.");
        }
        // ...
    }
}

SIPTransactionEngine.cs

Before

namespace SIPSorcery.SIP
{
    internal class SIPTransactionEngine : IDisposable
    {
        // ...
        private void RemoveExpiredTransactions()
        {
            try
            {
                List<string> expiredTransactionIds = new List<string>();
                var now = DateTime.Now;

                foreach (var (_, transaction) in m_pendingTransactions)
                {
                    if (transaction.TransactionType == SIPTransactionTypesEnum.InviteClient || transaction.TransactionType == SIPTransactionTypesEnum.InviteServer)
                    {
                        // ...
                        else if (transaction.TransactionState == SIPTransactionStatesEnum.Proceeding)
                        {
                            if (now.Subtract(transaction.Created).TotalMilliseconds >= m_maxRingTime)
                            {
                                // INVITE requests that have been ringing too long. This can apply to both
                                // client and server INVITE transactions.
                                transaction.Expire(now);
                                expiredTransactionIds.Add(transaction.TransactionId);
                            }
                        }
                        else if (now.Subtract(transaction.Created).TotalMilliseconds >= m_t6)
                        {
                            // ...
                        }
                        // ...
                    }
                    // ...
                }
            }
        }
    }
}

After:

namespace SIPSorcery.SIP
{
    internal class SIPTransactionEngine : IDisposable
    {
        // ...
        private void RemoveExpiredTransactions()
        {
            try
            {
                List<string> expiredTransactionIds = new List<string>();
                var now = DateTime.Now;

                foreach (var (_, transaction) in m_pendingTransactions)
                {
                    if (transaction.TransactionType == SIPTransactionTypesEnum.InviteClient || transaction.TransactionType == SIPTransactionTypesEnum.InviteServer)
                    {
                        // ...
                        else if (transaction.TransactionState == SIPTransactionStatesEnum.Proceeding)
                        {
                            if (now.Subtract(transaction.Created).TotalMilliseconds >= m_maxRingTime)
                            {
                                // INVITE requests that have been ringing too long. This can apply to both
                                // client and server INVITE transactions.
                                transaction.Expire(now);
                                expiredTransactionIds.Add(transaction.TransactionId);
                            }
                        }
                        // Added handling for Cancelled state
                        else if (transaction.TransactionState == SIPTransactionStatesEnum.Cancelled)
                        {
                            var cancelledAt = (transaction.CancelledAt == DateTime.MinValue) ? transaction.Created : transaction.CancelledAt;

                            if (now.Subtract(cancelledAt).TotalMilliseconds >= m_t6)
                            {
                                expiredTransactionIds.Add(transaction.TransactionId);
                            }
                        }
                        else if (now.Subtract(transaction.Created).TotalMilliseconds >= m_t6)
                        {
                            // ...
                        }
                        // ...
                    }
                    // ...
                }
            }
        }
    }
}

Behavior after applying the fix (Logs)

After applying this fix, cancelling after 32 seconds behaves exactly the same as cancelling before 32 seconds. The 487 response is correctly matched, and the call ends gracefully (UACInviteTransactionFinalResponseReceived event is triggered).

Logs (After fix, >= 32s):

[00:00:00.005] Simple SIP Terminal RTP TX/RX (SIPSorcery)
[00:00:00.019] Listening on UDP 5060
[00:00:00.060] Commands: call <sip-uri>, cancel, answer, reject, hangup, hold, resume, hold status, unregister, rtp on, rtp off, rtp music, rtp silence, rtp stats, rtp reset, quit
[00:00:00.061] > [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:00.118] [SIP-IN] 401 Unauthorized for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:00.124] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:00.126] [SIP-IN] 200 OK for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:00.128] Registered: sip:1003@172.21.100.102
[00:00:11.214] call sip:1001@172.21.100.102
[00:00:11.216] Dialing sip:1001@172.21.100.102...
[00:00:11.217] > [SIP-OUT] INVITE sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:11.257] [SIP-IN] 401 Unauthorized for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:11.258] [SIP-OUT] ACK sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:11.261] [SIP-OUT] INVITE sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:11.263] [SIP-IN] 100 Trying for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:11.266] [UAC] TRYING 100 Trying
[00:00:11.289] [SIP-IN] 180 Ringing for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:11.290] [UAC] RINGING 180 Ringing
[00:00:11.344] [SIP-IN] 180 Ringing for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:11.344] [UAC] RINGING 180 Ringing
[00:00:48.101] cancel
[00:00:48.102] Outgoing call cancel requested.
[00:00:48.102] > [SIP-OUT] CANCEL sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:48.104] [UAC] FAILED Call cancelled by user. 
[00:00:48.104] Call failed or cancelled.
[00:00:48.105] [SIP-IN] 487 Request Terminated for INVITE (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:00:48.106] [SIP-OUT] ACK sip:1001@172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:00:48.106] [UAC-FINAL] 487 Request Terminated
[00:00:48.106] [UAC-FINAL] UACInviteTransactionFinalResponseReceived for transaction zbBtdQopc3yh+MSNIbzu8MH/PhU= (INVITE)
[00:01:00.066] quit
[00:01:00.067] Sending unregister before shutdown...
[00:01:00.068] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:01:00.070] [SIP-IN] 401 Unauthorized for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:00.071] [SIP-OUT] REGISTER sip:172.21.100.102 (udp:172.21.100.110:5060 -> udp:172.21.100.102:5060)
[00:01:00.072] [SIP-IN] 200 OK for REGISTER (udp:172.21.100.102:5060 -> udp:0.0.0.0:5060)
[00:01:00.072] Unregister completed.

Is this behavior around the 32-second boundary intended? Or would a fix similar to the one above be considered desirable?
Thank you for your time and assistance!

Finally, I am sharing the code used for this validation.

Code used for validation

using System.Net;
using System.Reflection;
using System.Diagnostics;
using System.IO;
using System.Text;
using SIPSorcery.Media;
using SIPSorcery.Net;
using SIPSorcery.SIP;
using SIPSorcery.SIP.App;
using SIPSorceryMedia.Abstractions;

const int defaultSipListenPort = 5060;
const int registerExpiry = 120;

var options = ParseArgs(args);
var sipListenPort = options.TryGetValue("listen", out var listenValue) && int.TryParse(listenValue, out var parsedPort)
    ? parsedPort
    : defaultSipListenPort;

var authUsername = options.GetValueOrDefault("username");
var authPassword = options.GetValueOrDefault("password");
var registerServer = options.GetValueOrDefault("server");

var appElapsed = Stopwatch.StartNew();
Console.SetOut(new TimestampTextWriter(Console.Out, appElapsed));

Console.WriteLine("Simple SIP Terminal RTP TX/RX (SIPSorcery)");
Console.WriteLine($"Listening on UDP {sipListenPort}");

var sipTransport = new SIPTransport();
sipTransport.AddSIPChannel(new SIPUDPChannel(new IPEndPoint(IPAddress.Any, sipListenPort)));

var userAgent = new SIPUserAgent(sipTransport, null, true);
EnableDiagnostics(sipTransport, userAgent);
SIPRegistrationUserAgent? registerUserAgent = null;
VoIPMediaSession? activeSession = null;
AudioExtrasSource? activeAudioSource = null;
SIPServerUserAgent? pendingIncomingCall = null;
AudioSourcesEnum currentTxSource = AudioSourcesEnum.None;
long rtpRxPacketCount = 0;
long rtpRxByteCount = 0;
DateTime? firstRtpRxAtUtc = null;
DateTime? lastRtpRxAtUtc = null;
bool shutdownRequested = false;
bool isDialing = false;
bool cancelRequested = false;
var observedFinalResponseTransactionIds = new HashSet<string>();

Console.CancelKeyPress += (_, eventArgs) =>
{
    eventArgs.Cancel = true;
    shutdownRequested = true;
    Console.WriteLine("Shutdown requested (Ctrl+C).");
};

userAgent.OnIncomingCall += (ua, req) =>
{
    Console.WriteLine($"Incoming call from {req.Header.From?.FromURI}");

    if (ua.IsCallActive || pendingIncomingCall != null)
    {
        Console.WriteLine("Already in call or another incoming call is pending. Rejecting with Busy Here.");
        var busyUas = ua.AcceptCall(req);
        busyUas.Reject(SIPResponseStatusCodesEnum.BusyHere, "Busy Here");
        return;
    }

    pendingIncomingCall = ua.AcceptCall(req);
    Console.WriteLine("Incoming call is pending. Type 'answer' or 'reject'.");
};

userAgent.ServerCallCancelled += (uas, cancelReq) =>
{
    if (pendingIncomingCall == uas)
    {
        pendingIncomingCall = null;
    }

    Console.WriteLine("Incoming call cancelled by remote party.");
};

userAgent.OnCallHungup += (dialog) =>
{
    Console.WriteLine("Call finished.");
    activeSession?.Close("hungup");
    activeSession = null;
    activeAudioSource = null;
    currentTxSource = AudioSourcesEnum.None;
};

userAgent.RemotePutOnHold += () =>
{
    Console.WriteLine("Remote party put this call on hold.");
};

userAgent.RemoteTookOffHold += () =>
{
    Console.WriteLine("Remote party resumed this call.");
};

if (!string.IsNullOrWhiteSpace(registerServer) &&
    !string.IsNullOrWhiteSpace(authUsername) &&
    !string.IsNullOrWhiteSpace(authPassword))
{
    registerUserAgent = new SIPRegistrationUserAgent(
        sipTransport,
        authUsername,
        authPassword,
        registerServer,
        registerExpiry);

    registerUserAgent.RegistrationSuccessful += (uri, response) =>
        Console.WriteLine($"Registered: {uri}");
    registerUserAgent.RegistrationTemporaryFailure += (uri, response, error) =>
        Console.WriteLine($"Register temporary failure: {error}");
    registerUserAgent.RegistrationFailed += (uri, response, error) =>
        Console.WriteLine($"Register failed: {error}");

    registerUserAgent.Start();
}
else
{
    Console.WriteLine("Registration disabled (set --server --username --password to enable).");
}

Console.WriteLine("Commands: call <sip-uri>, cancel, answer, reject, hangup, hold, resume, hold status, unregister, rtp on, rtp off, rtp music, rtp silence, rtp stats, rtp reset, quit");

while (true)
{
    if (shutdownRequested)
    {
        break;
    }

    Console.Write("> ");
    var line = Console.ReadLine();

    if (line == null)
    {
        break;
    }

    if (string.IsNullOrWhiteSpace(line))
    {
        continue;
    }

    var trimmed = line.Trim();

    if (trimmed.Equals("quit", StringComparison.OrdinalIgnoreCase) ||
        trimmed.Equals("exit", StringComparison.OrdinalIgnoreCase))
    {
        break;
    }

    if (trimmed.Equals("hangup", StringComparison.OrdinalIgnoreCase))
    {
        if (userAgent.IsCallActive)
        {
            userAgent.Hangup();
            Console.WriteLine("Hangup sent.");
        }
        else
        {
            Console.WriteLine("No active call.");
        }

        continue;
    }

    if (trimmed.Equals("hold", StringComparison.OrdinalIgnoreCase))
    {
        if (!userAgent.IsCallActive)
        {
            Console.WriteLine("No active call.");
            continue;
        }

        if (userAgent.IsOnLocalHold)
        {
            Console.WriteLine("Already on local hold.");
            continue;
        }

        userAgent.PutOnHold();
        Console.WriteLine("Local hold requested.");
        continue;
    }

    if (trimmed.Equals("resume", StringComparison.OrdinalIgnoreCase))
    {
        if (!userAgent.IsCallActive)
        {
            Console.WriteLine("No active call.");
            continue;
        }

        if (!userAgent.IsOnLocalHold)
        {
            Console.WriteLine("Call is not on local hold.");
            continue;
        }

        userAgent.TakeOffHold();
        Console.WriteLine("Resume requested.");
        continue;
    }

    if (trimmed.Equals("hold status", StringComparison.OrdinalIgnoreCase))
    {
        Console.WriteLine($"LocalHold={userAgent.IsOnLocalHold}, RemoteHold={userAgent.IsOnRemoteHold}");
        continue;
    }

    if (trimmed.Equals("cancel", StringComparison.OrdinalIgnoreCase))
    {
        if (isDialing && !userAgent.IsCallActive)
        {
            cancelRequested = true;
            _ = Task.Run(async () =>
            {
                for (var count = 0; count < 20 && isDialing && !userAgent.IsCallActive; count++)
                {
                    userAgent.Cancel();
                    await Task.Delay(100);
                }
            });
            Console.WriteLine("Outgoing call cancel requested.");
        }
        else
        {
            Console.WriteLine("No outgoing call attempt to cancel.");
        }

        continue;
    }

    if (trimmed.Equals("unregister", StringComparison.OrdinalIgnoreCase))
    {
        if (registerUserAgent == null)
        {
            Console.WriteLine("Registration is not configured.");
            continue;
        }

        var unregistered = await TryUnregisterAsync(registerUserAgent, 2000);
        registerUserAgent = null;
        Console.WriteLine(unregistered ? "Unregister completed." : "Unregister timeout (request may still have been sent).");
        continue;
    }

    if (trimmed.Equals("answer", StringComparison.OrdinalIgnoreCase))
    {
        if (pendingIncomingCall == null)
        {
            Console.WriteLine("No pending incoming call.");
            continue;
        }

        (activeSession, activeAudioSource) = CreateMediaSession(OnRtpPacketReceived);
        var answerResult = await userAgent.Answer(pendingIncomingCall, activeSession);
        pendingIncomingCall = null;
        Console.WriteLine(answerResult
            ? "Incoming call answered. RTP TX is OFF (use 'rtp on' or 'rtp music')."
            : "Failed to answer incoming call.");

        if (!answerResult)
        {
            activeSession.Close("answer failed");
            activeSession = null;
            activeAudioSource = null;
            currentTxSource = AudioSourcesEnum.None;
        }

        continue;
    }

    if (trimmed.Equals("reject", StringComparison.OrdinalIgnoreCase))
    {
        if (pendingIncomingCall == null)
        {
            Console.WriteLine("No pending incoming call.");
            continue;
        }

        pendingIncomingCall.Reject(SIPResponseStatusCodesEnum.Decline, "Decline");
        pendingIncomingCall = null;
        Console.WriteLine("Incoming call rejected.");
        continue;
    }

    if (trimmed.StartsWith("call ", StringComparison.OrdinalIgnoreCase))
    {
        if (userAgent.IsCallActive || isDialing)
        {
            Console.WriteLine("Already in call or dialing. Hang up/cancel first.");
            continue;
        }

        var destination = trimmed[5..].Trim();
        if (string.IsNullOrWhiteSpace(destination))
        {
            Console.WriteLine("Usage: call <sip-uri>");
            continue;
        }

        isDialing = true;
        cancelRequested = false;
        _ = ObserveUacFinalResponsesAsync(userAgent, observedFinalResponseTransactionIds);
        _ = Task.Run(async () =>
        {
            (activeSession, activeAudioSource) = CreateMediaSession(OnRtpPacketReceived);
            var callResult = await userAgent.Call(destination, authUsername, authPassword, activeSession);
            isDialing = false;

            if (callResult && cancelRequested && userAgent.IsCallActive)
            {
                userAgent.Hangup();
                callResult = false;
            }

            cancelRequested = false;

            Console.WriteLine(callResult
                ? "Call connected. RTP TX is OFF (use 'rtp on' or 'rtp music')."
                : "Call failed or cancelled.");

            if (!callResult)
            {
                activeSession.Close("call failed");
                activeSession = null;
                activeAudioSource = null;
                currentTxSource = AudioSourcesEnum.None;
            }
        });

        Console.WriteLine($"Dialing {destination}...");

        continue;
    }

    if (trimmed.Equals("rtp on", StringComparison.OrdinalIgnoreCase) ||
        trimmed.Equals("rtp music", StringComparison.OrdinalIgnoreCase))
    {
        if (!userAgent.IsCallActive || activeAudioSource == null)
        {
            Console.WriteLine("No active call.");
            continue;
        }

        activeAudioSource.SetSource(AudioSourcesEnum.Music);
        currentTxSource = AudioSourcesEnum.Music;
        Console.WriteLine("RTP TX ON (music source).");
        continue;
    }

    if (trimmed.Equals("rtp silence", StringComparison.OrdinalIgnoreCase))
    {
        if (!userAgent.IsCallActive || activeAudioSource == null)
        {
            Console.WriteLine("No active call.");
            continue;
        }

        activeAudioSource.SetSource(AudioSourcesEnum.Silence);
        currentTxSource = AudioSourcesEnum.Silence;
        Console.WriteLine("RTP TX ON (silence source).");
        continue;
    }

    if (trimmed.Equals("rtp off", StringComparison.OrdinalIgnoreCase))
    {
        if (!userAgent.IsCallActive || activeAudioSource == null)
        {
            Console.WriteLine("No active call.");
            continue;
        }

        activeAudioSource.SetSource(AudioSourcesEnum.None);
        currentTxSource = AudioSourcesEnum.None;
        Console.WriteLine("RTP TX OFF.");
        continue;
    }

    if (trimmed.Equals("rtp stats", StringComparison.OrdinalIgnoreCase))
    {
        var txState = activeAudioSource == null
            ? "n/a"
            : currentTxSource.ToString();

        Console.WriteLine($"RTP RX packets={rtpRxPacketCount}, bytes={rtpRxByteCount}, first={(firstRtpRxAtUtc?.ToString("O") ?? "n/a")}, last={(lastRtpRxAtUtc?.ToString("O") ?? "n/a")}");
        Console.WriteLine($"RTP TX source={txState}");
        continue;
    }

    if (trimmed.Equals("rtp reset", StringComparison.OrdinalIgnoreCase))
    {
        rtpRxPacketCount = 0;
        rtpRxByteCount = 0;
        firstRtpRxAtUtc = null;
        lastRtpRxAtUtc = null;
        Console.WriteLine("RTP RX stats reset.");
        continue;
    }

    Console.WriteLine("Unknown command. Use: call <sip-uri>, cancel, answer, reject, hangup, hold, resume, hold status, unregister, rtp on, rtp off, rtp music, rtp silence, rtp stats, rtp reset, quit");
}

if (userAgent.IsCalling && !userAgent.IsCallActive)
{
    isDialing = false;
    cancelRequested = false;
    userAgent.Cancel();
    await Task.Delay(200);
}

if (userAgent.IsCallActive)
{
    userAgent.Hangup();
}

if (pendingIncomingCall != null)
{
    pendingIncomingCall.Reject(SIPResponseStatusCodesEnum.RequestTerminated, "Shutdown");
}

if (registerUserAgent != null)
{
    Console.WriteLine("Sending unregister before shutdown...");
    var unregistered = await TryUnregisterAsync(registerUserAgent, 2000);
    Console.WriteLine(unregistered ? "Unregister completed." : "Unregister timeout (request may still have been sent).");
    registerUserAgent = null;
}

activeSession?.Close("shutdown");
sipTransport.Shutdown();

static async Task<bool> TryUnregisterAsync(SIPRegistrationUserAgent registrationUserAgent, int timeoutMs)
{
    var tcs = new TaskCompletionSource<bool>(TaskCreationOptions.RunContinuationsAsynchronously);

    void Complete(bool result)
    {
        tcs.TrySetResult(result);
    }

    registrationUserAgent.RegistrationRemoved += (_, _) => Complete(true);
    registrationUserAgent.RegistrationFailed += (_, _, _) => Complete(false);
    registrationUserAgent.RegistrationTemporaryFailure += (_, _, _) => Complete(false);

    registrationUserAgent.Stop(true);

    var completed = await Task.WhenAny(tcs.Task, Task.Delay(timeoutMs));
    return completed == tcs.Task && tcs.Task.Result;
}

void OnRtpPacketReceived(IPEndPoint remoteEndPoint, SDPMediaTypesEnum mediaType, RTPPacket rtpPacket)
{
    if (mediaType != SDPMediaTypesEnum.audio)
    {
        return;
    }

    if (firstRtpRxAtUtc == null)
    {
        firstRtpRxAtUtc = DateTime.UtcNow;
    }

    lastRtpRxAtUtc = DateTime.UtcNow;
    rtpRxPacketCount++;
    rtpRxByteCount += rtpPacket.Payload?.Length ?? 0;
}

static (VoIPMediaSession Session, AudioExtrasSource AudioSource) CreateMediaSession(
    Action<IPEndPoint, SDPMediaTypesEnum, RTPPacket> onRtpPacketReceived)
{
    var audioOptions = new AudioSourceOptions
    {
        AudioSource = AudioSourcesEnum.None,
    };

    var audioSource = new AudioExtrasSource(new AudioEncoder(), audioOptions);
    audioSource.RestrictFormats(format => format.Codec == AudioCodecsEnum.PCMU || format.Codec == AudioCodecsEnum.PCMA);

    var mediaSession = new VoIPMediaSession(new MediaEndPoints
    {
        AudioSource = audioSource,
    });

    mediaSession.AcceptRtpFromAny = true;
    mediaSession.OnRtpPacketReceived += onRtpPacketReceived;

    return (mediaSession, audioSource);
}

static Dictionary<string, string> ParseArgs(string[] commandLineArgs)
{
    var result = new Dictionary<string, string>(StringComparer.OrdinalIgnoreCase);

    for (var index = 0; index < commandLineArgs.Length; index++)
    {
        var token = commandLineArgs[index];
        if (!token.StartsWith("--", StringComparison.Ordinal))
        {
            continue;
        }

        var key = token[2..];
        var value = index + 1 < commandLineArgs.Length ? commandLineArgs[index + 1] : string.Empty;
        if (!value.StartsWith("--", StringComparison.Ordinal))
        {
            result[key] = value;
            index++;
        }
        else
        {
            result[key] = "true";
        }
    }

    return result;
}

static void EnableDiagnostics(SIPTransport sipTransport, SIPUserAgent userAgent)
{
    sipTransport.SIPRequestOutTraceEvent += (localEndPoint, remoteEndPoint, request) =>
    {
        if (request.Method == SIPMethodsEnum.INVITE ||
            request.Method == SIPMethodsEnum.CANCEL ||
            request.Method == SIPMethodsEnum.ACK ||
            request.Method == SIPMethodsEnum.BYE ||
            request.Method == SIPMethodsEnum.REGISTER)
        {
            Console.WriteLine($"[SIP-OUT] {request.Method} {request.URI} ({localEndPoint} -> {remoteEndPoint})");
        }
    };

    sipTransport.SIPResponseInTraceEvent += (localEndPoint, remoteEndPoint, response) =>
    {
        var method = response.Header?.CSeqMethod;
        if (method == SIPMethodsEnum.INVITE || method == SIPMethodsEnum.REGISTER)
        {
            Console.WriteLine($"[SIP-IN] {response.StatusCode} {response.ReasonPhrase} for {method} ({remoteEndPoint} -> {localEndPoint})");
        }
    };

    sipTransport.SIPTransportResponseReceived += (localEndPoint, remoteEndPoint, response) =>
    {
        Console.WriteLine($"[SIP-UNMATCHED] {response.StatusCode} {response.ReasonPhrase} for {response.Header?.CSeqMethod} ({remoteEndPoint} -> {localEndPoint})");
        Console.WriteLine($"[SIP-UNMATCHED] SIPTransportResponseReceived for transaction {response.Header?.CSeqMethod} ({response.Header?.CSeqMethod})");
        return Task.CompletedTask;
    };

    userAgent.ClientCallTrying += (_, response) =>
        Console.WriteLine($"[UAC] TRYING {response.StatusCode} {response.ReasonPhrase}");
    userAgent.ClientCallRinging += (_, response) =>
        Console.WriteLine($"[UAC] RINGING {response.StatusCode} {response.ReasonPhrase}");
    userAgent.ClientCallAnswered += (_, response) =>
        Console.WriteLine($"[UAC] ANSWERED {response.StatusCode} {response.ReasonPhrase}");
    userAgent.ClientCallFailed += (_, error, response) =>
        Console.WriteLine($"[UAC] FAILED {error} {(response != null ? $"({response.StatusCode} {response.ReasonPhrase})" : string.Empty)}");
}

static async Task ObserveUacFinalResponsesAsync(SIPUserAgent userAgent, HashSet<string> observedTransactionIds)
{
    var uacField = typeof(SIPUserAgent).GetField("m_uac", BindingFlags.Instance | BindingFlags.NonPublic);
    if (uacField == null)
    {
        return;
    }

    var startedAt = DateTime.UtcNow;
    var hasSeenCallStart = false;
    while (DateTime.UtcNow.Subtract(startedAt) < TimeSpan.FromSeconds(60))
    {
        try
        {
            var uac = uacField.GetValue(userAgent) as ISIPClientUserAgent;
            var tx = uac?.ServerTransaction;

            if (tx != null)
            {
                var shouldAttach = false;
                lock (observedTransactionIds)
                {
                    shouldAttach = observedTransactionIds.Add(tx.TransactionId);
                }

                if (shouldAttach)
                {
                    tx.UACInviteTransactionFinalResponseReceived += (_, _, _, response) =>
                    {
                        // This is a final response received by the UAC transaction that we haven't observed before. Log it.
                        Console.WriteLine($"[UAC-FINAL] {response.StatusCode} {response.ReasonPhrase}");
                        Console.WriteLine($"[UAC-FINAL] UACInviteTransactionFinalResponseReceived for transaction {tx.TransactionId} ({response.Header?.CSeqMethod})");
                        return Task.FromResult(System.Net.Sockets.SocketError.Success);
                    };
                }
            }
        }
        catch
        {
        }

        if (userAgent.IsCalling || userAgent.IsCallActive)
        {
            hasSeenCallStart = true;
        }

        if (hasSeenCallStart && !userAgent.IsCalling && !userAgent.IsCallActive)
        {
            break;
        }

        await Task.Delay(100);
    }
}

internal sealed class TimestampTextWriter : TextWriter
{
    private readonly TextWriter _inner;
    private readonly Stopwatch _elapsed;
    private readonly object _sync = new object();
    private bool _atLineStart = true;

    public TimestampTextWriter(TextWriter inner, Stopwatch elapsed)
    {
        _inner = inner;
        _elapsed = elapsed;
    }

    public override Encoding Encoding => _inner.Encoding;

    public override void Write(char value)
    {
        lock (_sync)
        {
            WritePrefixIfNeeded();
            _inner.Write(value);
            if (value == '\n')
            {
                _atLineStart = true;
            }
        }
    }

    public override void Write(string? value)
    {
        if (string.IsNullOrEmpty(value))
        {
            return;
        }

        lock (_sync)
        {
            foreach (var character in value)
            {
                WritePrefixIfNeeded();
                _inner.Write(character);
                if (character == '\n')
                {
                    _atLineStart = true;
                }
            }
        }
    }

    public override void WriteLine(string? value)
    {
        Write(value);
        Write(Environment.NewLine);
    }

    public override void Flush()
    {
        lock (_sync)
        {
            _inner.Flush();
        }
    }

    private void WritePrefixIfNeeded()
    {
        if (_atLineStart)
        {
            _inner.Write($"[{_elapsed.Elapsed:hh\\:mm\\:ss\\.fff}] ");
            _atLineStart = false;
        }
    }
}

[sipsorcery]

Thanks for the detailed diagnosis. The fix looks good. Would you mind submitting a PR?

[shokoban]

Thank you very much for checking.
Understood. I will submit the PR.
(I'm not very familiar with Git yet, so it might take me a little time. I appreciate your patience.)