[asterisk-dev] logger vs. verbosity level in Asterisk 1.8.12.2

[Paul Belanger]

On 12-07-18 07:05 PM, Sean Kelly wrote:
> Greetings,
>
> I've been developing a custom Asterisk module for my employer for just
> over a month now. It has been an enjoyable learning experience for the
> most part, and now I am getting down to brass tacks for the finishing
> work. One minor issue that I've come up against, but ignored until I
> had time to confirm it today is that the logger does not appear to be
> respecting the verbosity level that is set when monitoring the
> console. Here is the scenario:
>
> * Asterisk 1.8.12.2 on CentOS, compiled from source
> * Our custom module compiled in under the apps directory - Makefile
> takes care of this automagically
> * Using CounterPath's X-Lite 4 softphone on a Windows 7 PC to dial
> into Asterisk over SIP
> * Monitoring Asterisk console in the Linux shell
>
> Follows is the simple test scenario that reliably reproduces what I am
> looking at. I have added the following extension to the Asterisk
> configuration:
>
> /etc/asterisk/extensions.conf
> =========================================================================
> exten => 9,1,answer
> exten => 9,n,verbosity
> exten => 9,n,hangup
> =========================================================================
>
> This allows me to dial 9 on the softphone and get asterisk to answer,
> run the "verbosity" test module, and hang up.
>
> Here is the simple verbosity test module source code itself:
>
> asterisk/apps/app_verbosity.c
> =========================================================================
> #include <stdio.h>
> #include <stdlib.h>
>
> #include "asterisk.h"
>
> ASTERISK_FILE_VERSION(__FILE__, "$Revision: $")
>
> #include "asterisk/logger.h"
> #include "asterisk/channel.h"
> #include "asterisk/module.h"
>
> static char *app = "Verbosity";
> static char *synopsis = "Puts a couple test messages out to the
> console at different verbosity levels";
> static char *descrip = "Puts a couple test messages out to the console
> at different verbosity levels\n";
>
> int verbosity_exec(struct ast_channel *chan, const char *data);
> int load_module(void);
> int unload_module(void);
>
> #define FMT     "This is a test message at verbosity level [%d]\n"
> int verbosity_exec(struct ast_channel *chan, const char *data) {
>          ast_verbose(VERBOSE_PREFIX_1 FMT, 1);
>          ast_verbose(VERBOSE_PREFIX_2 FMT, 2);
>          ast_verbose(VERBOSE_PREFIX_3 FMT, 3);
>          ast_verbose(VERBOSE_PREFIX_4 FMT, 4);
>          return(0);
> }
>
> int load_module(void) {
>          ast_verbose(VERBOSE_PREFIX_3 "Loaded Verbosity.\n");
>          return ast_register_application(app, verbosity_exec, synopsis, descrip);
> }
>
> int unload_module(void) {
>          return ast_unregister_application(app);
> }
>
> AST_MODULE_INFO_STANDARD(ASTERISK_GPL_KEY, "Verbosity");
> =========================================================================
>
Rather then hacking your own, check out:

*CLI> core show application Verbose

That's the current way to add verboseness to your dialplans.  Of course 
you can also check out the source code.

