Debugging SIP Messages the Traditional Way

Since its release, the PJSIP stack has provided logging of SIP message traffic via the pjsip set logger  CLI command. This dumps all received and transmitted SIP messages as a VERBOSE message. This is useful for two scenarios:

1. When wanting to log all SIP messages in an Asterisk log file.
2. When attempting to debug SIP messages in real-time via the CLI.

In the first scenario, the existing CLI command works just fine. However, when attempting to debug live SIP calls on a production system with pjsip set logger , the amount of traffic will often flood the CLI. This makes it incredibly difficult to debug SIP calls via the CLI, requiring the use of either the generated log file (which can also be large), or third party tools (such as Wireshark or tcpdump).

While third party tools are often fantastic for helping troubleshoot VoIP issues, on some production systems, it may not be possible to install said tools. As such, it’s still sometimes nice if Asterisk can help troubleshoot issues as well. Coming in Asterisk 13.8.0, a new module – res_pjsip_history  – has been added that provides capturing, filtering, and display of SIP messages. In this post, we’ll cover how to use the module, as well as potential avenues for future enhancements to its functionality.

Using the PJSIP History Module

The PJSIP history module maintains an in-memory history of all sent/received SIP messages that pass through the PJSIP stack. Because the history is stored in-memory, it does not start capturing until told to, and users should be careful to turn off the capture and not leave it running. You can run your system out of memory if you leave it on permanently!

Capturing Messages

To start capturing, run the pjsip set history on  command:

c4b97349e93a*CLI> pjsip set history on
PJSIP History enabled

You can stop capturing by running the pjsip set history off  command:

c4b97349e93a*CLI> pjsip set history off
PJSIP History disabled

This doesn’t clear the captured history, it merely stops capturing new SIP messages. You can re-enable the capture by running pjsip set history on  again. To clear the history, run pjsip set history clear :

c4b97349e93a*CLI> pjsip set history clear
PJSIP History cleared

Manipulating a Capture

All of that is fine and good, but how do we look at captured messages?

To show the entire history, we can use pjsip show history , which will provide a summary of the history:

*CLI> pjsip show history
No.   Timestamp  (Dir) Address                  SIP Message                        
===== ========== ============================== ===================================
00000 1455284512 * <== 127.0.0.1:5061           INVITE sip:sipp@127.0.0.1:5060 SIP/2.0
00001 1455284512 * ==> 127.0.0.1:5061           SIP/2.0 401 Unauthorized
00002 1455284512 * <== 127.0.0.1:5061           ACK sip:sipp@127.0.0.1 SIP/2.0
00003 1455284512 * <== 127.0.0.1:5061           INVITE sip:sipp@127.0.0.1:5060 SIP/2.0
00004 1455284512 * ==> 127.0.0.1:5061           SIP/2.0 401 Unauthorized
00005 1455284512 * <== 127.0.0.1:5061           ACK sip:sipp@127.0.0.1 SIP/2.0
00006 1455284512 * <== 127.0.0.1:5061           INVITE sip:sipp@127.0.0.1:5060 SIP/2.0
00007 1455284512 * ==> 127.0.0.1:5061           SIP/2.0 401 Unauthorized
00008 1455284512 * <== 127.0.0.1:5061           ACK sip:sipp@127.0.0.1 SIP/2.0

That can be a lot of messages on a busy system. To look at a particular SIP message, we can tell Asterisk to display a specific entry:

*CLI> pjsip show history entry 6
<--- History Entry 6 Received from 127.0.0.1:5061 at 1455284512 --->
INVITE sip:sipp@127.0.0.1:5060 SIP/2.0
Via: SIP/2.0/UDP 127.0.1.1:5061;received=127.0.0.1;branch=z9hG4bK-14157-3-0
From: "sipp" <sip:sipp@127.0.1.1>;tag=14157SIPpTag003
To: "sipp" <sip:sipp@127.0.0.1>
Call-ID: 3-14157@127.0.1.1
CSeq: 1 INVITE
Contact: <sip:sipp@127.0.1.1:5061>
Max-Forwards: 70
Subject: Performance Test
Content-Type: application/sdp
Content-Length: 129
Content-Type: application/sdp
Content-Length:   129

