kenmirrors/asterisk
1
0
Fork 0
mirror of https://github.com/asterisk/asterisk.git synced 2025-09-02 19:16:15 +00:00
Code Issues Packages Projects Releases Wiki Activity

Scope Tracing: A new facility for tracing scope enter/exit

Browse Source 
What's wrong with ast_debug?

  ast_debug is fine for general purpose debug output but it's not
  really geared for scope tracing since it doesn't present its
  output in a way that makes capturing and analyzing flow through
  Asterisk easy.

How is scope tracing better?

  Scope tracing uses the same "cleanup" attribute that RAII_VAR
  uses to print messages to a separate "trace" log level.  Even
  better, the messages are indented and unindented based on a
  thread-local call depth counter.  When output to a separate log
  file, the output is uncluttered and easy to follow.

  Here's an example of the output. The leading timestamps and
  thread ids are removed and the output cut off at 68 columns for
  commit message restrictions but you get the idea.

--> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001
	--> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173
		--> res_pjsip_session.c:3669 handle_incoming_response PJSIP/
			--> chan_pjsip.c:3265 chan_pjsip_incoming_response_after
				--> chan_pjsip.c:3194 chan_pjsip_incoming_response P
					    chan_pjsip.c:3245 chan_pjsip_incoming_respon
				<-- chan_pjsip.c:3194 chan_pjsip_incoming_response P
			<-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after
		<-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/
	<-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173
<-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001

  The messages with the "-->" or "<--" were produced by including
  the following at the top of each function:

  SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session));

  Scope isn't limited to functions any more than RAII_VAR is.  You
  can also see entry and exit from "if", "for", "while", etc blocks.

  There is also an ast_trace() macro that doesn't track entry or
  exit but simply outputs a message to the trace log using the
  current indent level.  The deepest message in the sample
  (chan_pjsip.c:3245) was used to indicate which "case" in a
  "select" was executed.

How do you use it?

  More documentation is available in logger.h but here's an overview:

  * Configure with --enable-dev-mode.  Like debug, scope tracing
    is #ifdef'd out if devmode isn't enabled.

  * Add a SCOPE_TRACE() call to the top of your function.

  * Set a logger channel in logger.conf to output the "trace" level.

  * Use the CLI (or cli.conf) to set a trace level similar to setting
    debug level... CLI> core set trace 2 res_pjsip.so

Summary Of Changes:

  * Added LOG_TRACE logger level.  Actually it occupies the slot
    formerly occupied by the now defunct "event" level.

  * Added core asterisk option "trace" similar to debug.  Includes
	ability to specify global trace level in asterisk.conf and CLI
	commands to turn on/off and set levels.  Levels can be set
	globally (probably not a good idea), or by module/source file.

  * Updated sample asterisk.conf and logger.conf.  Tracing is
    disabled by default in both.

  * Added __ast_trace() to logger.c which keeps track of the indent
    level using TLS. It's #ifdef'd out if devmode isn't enabled.

  * Added ast_trace() and SCOPE_TRACE() macros to logger.h.
    These are all #ifdef'd out if devmode isn't enabled.

Why not use gcc's -finstrument-functions capability?

  gcc's facility doesn't allow access to local data and doesn't
  operate on non-function scopes.

Known Issues:

  The only know issue is that we currently don't know the line
  number where the scope exited.  It's reported as the same place
  the scope was entered.  There's probably a way to get around it
  but it might involve looking at the stack and doing an 'addr2line'
  to get the line number.  Kind of like ast_backtrace() does.
  Not sure if it's worth it.

Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
This commit is contained in:
George Joseph
2020-05-14 12:24:19 -06:00
committed by Friendly Automation
parent c16937cdbe
commit ca3c22c5f1
10 changed files with 605 additions and 100 deletions
Download Patch File Download Diff File Expand all files Collapse all files

299
main/cli.c
View File