> Pretty basic, I know. Now here is the console output from Asterisk
> which is what is confusing me. I start by setting the verbosity level
> down to 1, and then dial 9 to get the verbosity module to run. Each
> time I increase the verbosity level by 1 and run it again to see what
> changes up through level 4:
>
> =========================================================================
> Connected to Asterisk 1.8.12.2 currently running on sandbox (pid = 21556)
> Verbosity is at least 3
> sandbox*CLI>
> sandbox*CLI>
> sandbox*CLI>
> sandbox*CLI> core set verbose 1
> Verbosity was 3 and is now 1
> sandbox*CLI>
> sandbox*CLI>
>   This is a test message at verbosity level [1]
>    == This is a test message at verbosity level [2]
>      -- This is a test message at verbosity level [3]
>         > This is a test message at verbosity level [4]
> sandbox*CLI> core set verbose 2
> Verbosity was 1 and is now 2
>    == Using SIP RTP CoS mark 5
>   This is a test message at verbosity level [1]
>    == This is a test message at verbosity level [2]
>      -- This is a test message at verbosity level [3]
>         > This is a test message at verbosity level [4]
>    == Spawn extension (inbound, 9, 3) exited non-zero on 'SIP/softphone-00000001'
> sandbox*CLI> core set verbose 3
> Verbosity was 2 and is now 3
>    == Using SIP RTP CoS mark 5
>      -- Executing [9 at inbound:1] Answer("SIP/softphone-00000002", "") in new stack
>      -- Executing [9 at inbound:2] Verbosity("SIP/softphone-00000002", "")
> in new stack
>   This is a test message at verbosity level [1]
>    == This is a test message at verbosity level [2]
>      -- This is a test message at verbosity level [3]
>         > This is a test message at verbosity level [4]
>      -- Executing [9 at inbound:3] Hangup("SIP/softphone-00000002", "") in new stack
>    == Spawn extension (inbound, 9, 3) exited non-zero on 'SIP/softphone-00000002'
> sandbox*CLI> core set verbose 4
> Verbosity was 3 and is now 4
>    == Using SIP RTP CoS mark 5
>      -- Executing [9 at inbound:1] Answer("SIP/softphone-00000003", "") in new stack
>      -- Executing [9 at inbound:2] Verbosity("SIP/softphone-00000003", "")
> in new stack
>   This is a test message at verbosity level [1]
>    == This is a test message at verbosity level [2]
>      -- This is a test message at verbosity level [3]
>         > This is a test message at verbosity level [4]
>      -- Executing [9 at inbound:3] Hangup("SIP/softphone-00000003", "") in new stack
>    == Spawn extension (inbound, 9, 3) exited non-zero on 'SIP/softphone-00000003'
> sandbox*CLI>
> =========================================================================
>
> My confusion is that every verbosity level echoes the same four
> messages. The only difference appears to come in at level 2 when
> asterisk's own internal messages start showing up.
>
> The source code man page for logger.h
> (http://www.asterisk.org/doxygen/asterisk1.8/logger_8h.html) says of
> ast_verbose:
> =========================================================================
> void 	__ast_verbose (const char *file, int line, const char *func,
> const char *fmt,...)
> This works like ast_log, but prints verbose messages to the console
> depending on verbosity level set. ast_verbose(VERBOSE_PREFIX_3
> "Whatever %s is happening\n", "nothing"); This will print the message
> to the console if the verbose level is set to a level >= 3 Note the
> abscence of a comma after the VERBOSE_PREFIX_3. This is important.
> VERBOSE_PREFIX_1 through VERBOSE_PREFIX_3 are defined.
> =========================================================================
>
> Viewing logger.h I actually found VERBOSE_PREFIX_4 to be defined as
> well though it was not documented. I have been using VERBOSE_PREFIX_4
> to log debug messages. With 3 as the default, debug messages should be
> hidden until the user explicitly increases the verbosity level. From
> the ast_verbose() function description I would expect this to work,
> but it's not.
>
> Is this a bug in the logger's behavior, or am I missing something?
>
IIRC you want to be using ast_verb() vs ast_verbose().  A good example 
would be to compare app_verbose.c in 1.8 and trunk for the differences.

I think your issue is, you need to add a check for option_verbose:

if (option_verbose > 1) {
      ast_verbose(VERBOSE_PREFIX_2 "verbose greater then 1");
}

-- 
Paul Belanger | PolyBeacon, Inc.
Jabber: paul.belanger at polybeacon.com | IRC: pabelanger (Freenode)
Github: https://github.com/pabelanger | Twitter: 
https://twitter.com/pabelanger