[asterisk-users] Tips & best practices for asterisk troubleshooting & parsing logs

Sat Oct 29 23:29:52 CDT 2011

Hi Douglas,

You;re right, that method is useful only for one-to-one call but as soon as
the call gets transferred etc etc as you mentioned everything will get
mixed and confusing.

Any way I this can be done? Can’t a call be passed off from one channel to
> another, which would leave me with only seeing a part of the logs for the
> life of the call if I only grep the logs based on one channel id?

Yes, is the answer if you want this to implement. You need to do the
following in order to achieve an start-end logging of a call.

1- As soon as call Enters Asterisk dialplan save its UNIQUEID (plus any
other key i.e timestamp ) in a CALL-IDENTIFY variable.
2- Use the CALL-IDENTIFY variable throughout your dialplan contexts to
verbose() useful information.(I saw a log() application in asterisk 1.8.5
to do this in a the log file...i.e print logs of your own)

Another interesting thing for this purpose would be CEL, though it maynot
be available in your older deployments. I haven't toyed around with CEL
myself but so far I've the impression that its a very verbose form of CDRs.
So using CEL to keep track of your call in a DB would help as well.

Another Idea is to use the SIP-Header Call-ID as your CALL-IDENTIFY
variable. This way when you're debugging the issue using asterisk logs
alongside taking SIP-traces it'll help you identify which packets belongs
to which log lines.

Wireshark is a great tool. I take Sip traces, open up in wireshark goto
voip calls and you'll see all the calls that were at-least initiated after
when u started the trace. Apply filter on your specific call and see only
sip traces relevant to one particular call.

Thats all I could come up at this time.

I hope this would be of some help.

--
Regards,
Sammy
On Fri, Oct 28, 2011 at 11:10 PM, Douglas Mortensen <doug at impalanetworks.com
> wrote:

