Asterisk 11 Development: Call IDs for Asterisk Logs

By Matt Jordan

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.

To Learn more about Asterisk 11, visit our wiki.

Related Posts

There Are 4 Comments

  • this is great we are trying to do caller ID shown in CDR

  • Ludovic Gasc (Eyepea) says:

    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.

  • EllisGL says:

    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.

Add to the Discussion

Your email address will not be published. Required fields are marked *

About the Author

Matt Jordan

Matt Jordan joined Digium in July of 2011. Since joining Digium, he has served as lead on the Asterisk open source project, as an Engineering Manager, and as Director of Technology. In June 2016, Jordan was named CTO of Digium. In this role, Jordan is responsible for technology and architectural decisions used in the Company’s product and service offerings. Jordan holds a Bachelor of Science degree in Computer Engineering from Michigan Technological University, and a Master of Science degree in Electrical Engineering from Louisiana State University and multiple patents.

See All of Matt's Articles