Overview¶

Unique Call-ID Logging is meant to make log messages easily understood to relate with a particular call in Asterisk. This concept was branched off from Clod Patry's CLI filtering patch. The CLI filtering patch used thread storage to link threads to channels. If filters were set in CLI, channels bound to the thread would be examined to see if they are part of a call involved with some field specified on the channel (channel name, accountcode, or callerid num). That patch has been determined to have significant problems related to locking, which if resolved could potentially result in a heavy performance hit with logging, so some concepts from it were split off in order to design this feature, which basically just adds a uniquely identifying value for the call-id to all log messages which can be identified as relating to a certain call.

Table of Contents¶

Specification¶

A is a unique identifier that is associated with a complete call and the elements that compose it. Logs that could benefit from this can occur both before any channels for that call are created, and after all channels in a call are destroyed. The is bound to any channels that are created by something associated with the . Only log statements that can be associated with a call are tagged with a ; some log statements related to a call can occur before a can be created (it isn't always immediately known when one will be needed). In a typical Asterisk log file, a call's log messages can look something like the following:

log

css[Mar 7 00:00:00] VERBOSE[6165] netsock2.c: == Using SIP RTP CoS mark 5
[Mar 7 00:00:00] DEBUG[6165] call_identifier.c: <function stuff>: CALL_ID [C000001] created by thread.
[Mar 7 00:00:00] DEBUG[6167][C00000001] call_identifier.c: <function stuff>: CALL_ID [C000001] bound to thread.
[Mar 7 00:00:00] VERBOSE[6167][C00000001] pbx.c: -- Executing [023@sipphones:1] Dial("SIP/123-00000000", "SIP/GoldFishGang") in new stack
[Mar 7 00:00:00] VERBOSE[6167][C00000001] netsock2.c: == Using SIP RTP CoS mark 5
...
[Mar 7 00:00:00] VERBOSE[6167][C00000001] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 7 00:00:00] VERBOSE[6167][C00000001] pbx.c: -- Executing [023@sipphones:2] NoOp("SIP/123-00000000", "Oh wait, that isn't a thing.") in new stack
[Mar 7 00:00:00] VERBOSE[6167][C00000001] pbx.c: -- Auto fallthrough, channel 'SIP/123-00000000' status is 'CHANUNAVAIL'
[Mar 7 00:00:00] DEBUG[6167][C00000001] call_identifier.c: <function stuff>: Call ID [000001] dereffed and destroyed by thread [6167]

This case represents a simple scenario where a a SIP packet is received which starts a new call. Before a channel can be created, The SIP channel driver anticipates a new call will be started and creates a related to that call. The call id is referenced by the pbx thread created for that channel. [000001].

Many users use Asterisk from the perspective of the CLI. By default, verbose messages in CLI don't display the call-id file. In order to accommodate these users without forcing them to look at log files, a cli command to enable the to be displayed with the verbose message will need to be added (which could be placed in startup_commands).

nonecore set verbose_callids on = yes

This would effectively change the display of a verbose message on CLI from:

css-- Executing [023@sipphones:2] NoOp("SIP/123-00000000", "Oh wait, that isn't a thing.") in new stack

to:

css-- [C00000001] Executing [023@sipphones:2] NoOp("SIP/123-00000000", "Oh wait, that isn't a thing.") in new stack

Having call identifiers in log messages like this could greatly help users to visually parse what is happening with their calls and could also be helpful in identifying problems from the perspective of support or development.