> Anton,****
>
> ** **
>
> Thanks for the input. I wasn’t aware of ngrep. I’ll check it out. A packet
> analyzer is a good idea. I am accustomed to using a packet analyzer mostly
> in a “reactive” approach, or during an incident. Are you suggesting that I
> just setup a capture to be running continuously until we become aware of
> the problem, and then at that point, review it to see what really happened
> (regarding what was & was not transmitted on the network)?****
>
> ** **
>
> Also, thanks for the link in the Asterisk Cookbook. I’ll check it out.****
>
> ** **
>
> From your egrep example here:****
>
> tail -f /var/log/asterisk/full | egrep --color -w
> 'chan_sip.*SIP/911|pbx.*SIP/911'****
>
> ** **
>
> Are you basically using 911 as an example extension that we wanted to see
> logging for? That seems useful. Thanks. FYI, I grepped for chan_sip, and
> pbx, but didn’t really get anything from those with any SIP extension
> logging. Could that be because I’m using asterisk 1.4? FYI, the customer
> I’m troubleshooting for is using 1.6, so maybe it would give me something
> on their version….?****
>
> ** **
>
> Still one of my concerns is the ability to follow an inbound call from the
> time it hits asterisk, until it is finally gone. I’d like to follow the
> call through the logging to have a logical view of what happened to the
> call from the time it rang in (where the call got sent to [time conditions,
> queues, ring groups, extensions, transfers, etc.], what phones were rung
> trying to connect the call, etc.****
>
> ** **
>
> Any way I this can be done? Can’t a call be passed off from one channel to
> another, which would leave me with only seeing a part of the logs for the
> life of the call if I only grep the logs based on one channel id?****
>
> ** **
>
> Thanks,****
>
> -****
>
> Doug Mortensen****
>
> Network Consultant****
>
> Impala Networks****
>
> P: 505.327.7300****
>
> ** **
>
> *From:* Anton Kvashenkin [mailto:anton.jugatsu at gmail.com]
> *Sent:* Thursday, October 27, 2011 8:27 AM
>
> *To:* Asterisk Users Mailing List - Non-Commercial Discussion
> *Subject:* Re: [asterisk-users] Tips & best practices for asterisk
> troubleshooting & parsing logs****
>
> ** **
>
> Capture pcap with tshark or tcpdump for the future analysis with
> wireshark. Ngrep is also handy tool for captaring, say, INVITE. You can use
> grep like this: tail -f /var/log/asterisk/full | egrep --color -w
> 'chan_sip.*SIP/911|pbx.*SIP/911'
> Interesting technique from Astresk Cookbook, "Debugging dialplan with
> Verbose()
> http://ofps.oreilly.com/titles/9781449303822/DialplanFundamentals.html****
>
> 2011/10/27 Sammy Govind <govoiper at gmail.com>****
>
> It was a challenge to read through all the interesting experience you've
> shared over here. I don't know what others may be using for parsing the
> logs beautifully and make them usable. What I would recommend you at the
> very beginning ,since you mentioned using egrep, is figure out the Channel
> identifier string from the logs for a particular call. That's underlined
> below for you.****
>
> ** **
>
> [Oct 26 17:58:01] VERBOSE[14274] logger.c:     -- Executing [s at tc-maint:3]
> System("*Local/s at tc-maint-2496,2*","/var/lib/asterisk/bin/schedtc.php 60
> /var/spool/asterisk/outgoing 0") in new stack****
>
> ** **
>
> Once you Figure out this part use egrep tool and you'll end up seeing only
> the data related to this particular call.****
>
> ** **
>
> More advanced tool or techniques may involve setting up a central logging
> server where all the other servers deposit their logs and use monitoring
> tools like swatch, splunk, zabbix etc etc etc to parse the logs for you and
> generate alerts. ****
>
> ** **
>
> I haven't came across any Asterisk-specific log parser utility so far.
> Honestly, I never needed one.****
>
> ** **
>
> On Thu, Oct 27, 2011 at 5:16 AM, Douglas Mortensen <
> doug at impalanetworks.com> wrote:****
>
> Hello all,
>
> I have been running asterisk systems since summer of 2008. I do not claim
> to be an expert. But I have worked through many issues during this period.
> I have setup & manage 5 systems, which serve 6 companies total (and of
> course process calls for all of the people they do business with).
>
> I have always been happy with asterisk (well, obviously less happy during
> the problem times... :-). And I continue to prefer to us it. However, if I
> could name the one largest struggle that I have with asterisk, it is the
> facilities that it provides for troubleshooting issues & parsing logs.
>
> I am hoping that someone on this mailing list can help me to realize how
> ignorant I really am, and how much time I have wasted parsing, "grep"ping &
> "less"ing logs manually. I am hoping that one of you can help me "see the
> light". If so, I would be most grateful.
>
> Specifically, here are the challenges I encounter, which I would
> desperately appreciate help with:
>
> Here's an example scenario:
>
> A customer calls me & says that a call just came in & some of their
> wireless DECT phones (I know, trouble already.... :-) didn't ring, while
> others did. I tell the customer that I'll start looking into the problem
> immediately.
>
> I am using AsteriskNOW with asterisk 1.6. So I SSH into the system & cd to
> /var/log/asterisk & start looking at the "full" log via "less". We have
> configured the bulk of our system via FreePBX 2.9. Inbound calls are routed
> first to a time condition which checks whether it is after hours. If it is
> not afterhours, then are then routed to a queue, which rings all phones (4
> wireless DECT phones on 1 DECT wireless server that registers the SIP
> extensions on behalf of its 4 phones, and 4 more wireless DECT phones on
> their own wireless server configured the same, and an ATA connected to a
> paging amp that rings a loud speaker). From there, someone typically will
> answer the call. Often times they then transfer the call to another
> extension. However, sometimes no one answers the call, and it winds up
> going to VM.
>
> >From the logging aspect of asterisk, it has usually felt like I am
> trudging through a swampy marsh trying to put the bits & pieces together.
> The challenge I've seen is that the above scenario can actually consist of
> multiple SIP calls w/ different legs. I *think* (but am not 100% sure) that
> often times a call can be handed off from 1 asterisk process to another.
> The result is that "grep"ping by the asterisk process ID shown after the
> VERBOSE (or NOTICE or DEBUG section [see below]), I don't actually get to
> see the full sequence of events in following  all logging that is relevant
> to that phone call.
>
> [Oct 26 17:58:01] VERBOSE[14274] logger.c:     -- Executing [s at tc-maint:3]
> System("Local/s at tc-maint-2496,2","/var/lib/asterisk/bin/schedtc.php 60
> /var/spool/asterisk/outgoing 0") in new stack
>
> Then on a busy asterisk system, if I filter by the process id, the one
> process that starts handling the call originally, may wind up immediately
> taking on another totally unrelated call after handing the initial call off
> to another process. If I am not extremely careful, I may wind up mistaking
> the log lines for the 2nd call, as being a part of the 1st call, and then
> I'm totally barking up the wrong tree.... :-)
>
> Another option I've tried is to enable SIP debugging. Generally, I do like
> this. And one nice thing is that asterisk seems to usually add the SIP
> "Date:" parameter with its SIP invites, etc. The result is that I can grep
> the asterisk log like this `egrep -v ^"\[" full` (SIP debug lines don't
> have the standard timestamp at the beginning) and then I'm only seeing the
> SIP debugging, in a pretty clean output. Still, there can be a LOT of SIP
> traffic going on, when I'm ringing 9 different extensions from a queue.
> Trying to parse it all can make me go cross-eyed. :-) And doing so can take
> a LONG time (30+ minutes). The SIP debug lines don't necessarily tell me
> which call they correspond with. So if there are multiple calls going on or
> ringing at the same time, this can really get hairy.
>
> So more or less, I think I've sort of established the type of experience I
> have with parsing the asterisk logging in troubleshooting issues.
> Ultimately, I usually can get to the bottom of it, but it literally
> probably takes 45-60+ minutes of just parsing through the log files before
> I even get to the point, of being able to answer some seemingly simple
> questions.
>
> Am I going about this the wrong way? Please say yes. Because this is
> literally probably the only challenge (& sometimes frustration) I have with
> asterisk. Are there [much] better ways to go about this?
>
> I did a bit of searching online, and it seems that some people have
> attempted to create tools to parse & display the asterisk full log in a
> more structured simplified manner. But my initial impression was that these
> were more of "good ideas" that people started on, but they haven't really
> matured to the point of being really helpful with these types of situations.
>
> A part of me just thinks that it just shouldn't be so hard to be able to
> tell whether a certain extension did actually get a SIP INVITE sent to it,
> or whether it responded, or to simply just follow the chain of the route
> that a call took through asterisk prior to running into trouble (or just
> where it ended up).
>
> It seems to me that there should be some powerful tool that does the hard
> work of parsing the related log lines for us, so that we can just *quickly*
> review its output & see the sequence of events to determine exactly what
> happened.
>
> Only when we find out what happened, can we even start working on the
> solution.
>
> If you have some insight into reviewing, filtering & parsing asterisk logs
> in the process of troubleshooting issues, I would GREATLY appreciate it.
>
> What approach would you take? What are the best practices, tips & secrets
> that you've developed?
>
> Thanks all!
> -
> Doug Mortensen
> Network Consultant
> Impala Networks Inc
> CCNA, MCSA, Security+, A+
> Linux+, Network+, Server+
> A.A.S. Information Technology
> .
> www.impalanetworks.com
> P: (505) 327-7300
> F: (505) 327-7545
>
>
> --
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
> New to Asterisk? Join us for a live introductory webinar every Thurs:
>               http://www.asterisk.org/hello
>
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>   http://lists.digium.com/mailman/listinfo/asterisk-users****
>
> ** **
>
>
> --
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
> New to Asterisk? Join us for a live introductory webinar every Thurs:
>               http://www.asterisk.org/hello
>
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>   http://lists.digium.com/mailman/listinfo/asterisk-users****
>
> ** **
>
> --
> _____________________________________________________________________
> -- Bandwidth and Colocation Provided by http://www.api-digital.com --
> New to Asterisk? Join us for a live introductory webinar every Thurs:
>               http://www.asterisk.org/hello
>
> asterisk-users mailing list
> To UNSUBSCRIBE or update options visit:
>   http://lists.digium.com/mailman/listinfo/asterisk-users
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20111030/06bb3a72/attachment.htm>