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

[Sean Kelly]

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");
=========================================================================

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?

Thanks,
- Sean M. Kelly