A callid string should always appear as an 8-digit hexadecimal number in the following format: [C########]

Design¶

The is a refcounted object that stores a uniquely identifying value

Call-ID struct¶

The struct should be stored in an ao2 container for reference counting. All channel threads should reference one and only one call-id in thread storage and for the lifetime of the thread, they will hold one reference. Since the call-id is stored in thread storage for the channel thread, it should persist through masquerades. The channel tech itself might need to reference the so that it can be linked to the call if it becomes a zombie. Any applications that produce monitor threads (like audio hooks) that attach to a call will also need to add a reference to the call-id in thread storage belonging to the newly created thread. Theads that hold call-id's will need to give up those references when they die.

logger.h

Eclipsecpp
struct ast_callid {
 int call_identifier; /* Numerical value of the call displayed in the log */
};

Call-ID API¶

cpp
/*!
 * \brief factory function to create a new uniquely identifying callid.
 *
 * \retval ast_callid struct pointer containing the call id (and other information if that route is taken)
 *
 * \note The newly created callid will be referenced upon creation and this function should be
 * paired with a call to ast_callid_deref()
 */
struct ast_callid \*ast_create_callid();

/*!
 * \brief Increase callid reference count
 *
 * \param c the ast_callid
 *
 * \retval c always
 */
#define ast_callid_ref(c) ({ ao2_ref(c, +1); (c); )}

/*!
 * \brief Decrease callid reference count
 *
 * \param c the ast_callid
 *
 * \retval NULL always
 */
#define ast_callid_unref(c) ({ ao2_ref(c, -1); (struct ast_channel \*) (NULL); )}

/*!
 * \brief Adds a known callid to thread storage of the calling thread
 *
 * \retval -1 - failure to allocate thread storage
 * \retval 0 - success
 * \retval 1 - failure due to thread already being bound to a callid
 */
int ast_callid_threadassoc_add(struct ast_callid \*callid);

Logging - Thread storage and ast_log_callid¶

In order to avoid having to modify every log call in Asterisk, Clod's patch used thread storage to store a channel pointer. Since it was stored in thread storage, it didn't need to be directly passed to the function and could just be checked at the time of log output for the existence of relevant data. In this way, CLI filtering could log messages between different calls without any new arguments to ast_log. A similar method could be used to bind threads to s.

This alone may not be enough to handle all logs related to specific calls though. Some threads that get involved with specific calls change which call they are working on frequently (notably channel drivers) and in these cases, the proper solution might be to introduce a secondary ast_log function which includes either a reference to the being worked with or else just the value of the

ast_log_callid(struct call_id *id, args from ast_log) - Acts as ast_log currently does, except if call_id is not NULL, then [CALL_ID] will be attached after the thread ID as shown above for written log statements. For verbose logs in CLI, it will not be displayed

**ast_log(*****args from ast_log*****)** **-** Acts as ast_log currently does, except it checks thread storage to see if the thread calling ast_log is bound to a callid. If it is, then the callid is passed to ast_log_callid.  If not, a NULL value is passed for call_id instead.

ast_log will become a helper function to ast_log_callid.

Handling and Spreading Call IDs - Channel Drivers, Channel/PBX threads, and Application Threads¶

Each call starts with a channel driver responsible for creating channels. In the case of SIP for example, the channel driver has a thread which reads incoming SIP messages, and if one of these SIP messages happens to be requesting a call of some sort, then Asterisk will eventually create a channel thread for it. There may be some relevant log messages between the time a channel driver has discerned that a new call is taking place and when it has actually created the channel (and PBX thread) associated with it. Since the lifetime of logs related to a call starts before the birth of any PBX threads related to the call (and possibly also after the death of the call), each individual channel driver will be responsible for creating and linking them to the channels and pbx threads that need them.

In the case of threads that interact with multiple channels from multiple calls, thread storage can't be used to handle the log messages. For these types of situations, the will need an additional reference stored in channels that are part of the call and threads working with these channels will have to read the from each channel before processing logs with ast_log_callid.

Also, certain applications such as mixmonitor will create threads which act within the call, but are slightly disjoint from the call itself. The tentative approach for dealing with these threads is to copy the in thread storage from the threads responsible for creating them to to the created threads by manipulating ast_pthread_create (and/or its variants).

Running through a simple example call with an audiohook¶

1. An invite request comes in through the SIP channel driver. The driver handles the request in the handle_request_invite function and determines that the dialog is going to create a new channel.
2. handle_request_invite determines the call to be a 'first invitation' and creates a new ast_callid with ast_create_callid() which it will store in a local variable. Some log messages
3. handle_reqeust_invite creates a new SIP channel with a reference to the ast_callid. As part of the channel thread creation process, the call-id is put into thread storage and the ao2 object support it gets a ref bump (2).
4. As handle_request_invite is finishing, the channel driver's network monitor thread derefs the ast_callid. (1)
5. The new channel starts going through pbx on the following extension:

exten => s,1,NoOp(example no op message)
exten => s,2,MixMonitor(mixfile.wav)
exten => s,3,Dial(SIP/examplepeer)

exten => s,1,Dial(SIP/examplepeer)