<html>
<head>
<base href="https://wiki.asterisk.org/wiki">
<link rel="stylesheet" href="/wiki/s/en/2171/18/9/_/styles/combined.css?spaceKey=AST&forWysiwyg=true" type="text/css">
</head>
<body style="background: white;" bgcolor="white" class="email-body">
<div id="pageContent">
<div id="notificationFormat">
<div class="wiki-content">
<div class="email">
<h2><a href="https://wiki.asterisk.org/wiki/display/AST/Unique+Call-ID+Logging">Unique Call-ID Logging</a></h2>
<h4>Page <b>added</b> by <a href="https://wiki.asterisk.org/wiki/display/~jrose">Jonathan Rose</a>
</h4>
<br/>
<div class="notificationGreySide">
<h1><a name="UniqueCall-IDLogging-Overview"></a>1. Overview</h1>
<p>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.</p>
<h1><a name="UniqueCall-IDLogging-TableofContents"></a>2. Table of Contents</h1>
<style type='text/css'>/*<![CDATA[*/
div.rbtoc1331919282501 {margin-left: 1.5em;padding: 0px;}
div.rbtoc1331919282501 ul {list-style: disc;margin-left: 0px;padding-left: 20px;}
div.rbtoc1331919282501 li {margin-left: 0px;padding-left: 0px;}
/*]]>*/</style><div class='rbtoc1331919282501'>
<ul>
<li><a href='#UniqueCall-IDLogging-Overview'>1. Overview</a></li>
<li><a href='#UniqueCall-IDLogging-TableofContents'>2. Table of Contents</a></li>
<li><a href='#UniqueCall-IDLogging-Specification'>3. Specification</a></li>
<li><a href='#UniqueCall-IDLogging-Design'>4. Design</a></li>
<ul>
<li><a href='#UniqueCall-IDLogging-CallIDstruct'>4.1. Call-ID struct</a></li>
<li><a href='#UniqueCall-IDLogging-CallIDAPI'>4.2. Call-ID API</a></li>
<li><a href='#UniqueCall-IDLogging-LoggingThreadstorageandastlogcallid'>4.3. Logging - Thread storage and ast_log_callid</a></li>
<li><a href='#UniqueCall-IDLogging-HandlingandSpreadingCallIDsChannelDrivers%2CChannel%2FPBXthreads%2CandApplicationThreads'>4.4. Handling and Spreading Call IDs - Channel Drivers, Channel/PBX threads, and Application Threads</a></li>
<li><a href='#UniqueCall-IDLogging-Runningthroughasimpleexamplecallwithanaudiohook'>4.5. Running through a simple example call with an audiohook</a></li>
<li><a href='#UniqueCall-IDLogging-Runningthroughasimpleexamplecallwithtransfers'>4.6. Running through a simple example call with transfers</a></li>
</ul>
<li><a href='#UniqueCall-IDLogging-ImplmentationPhases'>5. Implmentation Phases</a></li>
<ul>
<li><a href='#UniqueCall-IDLogging-PhaseICreaterelevantdatastructuresandAPI'>5.1. Phase I - Create relevant data structures and API</a></li>
<li><a href='#UniqueCall-IDLogging-PhaseIIHandleapplicationthreadsandothersmallimprovements%28inprogress%29'>5.2. Phase II - Handle application threads and other small improvements (in-progress)</a></li>
<li><a href='#UniqueCall-IDLogging-PhaseIIIMigrate%3Ccallid%3Ecreationandbindingtoindividualchanneldrivers'>5.3. Phase III - Migrate <call-id> creation and binding to individual channel drivers</a></li>
</ul>
<li><a href='#UniqueCall-IDLogging-OpenQuestions'>6. Open Questions</a></li>
</ul></div>
<h1><a name="UniqueCall-IDLogging-Specification"></a>3. Specification</h1>
<p>A <call-id> is a unique identifier that is associated with a complete call and the elements that compose it. Logs that could benefit from this <call-id> can occur both before any channels for that call are created, and after all channels in a call are destroyed. The <call-id> is bound to any channels that are created by something associated with the <call-id>. Only log statements that can be associated with a call are tagged with a <call_id>; some log statements related to a call can occur before a <call-id> 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:</p>
<div class="code panel" style="border-width: 1px;"><div class="codeHeader panelHeader" style="border-bottom-width: 1px;"><b>log</b></div><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: css; gutter: false">[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][C000001] call_identifier.c: <function stuff>: CALL_ID [C000001] bound to thread.
[Mar 7 00:00:00] VERBOSE[6167][C000001] pbx.c: -- Executing [023@sipphones:1] Dial("SIP/123-00000000", "SIP/GoldFishGang") in new stack
[Mar 7 00:00:00] VERBOSE[6167][C000001] netsock2.c: == Using SIP RTP CoS mark 5
...
[Mar 7 00:00:00] VERBOSE[6167][C000001] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1)
[Mar 7 00:00:00] VERBOSE[6167][C000001] 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][C000001] pbx.c: -- Auto fallthrough, channel 'SIP/123-00000000' status is 'CHANUNAVAIL'
[Mar 7 00:00:00] DEBUG[6167][C000001] call_identifier.c: <function stuff>: Call ID [000001] dereffed and destroyed by thread [6167]</pre>
</div></div>
<p>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 <call-id> related to that call. The call id is referenced by the pbx thread created for that channel. [000001]. </p>
<p>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 <call-id> to be displayed with the verbose message will need to be added (which could be placed in startup_commands).</p>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: plain; gutter: false">core set verbose_callids on = yes</pre>
</div></div>
<p>This would effectively change the display of a verbose message on CLI from:</p>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: css; gutter: false">-- Executing [023@sipphones:2] NoOp("SIP/123-00000000", "Oh wait, that isn't a thing.") in new stack</pre>
</div></div>
<p>to:</p>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: css; gutter: false">-- [C000001] Executing [023@sipphones:2] NoOp("SIP/123-00000000", "Oh wait, that isn't a thing.") in new stack</pre>
</div></div>
<p>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.</p>
<h1><a name="UniqueCall-IDLogging-Design"></a>4. Design</h1>
<p>The <call-id> is a refcounted object that stores a uniquely identifying value</p>
<h2><a name="UniqueCall-IDLogging-CallIDstruct"></a>4.1. Call-ID struct</h2>
<p>The <call-id> 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 <call-id> 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.</p>
<div class="code panel" style="border-width: 1px;"><div class="codeHeader panelHeader" style="border-bottom-width: 1px;"><b>logger.h</b></div><div class="codeContent panelContent">
<pre class="theme: Eclipse; brush: cpp; gutter: false">struct ast_callid {
int call_identifier; /* Numerical value of the call displayed in the logs */
};</pre>
</div></div>
<h2><a name="UniqueCall-IDLogging-CallIDAPI"></a>4.2. Call-ID API</h2>
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: cpp; gutter: false">/*!
* \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);</pre>
</div></div>
<h2><a name="UniqueCall-IDLogging-LoggingThreadstorageandastlogcallid"></a>4.3. Logging - Thread storage and ast_log_callid</h2>
<p>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 <call-id>s.</p>
<p>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 <call-id> being worked with or else just the value of the <call-id></p>
<p><b> ast_log_callid(struct call_id *id,</b> <b><em>args from ast_log</em></b><b>) -</b> 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<br/>
(though in the log files, it will be displayed as above).</p>
<p> <b>ast_log(</b><b><em>args from ast_log</em></b><b>)</b> <b>-</b> 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.</p>
<p>ast_log will become a helper function to ast_log_callid.</p>
<h2><a name="UniqueCall-IDLogging-HandlingandSpreadingCallIDsChannelDrivers%2CChannel%2FPBXthreads%2CandApplicationThreads"></a>4.4. Handling and Spreading Call IDs - Channel Drivers, Channel/PBX threads, and Application Threads</h2>
<p>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 <call-ids> and linking them to the channels and pbx threads that need them.</p>
<p>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 <call-ids> 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 <call-ids> from each channel before processing logs with ast_log_callid.</p>
<p>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 <call-id> in thread storage from the threads responsible for creating them to to the created threads by manipulating ast_pthread_create (and/or its variants).</p>
<h2><a name="UniqueCall-IDLogging-Runningthroughasimpleexamplecallwithanaudiohook"></a>4.5. Running through a simple example call with an audiohook</h2>
<ol>
<li>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.</li>
<li>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<br/>
may occur in the meantime, in which case they will use the new ast_log_callid(...) with the ast_callid that is in the local variable.</li>
<li>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).</li>
<li>As handle_request_invite is finishing, the channel driver's network monitor thread derefs the ast_callid. (1)</li>
<li>The new channel starts going through pbx on the following extension:
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: java; gutter: false">exten => s,1,NoOp(example no op message)
exten => s,2,MixMonitor(mixfile.wav)
exten => s,3,Dial(SIP/examplepeer)</pre>
</div></div></li>
<li>The NoOp gets verbose logged to CLI. In the CLI, nothing special is visible, but since ast_log is called with a thread containing an ast_callid in thread storage, so ast_log checks the thread<br/>
storage, finds an ast_callid object, and uses that to write the <call-id> number to the log message for file output as shown in the example logs above.</li>
<li>MixMonitor is reached. Verbose logging occurs as with NoOp It creates a monitor_thread which will be part of the call. When the new thread is created, the pbx thread sends the call-id to it for<br/>
use in its own thread storage so that its log messages will use the <call-id> number as well. Also this bumps the refcount (2).</li>
<li>Dial is reached. Verbose logging occurs as with NoOp, The thread enters the channel .call function (sip_call)</li>
<li>Since sip_call is occuring on the same thread, all ast_log messages should automatically get their <call-id> logged properly.</li>
<li>Nothing too fancy happens during the call, and 20 seconds later, someone hangs up.</li>
<li>During the hangup process, the channel thread dies. As part of this dying process, the ast_callid it is associated with is dereffed (1).</li>
<li>The MixMonitor thread closes out since the channels it was interacting with are all dead, so its reference to the ast_callid is also dereffed (0). Since the refcount hits zero, the ast_callid is freed.</li>
</ol>
<p>This is a simple example and some details may be incomplete (or even incorrect).</p>
<h2><a name="UniqueCall-IDLogging-Runningthroughasimpleexamplecallwithtransfers"></a>4.6. Running through a simple example call with transfers</h2>
<ol>
<li>Steps 1-4 from the above occur. For the sake of the example, the user that started the call will be called SIP/examplecaller.<br/>
Refcount on the ast_callid is (1) since it is only held by the channel thread.</li>
<li>The new channel starts going through pbx on the following extension:
<div class="code panel" style="border-width: 1px;"><div class="codeContent panelContent">
<pre class="theme: Confluence; brush: java; gutter: false">exten => s,1,Dial(SIP/examplepeer)</pre>
</div></div></li>
<li>Dial is reached and is verbose logged. The thread enters the channel .call function (sip_call)</li>
<li>Nothing too special occurs until SIP/examplecaller transfers SIP/examplepeer to SIP/examplepeer2. This means the channel that started the call thread is going to become a zombie. The call will go on though, the thread will just receive a new channel. The <call-id> can probably just stay in as is. However, the zombie will no longer be a part of the thread, so it will need to reference<br/>
the <call-id> (2).</li>
<li>Zombie cleanup events take place using ast_log_callid to attach the <call-id> stamp to the logs.</li>
<li>The zombie finally dies. During that process, it ditches a reference to <call-id> (1).</li>
<li>After some time, examplepeer gets bored of talking to examplepeer2 and hangs up. The channel thread gives up the last reference (0) and dies. When the reference count hit zero, the call-id was disposed of.</li>
</ol>
<h1><a name="UniqueCall-IDLogging-ImplmentationPhases"></a>5. Implmentation Phases</h1>
<h2><a name="UniqueCall-IDLogging-PhaseICreaterelevantdatastructuresandAPI"></a>5.1. Phase I - Create relevant data structures and API</h2>
<p>Develop a simple prototype that handles the following:</p>
<ol>
<li>Implement <call-id> structure and factory. Bind <call-id> pointers to newly created channel threads.</li>
<li>Modify logging to read thread storage so that channel thread log messages include the <call-id> stamp.</li>
</ol>
<ul>
<li>Phase I is complete as of 14 Mar 2012 <a href="http://svn.asterisk.org/svn/asterisk/team/jrose/call_identifiers" class="external-link" rel="nofollow">http://svn.asterisk.org/svn/asterisk/team/jrose/call_identifiers</a> r359343</li>
</ul>
<h2><a name="UniqueCall-IDLogging-PhaseIIHandleapplicationthreadsandothersmallimprovements%28inprogress%29"></a>5.2. Phase II - Handle application threads and other small improvements (in-progress)</h2>
<p>Improve from phase I and add:</p>
<ol>
<li>Spread references to ast_callid structs to threads created by a pbx/channel thread already bound to a <call-id>.</li>
<li>Add CLI command to display <call-id> with verbose messages on CLI.</li>
</ol>
<h2><a name="UniqueCall-IDLogging-PhaseIIIMigrate%3Ccallid%3Ecreationandbindingtoindividualchanneldrivers"></a>5.3. Phase III - Migrate <call-id> creation and binding to individual channel drivers</h2>
<ol>
<li>Add logger API for ast_log_callid</li>
<li>Anticipate call-creation on a per channel-driver basis</li>
<li>Bind call-id to pbx threads with channel threads</li>
</ol>
<h1><a name="UniqueCall-IDLogging-OpenQuestions"></a>6. Open Questions</h1>
<ul>
<li>Transfers - As of the phase I prototype, a transfer will start a new PBX thread, so it will receive a new <call-id>. This may or may not be ideal, and can probably be adjusted fairly easily to keep the call-id between calls if/when channel drivers take control of <call-id> assignment.</li>
</ul>
</div>
<div id="commentsSection" class="wiki-content pageSection">
<div style="float: right;" class="grey">
<a href="https://wiki.asterisk.org/wiki/users/removespacenotification.action?spaceKey=AST">Stop watching space</a>
<span style="padding: 0px 5px;">|</span>
<a href="https://wiki.asterisk.org/wiki/users/editmyemailsettings.action">Change email notification preferences</a>
</div>
<a href="https://wiki.asterisk.org/wiki/display/AST/Unique+Call-ID+Logging">View Online</a>
|
<a href="https://wiki.asterisk.org/wiki/display/AST/Unique+Call-ID+Logging?showComments=true&showCommentArea=true#addcomment">Add Comment</a>
</div>
</div>
</div>
</div>
</div>
</body>
</html>