Asterisk 11 Development: Call IDs for Asterisk Logs
Matt Jordan July 19th, 2012
The beta of Asterisk 11 is rapidly approaching, and we thought we’d highlight some of the features that have been added to Asterisk in this new major release. Previously, Kevin discussed WebSocket support – this time, we’ll look at Call ID logging. The original idea for Call IDs came from a member of the Asterisk Open Source Developer community, Clod Patry, and was implemented for Asterisk 11 by our own Jonathan Rose.
So what is Call ID logging? While we’d like to say that Asterisk never needs to be debugged, it’s often the case that you need to know why Asterisk behaved in a particular manner. Often, this means looking at a log file created with the DEBUG log level. Since an Asterisk log file will contain messages from all calls currently occurring in the system, it can be difficult to figure out what messages apply to which call. For example, consider this log snippet showing SIP establishing multiple calls at the same time:
[Jul 8 10:27:17] DEBUG[24529] chan_sip.c: We're settling with these formats: (ulaw|h261|t140)
[Jul 8 10:27:17] DEBUG[24529] chan_sip.c: Checking SIP call limits for device
[Jul 8 10:27:17] DEBUG[24529] chan_sip.c: Updating call counter for incoming call
[Jul 8 10:27:17] DEBUG[24529] netsock2.c: Splitting '127.0.0.1:5060' into...
[Jul 8 10:27:17] DEBUG[24529] netsock2.c: ...host '127.0.0.1' and port ''.
[Jul 8 10:27:17] DEBUG[24529] netsock2.c: Splitting '127.0.0.1:5070' into...
[Jul 8 10:27:17] DEBUG[24529] netsock2.c: ...host '127.0.0.1' and port ''.
We’re clearly parsing IP addresses – but are we doing this for a single call? Are we doing it for multiple? If so, which call corresponds to 127.0.0.1:5060, and which one for 127.0.0.1:5070? And, do those log statements correspond to the format negotiation log statements that occur just prior to the IP address parsing?
Notice that we can’t use the thread identifier (the [24529] in the above log statements) to make these determinations, as that single thread could be handling SIP requests and responses for multiple calls. We need something else to provide that information.
Now, take a look at a very similar log snippet, taken from the current Asterisk trunk:
[Jul 8 10:35:14] DEBUG[32726][C-0000000b] netsock2.c: Splitting '127.0.0.1:5071' into...
[Jul 8 10:35:14] DEBUG[32726][C-0000000b] netsock2.c: ...host '127.0.0.1' and port '5071'.
[Jul 8 10:35:14] DEBUG[32762][C-0000000a] chan_sip.c: SIP answering channel: SIP/guest1-00000005
[Jul 8 10:35:14] DEBUG[32762][C-0000000a] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jul 8 10:35:14] DEBUG[32726][C-0000000b] netsock2.c: Splitting '127.0.0.1:5071' into...
[Jul 8 10:35:14] DEBUG[32726][C-0000000b] netsock2.c: ...host '127.0.0.1' and port ''.
[Jul 8 10:35:14] DEBUG[32762][C-0000000a] chan_sip.c: Setting framing from config on incoming call
You’ll note there’s a new identifier in the log statements – [C-XXXXXXXX]. That identifier is a “Call ID” – not to be confused with Caller ID! When a channel is created by a channel technology, it gets a new identifier assigned to it. From there on, all log statements associated with that channel get stamped with the Call ID. This makes it possible to determine what log statements correspond to what channel.
Going back to that example, we can see that there are actually two calls being affected here – C-0000000a and C-0000000b. If we only cared about log statements pertaining to the call with the C-0000000b identifier, we could use common Linux tools to filter only for that identifier, and get only the log statements we care about. This makes debugging problems on busy systems significantly easier.
Call IDs aren’t necessarily tied to the lifetime of a channel – they’re tied to the lifetime of a call, which may involved multiple channels. When two channels are bridged, if both channels currently have a Call ID, one of the Call IDs is retired, and one of the channels receives the Call ID of the channel its bridged to. When this happens, a DEBUG log statement is made, notifying you of the change:
[Jul 7 21:47:25] DEBUG[476][C-0000000c] channel_internal_api.c: Channel Call ID changing from [C-0000000c] to [C-0000000d]
This lets you tie together information about a channel for all the calls that the channel may be involved in.
With this feature in Asterisk 11, it will become easier for people to view all of the log output for only those calls that they’re interested in, even on busy systems. This makes diagnosing and fixing problems faster and easier then ever before.
[...] http://blogs.digium.com/2012/07/19/asterisk-11-development-call-ids-for-asterisk-logs/ Share this:TwitterFacebookLike this:LikeBe the first to like this. [...]
this is great we are trying to do caller ID shown in CDR
An AMI event is also generated for this? If yes, it will easier to follow a call via AMI.
No, this doesn’t affect AMI events currently. It could be made to fairly easily though, but currently whether an AMI event sends CallID or not is dependent on the AMI event being sent. Adding CallID headers to AMI events as they are available is certainly something we could look into.
Currently in testing mode (enabled TEST_FRAMEWORK from menuselect) an AMI event will be sent when the call ID changes for any given channel, but that’s just for testing. That could also be changed fairly easily though. It’d simply be a matter of removing the compilation flag requirement.
Jonathan,
I’m with Ludovic on this. Following a call based on the Unique ID’s in the AMI is a PITA. I would love to see this in the AMI.