[asterisk-dev] Logging/debug features: 3 ideas for discussion

[John Todd]

I am probably sure this has been discussed on -dev before, but my 
memory is failing me and so I'm hoping that someone can provide me 
with a quick refresher on some reasoning.  Perhaps this is a dead 
horse - if so, please just refer me to the thread where this has been 
discussed and I'll go and read that thread (Google hasn't helped with 
the keywords I'm using.)  There are even prior threads where some 
more simplistic ideas were discussed on debugging(see note 1), but 
nothing that seems to reference the three areas in which I have 
always noticed lacking functionality in the Asterisk debugging 
methods.  As dialplans get larger and more complex, better debugging 
is mandatory for figuring out what's going on when obscure problems 
arise.  I have heard quite a few complaints from various Asterisk 
developers (and non-Asterisk developers especially) who mock the lack 
of debugging capability when trying to root out problems.  Getting 
mocked is always a bad thing, wouldn't you agree?  So I propose these 
three modifications to Asterisk to prevent mockage during 
troubleshooting:


Channel Name Logging
Currently when Asterisk is in verbose/debug mode on the console, the 
channel name is not printed on the line of debug.  This seems to be a 
fairly basic element that could be added, and would allow some simple 
"grep" statements in a post-call scenario to allow viewing of 
individual call threads.  As it is now, debugging is mostly useless 
if there is more than one call on the system since there is no way to 
differentiate between events created by different calls.  (see note 
2)  If there exists a channel name, why not print it at the start of 
the message as an optional assist to bug tracking?  Plus, this might 
lead to someone writing a tool that parses logfiles and allows one to 
follow channels as they spawn other channels, and the like. 
Currently, that is not possible.


Timestamps
It seems that STRFTIME (or the set of commands Asterisk uses from 
within STRFTIME) is limited to not displaying milliseconds, and this 
translates into logfiles that do not contain millisecond events on 
timestamps.  Since Asterisk is being run now on machines that can 
process hundreds or thousands of commands per second on multiple 
channels, this leads to some very frustrating debugging issues where 
the timestamp is virtually useless.   (In fact, Google reports that 
#3 in the listing return for "STRFTIME milliseconds" is a recent 
thread on -dev about this topic.)  While I know that STRFTIME doesn't 
have the capability for milliseconds, it does seem to me to be an 
issue of increasing importance.  It would be wonderful to have 
NTP-synchronized timestamps that were accurate to the millisecond 
across all my systems.  However, I'd be willing to accept just 
locally-accurate timestamps across multiple channels on the same 
system, using some arbitrary time pointer.  As long as each channel 
was consistent with all other channels in logging events on the same 
system in regards to millisecond time, that would be a big jump 
forward in debugging capability.  While getting globally-accurate 
millisecond timestamps may be difficult, it would be great. Barring 
that, even internally-consistent (across channels) millisecond 
timestamps would be a good start.  Again, this could be an optional 
configuration command for those who are time purists (though getting 
NTP would be the best solution for those same time purists, which I 
would also prefer.)


Real-Time Activation Per-Call
Also, while this may have slipped by me in some of the more esoteric 
functions that have been built over the last several months, but I 
don't see any way of turning on debug or verbose from within the 
dialplan, which would help quite a bit.  We have production systems 
with many thousands of calls in a VERY short timeframe, and turning 
on debug or verbose on all channels is an immediate "swamp" with data 
to the console or to the logfile(s).  Wouldn't it be great to have 
something like:

exten => 1234,1,Set(LOG(debug)=5)

and then I could watch a specific call go through it's paces on the 
console and see where things break, or what happens, or whatever the 
reason is for my debug.  Right now, it's impossible to see what's 
going on.  Here's what I'd love to see as a LOG function:

   [another excerpt from my imaginary Asterisk system with func_log 
after being written]

jt-imaginary*CLI> core show function LOG
   -= Info about function 'LOG' =-

[Syntax]
LOG(<name>[,options])

[Synopsis]
Gets or sets logging levels for current channel or system

[Description]
Name:
    debug = sets debug level to a value from 0-5.  This value will override the
             existing default value for the system for this channel, if set.
             This value can be read and written.
    verbose = sets verbose level to a value from 0-5. This value will override
               the existing default value for the system for this channel, if
               set. This value can be read and written.

Options:
   'c' changes the level of output to the console (This is the default if not
        specified.)
   'd' sets the debug and verbose values to whatever is the system default.
   'f' changes the level of output to the logfiles.
   'g' sets the global values for this level (works only in conjunction
        with 'f'ile and 'c'onsole settings; acts like entered from console)
   'i' makes channels called with "Dial" from this channel inherit the debug
        and verbosity settings from this channel.  This is recursive, so any
        channels called from those channels (in the case of using Local
        channels specifically) will inherit the settings.
   'sX' changes the level of output to the syslog logger facility to localX,
         where "X" is a number between 0-9.

jt-imaginary*CLI>


OK, that wraps up yet another one of my famous feature request 
set/app documentation screeds.  I'd like to hear discussion on these 
- it seems too obvious that they haven't been implemented before, so 
I'm hoping someone can just point me at where this can be done in the 
existing code.

JT


(1) http://lists.digium.com/pipermail/asterisk-dev/2007-January/025811.html
(2) I've been using Asterisk for quite some time, and I keep meaning 
to really dig into the code that does writing to console/logfiles for 
debugging to look for where the channel name might be optionally 
prepended to debug lines.  I'm really hoping that I'm just missing 
something obvious here, since this seems such an obviously "good" 
thing to have.  Am I just blind?