v=0
o=user1 53655765 2353687637 IN IP4 127.0.1.1
s=-
c=IN IP4 127.0.1.1
t=0 0
m=audio 6000 RTP/AVP 0
a=rtpmap:0 PCMU/8000

*CLI>

Note that the entry numbers are displayed in the left hand column, and are simply a monotonically increasing value for each SIP message received or transmitted. Now that we have a particular INVITE request, we could filter our SIP messages further. pjsip show history  supports a simple filter query syntax similar to SQL or other query languages. To see everything in this dialog, we can filter by SIP Call-ID using pjsip show history where sip.msg.call-id = “3-14157@127.0.1.1” :

*CLI> pjsip show history where sip.msg.call-id = "3-14157@127.0.1.1"
No.   Timestamp  (Dir) Address                  SIP Message                        
===== ========== ============================== ===================================
00006 1455284512 * <== 127.0.0.1:5061           INVITE sip:sipp@127.0.0.1:5060 SIP/2.0
00007 1455284512 * ==> 127.0.0.1:5061           SIP/2.0 401 Unauthorized
00008 1455284512 * <== 127.0.0.1:5061           ACK sip:sipp@127.0.0.1 SIP/2.0

There are a number of fields currently supported by the pjsip show history  command, including:

• number : The PJSIP history entry number
• timestamp : The time the SIP message was sent or received
• addr : The source/destination address the SIP message was received from/transmitted to
• sip.msg.request.method : The SIP request method
• sip.msg.call-id : The SIP Call-ID header value

The query syntax supports all normal boolean operators, as well as a regex operator ‘LIKE’. This provides quite a bit of flexibility when searching through a large SIP history.

Extending the PJSIP History Filters

Of course, there are a lot of fields in a SIP message that are not currently supported by the pjsip show history  command. In the first release of this module, we wanted to focus on providing what we thought were the most useful fields, as opposed to a comprehensive list of headers/fields that may not be terribly useful. If, however, there is a field that you think would be useful to have, the module is relatively easy to extend!

First, we’d define a new entry to the table of allowed_fields , shown below:

/*! brief The fields we allow */
static struct allowed_field allowed_fields[] = {
    { .symbol = "number", .return_type = OPT_INT_T, .get_field = entry_get_number, },
    /* We co-op the NOOP type here for timeval */
    { .symbol = "timestamp", .return_type = OPT_NOOP_T, .get_field = entry_get_timestamp, },
    { .symbol = "addr", .return_type = OPT_SOCKADDR_T, .get_field = entry_get_addr, },
    { .symbol = "sip.msg.request.method", .return_type = OPT_CHAR_ARRAY_T, .get_field = entry_get_sip_msg_request_method, },
    { .symbol = "sip.msg.call-id", .return_type = OPT_CHAR_ARRAY_T, .get_field = entry_get_sip_msg_call_id, },
};

We need to provide three things for an entry here:

• symbol : The name of the field we want the user to enter. Each one of these in the table has to be unique.
• return_type : The type of value the user has to enter. This has to be one of the OPT_XXX  types defined in include/asterisk/config_options.h . The functions that define how a boolean operator will handle the field will understand the values defined there, and will know how to interpret the field’s type. Note that OPT_NOOP_T  is used for timestamps, and OPT_SOCKADDR_T  for IP addresses.
• get_field : Our callback function that determines how to extract the field’s actual value from a PJSIP history entry.

The next step is simply to define the callback function that is referenced by the get_field  attribute. A callback function takes in a pointer to a struct pjsip_history_entry  instance, and must return a void  pointer to the field in that struct  that is the value to be used in the expression. For example, the SIP Call-ID header is extracted as shown below:

/*! brief Callback to retrieve the entry's SIP Call-ID header */
static void *entry_get_sip_msg_call_id(struct pjsip_history_entry *entry)
{
    pjsip_cid_hdr *cid_hdr;

    cid_hdr = PJSIP_MSG_CID_HDR(entry->msg);

    return &cid_hdr->id;
}

The boolean expression evaluators will know that the field pointed to by this function is a string as the return_type  attribute in the allowed_fields  table is a OPT_CHAR_ARRAY_T , and will handle it accordingly.