@@ -102,8 +102,9 @@ struct module_level {
AST_RWLIST_HEAD(module_level_list, module_level);
/*! list of module names and their debug levels */
/*! lists of module names and their debug/trace levels */
static struct module_level_list debug_modules = AST_RWLIST_HEAD_INIT_VALUE;
static struct module_level_list trace_modules = AST_RWLIST_HEAD_INIT_VALUE;
AST_THREADSTORAGE(ast_cli_buf);
@@ -148,6 +149,23 @@ unsigned int ast_debug_get_by_module(const char *module)
return res;
}
unsigned int ast_trace_get_by_module(const char *module)
{
struct module_level *ml;
unsigned int res = 0;
AST_RWLIST_RDLOCK(&trace_modules);
AST_LIST_TRAVERSE(&trace_modules, ml, entry) {
if (!strcasecmp(ml->module, module)) {
res = ml->level;
break;
}
}
AST_RWLIST_UNLOCK(&trace_modules);
return res;
}
/*! \internal
* \brief Check if the user with 'uid' and 'gid' is allow to execute 'command',
* if command starts with '_' then not check permissions, just permit
@@ -381,10 +399,27 @@ static char *complete_number(const char *partial, unsigned int min, unsigned int
return NULL;
}
static void status_debug_verbose(struct ast_cli_args *a, const char *what, int old_val, int cur_val)
#define DEBUG_HANDLER 0
#define TRACE_HANDLER 1
#define VERBOSE_HANDLER 2
static void status_debug_verbose(struct ast_cli_args *a, int handler, int old_val, int cur_val)
{
char was_buf[30];
const char *was;
const char *what;
switch(handler) {
case DEBUG_HANDLER:
what = "Core debug";
break;
case TRACE_HANDLER:
what = "Core trace";
break;
case VERBOSE_HANDLER:
what = "Console verbose";
break;
}
if (old_val) {
snprintf(was_buf, sizeof(was_buf), "%d", old_val);
@@ -410,13 +445,131 @@ static void status_debug_verbose(struct ast_cli_args *a, const char *what, int o
}
}
static char *handle_debug(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
static char *handle_debug_or_trace(int handler, struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
int oldval;
int newlevel;
int atleast = 0;
const char *argv3 = a->argv ? S_OR(a->argv[3], "") : "";
struct module_level *ml;
struct module_level_list *modules;
unsigned int module_option;
int *core_option;
const char *handler_name;
if (a->argc <= e->args) {
return CLI_SHOWUSAGE;
}
if (handler == DEBUG_HANDLER) {
modules = &debug_modules;
module_option = AST_OPT_FLAG_DEBUG_MODULE;
core_option = &option_debug;
handler_name = "debug";
} else {
modules = &trace_modules;
module_option = AST_OPT_FLAG_TRACE_MODULE;
core_option = &option_trace;
handler_name = "trace";
}
if (a->argc == e->args + 1 && !strcasecmp(a->argv[e->args], "off")) {
newlevel = 0;
} else {
if (!strcasecmp(a->argv[e->args], "atleast")) {
atleast = 1;
}
if (a->argc != e->args + atleast + 1 && a->argc != e->args + atleast + 2) {
return CLI_SHOWUSAGE;
}
if (sscanf(a->argv[e->args + atleast], "%30d", &newlevel) != 1) {
return CLI_SHOWUSAGE;
}
if (a->argc == e->args + atleast + 2) {
/* We have specified a module name. */
char *mod = ast_strdupa(a->argv[e->args + atleast + 1]);
int mod_len = strlen(mod);
if (3 < mod_len && !strcasecmp(mod + mod_len - 3, ".so")) {
mod[mod_len - 3] = '\0';
}
AST_RWLIST_WRLOCK(modules);
ml = find_module_level(mod, modules);
if (!newlevel) {
if (!ml) {
/* Specified off for a nonexistent entry. */
AST_RWLIST_UNLOCK(modules);
ast_cli(a->fd, "Core %s is still 0 for '%s'.\n", handler_name, mod);
return CLI_SUCCESS;
}
AST_RWLIST_REMOVE(modules, ml, entry);
if (AST_RWLIST_EMPTY(modules)) {
ast_clear_flag(&ast_options, module_option);
}
AST_RWLIST_UNLOCK(modules);
ast_cli(a->fd, "Core %s was %u and has been set to 0 for '%s'.\n", handler_name,
ml->level, mod);
ast_free(ml);
return CLI_SUCCESS;
}
if (ml) {
if ((atleast && newlevel < ml->level) || ml->level == newlevel) {
ast_cli(a->fd, "Core %s is still %u for '%s'.\n", handler_name, ml->level, mod);
AST_RWLIST_UNLOCK(modules);
return CLI_SUCCESS;
}
oldval = ml->level;
ml->level = newlevel;
} else {
ml = ast_calloc(1, sizeof(*ml) + strlen(mod) + 1);
if (!ml) {
AST_RWLIST_UNLOCK(modules);
return CLI_FAILURE;
}
oldval = ml->level;
ml->level = newlevel;
strcpy(ml->module, mod);
AST_RWLIST_INSERT_TAIL(modules, ml, entry);
}
ast_set_flag(&ast_options, module_option);
ast_cli(a->fd, "Core %s was %d and has been set to %u for '%s'.\n", handler_name,
oldval, ml->level, ml->module);
AST_RWLIST_UNLOCK(modules);
return CLI_SUCCESS;
}
}
/* Update global debug level */
if (!newlevel) {
/* Specified level was 0 or off. */
AST_RWLIST_WRLOCK(modules);
while ((ml = AST_RWLIST_REMOVE_HEAD(modules, entry))) {
ast_free(ml);
}
ast_clear_flag(&ast_options, AST_OPT_FLAG_DEBUG_MODULE);
AST_RWLIST_UNLOCK(modules);
}
oldval = *core_option;
if (!atleast || newlevel > *core_option) {
*core_option = newlevel;
}
/* Report debug level status */
status_debug_verbose(a, handler, oldval, *core_option);
return CLI_SUCCESS;
}
static char *handle_debug(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
int atleast = 0;
const char *argv3 = a->argv ? S_OR(a->argv[3], "") : "";
switch (cmd) {
case CLI_INIT:
@@ -464,102 +617,61 @@ static char *handle_debug(struct ast_cli_entry *e, int cmd, struct ast_cli_args
* we are guaranteed to be called with argc >= e->args;
*/
if (a->argc <= e->args) {
return CLI_SHOWUSAGE;
}
return handle_debug_or_trace(DEBUG_HANDLER, e, cmd, a);
if (a->argc == e->args + 1 && !strcasecmp(a->argv[e->args], "off")) {
newlevel = 0;
} else {
if (!strcasecmp(a->argv[e->args], "atleast")) {
}
static char *handle_trace(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
int atleast = 0;
const char *argv3 = a->argv ? S_OR(a->argv[3], "") : "";
switch (cmd) {
case CLI_INIT:
e->command = "core set trace";
e->usage =
"Usage: core set trace [atleast] <level> [module]\n"
" core set trace off\n"
"\n"
" Sets level of trace messages to be displayed or\n"
" sets a module name to display trace messages from.\n"
" 0 or off means no messages should be displayed.\n";
return NULL;
case CLI_GENERATE:
if (!strcasecmp(argv3, "atleast")) {
atleast = 1;
}
if (a->argc != e->args + atleast + 1 && a->argc != e->args + atleast + 2) {
return CLI_SHOWUSAGE;
}
if (sscanf(a->argv[e->args + atleast], "%30d", &newlevel) != 1) {
return CLI_SHOWUSAGE;
}
if (a->pos == 3 || (a->pos == 4 && atleast)) {
const char *pos = a->pos == 3 ? argv3 : S_OR(a->argv[4], "");
int numbermatch = (ast_strlen_zero(pos) || strchr("123456789", pos[0])) ? 0 : 21;
if (a->argc == e->args + atleast + 2) {
/* We have specified a module name. */
char *mod = ast_strdupa(a->argv[e->args + atleast + 1]);
int mod_len = strlen(mod);
if (3 < mod_len && !strcasecmp(mod + mod_len - 3, ".so")) {
mod[mod_len - 3] = '\0';
if (a->n < 21 && numbermatch == 0) {
return complete_number(pos, 0, 0x7fffffff, a->n);
} else if (pos[0] == '0') {
if (a->n == 0) {
return ast_strdup("0");
}
} else if (a->n == (21 - numbermatch)) {
if (a->pos == 3 && !strncasecmp(argv3, "off", strlen(argv3))) {
return ast_strdup("off");
} else if (a->pos == 3 && !strncasecmp(argv3, "atleast", strlen(argv3))) {
return ast_strdup("atleast");
}
} else if (a->n == (22 - numbermatch) && a->pos == 3 && ast_strlen_zero(argv3)) {
return ast_strdup("atleast");
}
AST_RWLIST_WRLOCK(&debug_modules);
ml = find_module_level(mod, &debug_modules);
if (!newlevel) {
if (!ml) {
/* Specified off for a nonexistent entry. */
AST_RWLIST_UNLOCK(&debug_modules);
ast_cli(a->fd, "Core debug is still 0 for '%s'.\n", mod);
return CLI_SUCCESS;
}
AST_RWLIST_REMOVE(&debug_modules, ml, entry);
if (AST_RWLIST_EMPTY(&debug_modules)) {
ast_clear_flag(&ast_options, AST_OPT_FLAG_DEBUG_MODULE);
}
AST_RWLIST_UNLOCK(&debug_modules);
ast_cli(a->fd, "Core debug was %u and has been set to 0 for '%s'.\n",
ml->level, mod);
ast_free(ml);
return CLI_SUCCESS;
}
if (ml) {
if ((atleast && newlevel < ml->level) || ml->level == newlevel) {
ast_cli(a->fd, "Core debug is still %u for '%s'.\n", ml->level, mod);
AST_RWLIST_UNLOCK(&debug_modules);
return CLI_SUCCESS;
}
oldval = ml->level;
ml->level = newlevel;
} else {
ml = ast_calloc(1, sizeof(*ml) + strlen(mod) + 1);
if (!ml) {
AST_RWLIST_UNLOCK(&debug_modules);
return CLI_FAILURE;
}
oldval = ml->level;
ml->level = newlevel;
strcpy(ml->module, mod);
AST_RWLIST_INSERT_TAIL(&debug_modules, ml, entry);
}
ast_set_flag(&ast_options, AST_OPT_FLAG_DEBUG_MODULE);
ast_cli(a->fd, "Core debug was %d and has been set to %u for '%s'.\n",
oldval, ml->level, ml->module);
AST_RWLIST_UNLOCK(&debug_modules);
return CLI_SUCCESS;
} else if ((a->pos == 4 && !atleast && strcasecmp(argv3, "off") && strcasecmp(argv3, "channel"))
|| (a->pos == 5 && atleast)) {
return ast_module_helper(a->line, a->word, a->pos, a->n, a->pos, AST_MODULE_HELPER_RUNNING);
}
return NULL;
}
/* all the above return, so we proceed with the handler.
* we are guaranteed to be called with argc >= e->args;
*/
/* Update global debug level */
if (!newlevel) {
/* Specified level was 0 or off. */
AST_RWLIST_WRLOCK(&debug_modules);
while ((ml = AST_RWLIST_REMOVE_HEAD(&debug_modules, entry))) {
ast_free(ml);
}
ast_clear_flag(&ast_options, AST_OPT_FLAG_DEBUG_MODULE);
AST_RWLIST_UNLOCK(&debug_modules);
}
oldval = option_debug;
if (!atleast || newlevel > option_debug) {
option_debug = newlevel;
}
/* Report debug level status */
status_debug_verbose(a, "Core debug", oldval, option_debug);
return CLI_SUCCESS;
return handle_debug_or_trace(TRACE_HANDLER, e, cmd, a);
}
static char *handle_verbose(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
@@ -657,7 +769,7 @@ static char *handle_verbose(struct ast_cli_entry *e, int cmd, struct ast_cli_arg
}
/* Report verbose level status */
status_debug_verbose(a, "Console verbose", oldval, newlevel);
status_debug_verbose(a, VERBOSE_HANDLER, oldval, newlevel);
return CLI_SUCCESS;
}
@@ -1836,6 +1948,7 @@ static struct ast_cli_entry cli_cli[] = {
AST_CLI_DEFINE(handle_core_set_debug_channel, "Enable/disable debugging on a channel"),
AST_CLI_DEFINE(handle_debug, "Set level of debug chattiness"),
AST_CLI_DEFINE(handle_trace, "Set level of trace chattiness"),
AST_CLI_DEFINE(handle_verbose, "Set level of verbose chattiness"),
AST_CLI_DEFINE(group_show_channels, "Display active channels with group(s)"),