diff --git a/configs/samples/asterisk.conf.sample b/configs/samples/asterisk.conf.sample index bf0bdba092..3c1a4036a7 100644 --- a/configs/samples/asterisk.conf.sample +++ b/configs/samples/asterisk.conf.sample @@ -14,6 +14,7 @@ astsbindir => /usr/sbin [options] ;verbose = 3 ;debug = 3 +;trace = 0 ; Set the trace level. ;refdebug = yes ; Enable reference count debug logging. ;alwaysfork = yes ; Same as -F at startup. ;nofork = yes ; Same as -f at startup. diff --git a/configs/samples/logger.conf.sample b/configs/samples/logger.conf.sample index e5f0c551a7..9c7dcca401 100644 --- a/configs/samples/logger.conf.sample +++ b/configs/samples/logger.conf.sample @@ -118,6 +118,7 @@ ; Log levels include the following, and are specified in a comma delineated ; list: ; debug +; trace ; notice ; warning ; error @@ -146,12 +147,14 @@ ; the underlying code. Do NOT report debug messages as code issues, unless ; you have a specific issue that you are attempting to debug. They are ; messages for just that -- debugging -- and do not rise to the level of -; something that merit your attention as an Asterisk administrator. Debug -; messages are also very verbose and can and do fill up logfiles quickly; -; this is another reason not to have debug mode on a production system unless -; you are in the process of debugging a specific issue. +; something that merit your attention as an Asterisk administrator. Both +; debug and trace messages are also very verbose and can and do fill up +; logfiles quickly. This is another reason not to have debug or trace +; modes on a production system unless you are in the process of debugging +; a specific issue. ; ;debug => debug +;trace => trace ;security => security console => notice,warning,error ;console => notice,warning,error,debug diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h index 1d0c6bdbe0..4392e5adf9 100644 --- a/include/asterisk/logger.h +++ b/include/asterisk/logger.h @@ -245,6 +245,17 @@ void ast_console_toggle_loglevel(int fd, int level, int state); #endif #define AST_LOG_DEBUG __LOG_DEBUG, _A_ +#ifdef LOG_TRACE +#undef LOG_TRACE +#endif +#define __LOG_TRACE 1 +#define LOG_TRACE __LOG_TRACE, _A_ + +#ifdef AST_LOG_TRACE +#undef AST_LOG_TRACE +#endif +#define AST_LOG_TRACE __LOG_TRACE, _A_ + #ifdef LOG_NOTICE #undef LOG_NOTICE #endif @@ -517,6 +528,199 @@ void ast_logger_set_queue_limit(int queue_limit); */ int ast_logger_get_queue_limit(void); + +/*! + \page Scope_Trace Scope Trace + +The Scope Trace facility allows you to instrument code and output scope entry +and exit messages with associated data. + +To start using it: + * You must have used --enable-dev-mode. + * In logger.conf, set a logger channel to output the "trace" level. + * Instrument your code as specified below. + * Use the cli or cli.conf to enable tracing: CLI> core set trace [ module ] + +Its simplest usage requires only 1 macro call that... + - Registers a descructor for a special variable that gets called when the + variable goes out of scope. Uses the same principle as RAII_VAR. + The destructor prints the name of the function with an "exiting" indicator + along with an optional message. + - Prints the name of the function with an "entering" indicator along with + an optional message. + +Simple Example: +The following code... +\code +static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, + struct ast_sip_session *session, const pjmedia_sdp_session *offer) +{ + SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); + ... +} +\endcode +would produce... +\b [2020-05-17 15:16:51 -0600] TRACE[953402] : --> res_pjsip_session.c:4283 create_local_sdp PJSIP/1173-00000001 +\b [2020-05-17 15:16:51 -0600] TRACE[953402] : <-- res_pjsip_session.c:4283 create_local_sdp PJSIP/1173-00000001 + +There is one odd bit. There's no way to capture the line number of there the scope exited +so it's always going to be the line where SCOPE_TRACE is located. + +Similar to RAII_VAR, any block scope can be traced including "if", "for", "while", etc. +\note "case" statements don't create a scope block by themselves but you can create +a block for it, or use the generic trace functions mentioned below. + +Scope Output and Level: + +Rather than sending trace messages to the debug facility, a new facility "trace" has been +added to logger. A corresponding CLI command "core set trace", and a corresponding "trace" +parameter in asterisk.conf were added. This allows a separate log channel to be created +just for storing trace messages. The levels are the same as those for debug and verbose. + +Scope Indenting: + +Each time SCOPE_TRACE or SCOPE_TRACE is called, a thread-local indent value is +incremented on scope enter, and decremented on scope exit. This allows output +like the following (timestamp omitted for brevity): + +TRACE[953402] : --> res_pjsip_session.c:3940 session_inv_on_tsx_state_changed PJSIP/1173-00000001 TSX State: Proceeding Inv State: CALLING +TRACE[953402] : --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 +TRACE[953402] : --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 +TRACE[953402] : --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 Supplement: chan_pjsip +TRACE[953402] : --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after_media PJSIP/1173-00000001 Method: INVITE Status: 100 After Media +TRACE[953402] : --> chan_pjsip.c:3194 chan_pjsip_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 +TRACE[953402] : chan_pjsip.c:3245 chan_pjsip_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 Ignored +TRACE[953402] : <-- chan_pjsip.c:3194 chan_pjsip_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 +TRACE[953402] : <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after_media PJSIP/1173-00000001 Method: INVITE Status: 100 After Media +TRACE[953402] : <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 Supplement: chan_pjsip +TRACE[953402] : <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173-00000001 Method: INVITE Status: 100 +TRACE[953402] : <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 +TRACE[953402] : <-- res_pjsip_session.c:3940 session_inv_on_tsx_state_changed PJSIP/1173-00000001 TSX State: Proceeding Inv State: CALLING + +\note The trace level indicates which messages to print and has no effect on indent. + +Generic Trace Messages: + +Sometimes you may just want to print a message to the trace log with the appropriate indent +such as when executing a "case" clause in a "switch" statement. For example, the deepest +message in the sample output above (chan_pjsip.c:3245) is just a single message instead of +an entry/exit message. To do so, you can use the ast_trace macros... +\code + ast_trace(1, "%s Method: %.*s Status: %d Ignored\n", ast_sip_session_get_name(session), + (int)rdata->msg_info.cseq->method.name.slen, rdata->msg_info.cseq->method.name.ptr, status.code); +\endcode + +/note Final note: The trace facility, like debug, is only available when AST_DEVMODE is defined. + + */ + +/*! + * \brief Get the trace level for a module + * \param module the name of module + * \return the trace level + */ +unsigned int ast_trace_get_by_module(const char *module); + +#define TRACE_ATLEAST(level) \ + (option_trace >= (level) \ + || (ast_opt_trace_module \ + && ((int)ast_trace_get_by_module(AST_MODULE) >= (level) \ + || (int)ast_trace_get_by_module(__FILE__) >= (level)))) + +/*! + * \brief Controls if and when indenting is applied. + */ +enum ast_trace_indent_type { + /*! Use the existing indent level */ + AST_TRACE_INDENT_SAME = 0, + /*! Increment the indent before printing the message */ + AST_TRACE_INDENT_INC_BEFORE, + /*! Increment the indent after printing the message */ + AST_TRACE_INDENT_INC_AFTER, + /*! Decrement the indent before printing the message */ + AST_TRACE_INDENT_DEC_BEFORE, + /*! Decrement the indent after printing the message */ + AST_TRACE_INDENT_DEC_AFTER, + /*! Don't use or alter the level */ + AST_TRACE_INDENT_NONE, +}; + +#ifdef AST_DEVMODE + +void __attribute__((format (printf, 5, 6))) __ast_trace(const char *file, int line, const char *func, + enum ast_trace_indent_type indent_type, const char* format, ...); + +/*! + * \brief Print a trace message + * + * \param level The trace level + * \param indent_type One of the \ref ast_trace_indent_type values + * \param (optional) A printf style format string + * \param (optional) Arguments + * + */ +#define ast_trace_raw(level, indent_type, ...) \ + if (TRACE_ATLEAST(level)) { \ + __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, indent_type, " " __VA_ARGS__); \ + } + +/*! + * \brief Print a basic trace message + * + * \param level The trace level + * \param (optional) A printf style format string + * \param (optional) Arguments + * + * This will print the file, line and function at the current indent level + */ +#define ast_trace(level, ...) \ + if (TRACE_ATLEAST(level)) { \ + __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_SAME, " " __VA_ARGS__); \ + } + +/*! + * \brief Print a trace message with details when a scope is entered or existed. + * + * \param level The trace level + * \param (optional) A printf style format string + * \param (optional) Arguments + * + * This will print the file, line and function plus details at the current indent level. + * \note Like RAII_VAR, this macro must be called before any code in the scope. + * + * \note The variables used to detect scope change will look like + * __scopevar1234__EXIT and __scopevar1234__ENTER. + * The ENTER variable and function are needed to prevent mixed code and declaration issues. + * If we simple called __ast_trace, then this macro would need to be the last line + * of scope variable declaration. The following would fail. + * + * SCOPE_TRACE(1, "Help!\n"); + * int i; + */ +#define SCOPE_TRACE(level, ...) \ + const char *__trace_funcname = __PRETTY_FUNCTION__; \ + auto void __scopevar ## __LINE__ ## __EXIT(void * v); \ + void __scopevar ## __LINE__ ## __EXIT(void * v __attribute__((unused))) { \ + if (TRACE_ATLEAST(level)) { \ + __ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_DEC_BEFORE, " " __VA_ARGS__); \ + } \ + } \ + void *__scopevar ## __LINE__ ## __TRACER __attribute__((cleanup(__scopevar ## __LINE__ ## __EXIT))) = (void *) __PRETTY_FUNCTION__ ; \ + auto int __scopevar ## __LINE__ ## __ENTER(void); \ + int __scopevar ## __LINE__ ## __ENTER(void) { \ + if (TRACE_ATLEAST(level)) { \ + __ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_INC_AFTER, " " __VA_ARGS__); \ + } \ + return 0; \ + } \ + int __scopevar ## __LINE__ ## __RETURN __attribute__((unused)) = __scopevar ## __LINE__ ## __ENTER() + +#else +#define ast_trace_raw(__level, __indent_type, __fmt, ...) +#define ast_trace(__level) +#define SCOPE_TRACE(__level) +#endif + #if defined(__cplusplus) || defined(c_plusplus) } #endif diff --git a/include/asterisk/options.h b/include/asterisk/options.h index f8c813f19a..570100b724 100644 --- a/include/asterisk/options.h +++ b/include/asterisk/options.h @@ -82,6 +82,8 @@ enum ast_option_flags { AST_OPT_FLAG_MUTE = (1 << 22), /*! There is a per-module debug setting */ AST_OPT_FLAG_DEBUG_MODULE = (1 << 23), + /*! There is a per-module trace setting */ + AST_OPT_FLAG_TRACE_MODULE = (1 << 24), /*! Terminal colors should be adjusted for a light-colored background */ AST_OPT_FLAG_LIGHT_BACKGROUND = (1 << 25), /*! Make the global Message channel an internal channel to suppress AMI events */ @@ -124,6 +126,7 @@ enum ast_option_flags { #define ast_opt_always_fork ast_test_flag(&ast_options, AST_OPT_FLAG_ALWAYS_FORK) #define ast_opt_mute ast_test_flag(&ast_options, AST_OPT_FLAG_MUTE) #define ast_opt_dbg_module ast_test_flag(&ast_options, AST_OPT_FLAG_DEBUG_MODULE) +#define ast_opt_trace_module ast_test_flag(&ast_options, AST_OPT_FLAG_TRACE_MODULE) #define ast_opt_light_background ast_test_flag(&ast_options, AST_OPT_FLAG_LIGHT_BACKGROUND) #define ast_opt_force_black_background ast_test_flag(&ast_options, AST_OPT_FLAG_FORCE_BLACK_BACKGROUND) #define ast_opt_hide_connect ast_test_flag(&ast_options, AST_OPT_FLAG_HIDE_CONSOLE_CONNECT) @@ -184,6 +187,7 @@ extern struct ast_flags ast_options; extern int option_verbose; extern int ast_option_maxfiles; /*!< Max number of open file handles (files, sockets) */ extern int option_debug; /*!< Debugging */ +extern int option_trace; /*!< Debugging */ extern int ast_option_maxcalls; /*!< Maximum number of simultaneous channels */ extern unsigned int option_dtmfminduration; /*!< Minimum duration of DTMF (channel.c) in ms */ extern double ast_option_maxload; diff --git a/main/asterisk.c b/main/asterisk.c index 000e1a24ce..3e13d11f41 100644 --- a/main/asterisk.c +++ b/main/asterisk.c @@ -489,6 +489,7 @@ static char *handle_show_settings(struct ast_cli_entry *e, int cmd, struct ast_c ast_cli(a->fd, " Root console verbosity: %d\n", option_verbose); ast_cli(a->fd, " Current console verbosity: %d\n", ast_verb_console_get()); ast_cli(a->fd, " Debug level: %d\n", option_debug); + ast_cli(a->fd, " Trace level: %d\n", option_trace); ast_cli(a->fd, " Maximum load average: %lf\n", ast_option_maxload); #if defined(HAVE_SYSINFO) ast_cli(a->fd, " Minimum free memory: %ld MB\n", option_minmemfree); diff --git a/main/asterisk.exports.in b/main/asterisk.exports.in index 02328551ea..dfa72a69f2 100644 --- a/main/asterisk.exports.in +++ b/main/asterisk.exports.in @@ -12,6 +12,7 @@ LINKER_SYMBOL_PREFIXao2_*; LINKER_SYMBOL_PREFIX__ao2_*; LINKER_SYMBOL_PREFIXoption_debug; + LINKER_SYMBOL_PREFIXoption_trace; LINKER_SYMBOL_PREFIXoption_verbose; LINKER_SYMBOL_PREFIXcallerid_*; LINKER_SYMBOL_PREFIXcid_di; diff --git a/main/cli.c b/main/cli.c index ef73ba3892..b47b26c21f 100644 --- a/main/cli.c +++ b/main/cli.c @@ -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] [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)"), diff --git a/main/logger.c b/main/logger.c index 5a4b3feead..cf9357e4a1 100644 --- a/main/logger.c +++ b/main/logger.c @@ -202,7 +202,7 @@ static FILE *qlog; static char *levels[NUMLOGLEVELS] = { "DEBUG", - "---EVENT---", /* no longer used */ + "TRACE", "NOTICE", "WARNING", "ERROR", @@ -1216,9 +1216,9 @@ static char *handle_logger_set_level(struct ast_cli_entry *e, int cmd, struct as switch (cmd) { case CLI_INIT: - e->command = "logger set level {DEBUG|NOTICE|WARNING|ERROR|VERBOSE|DTMF} {on|off}"; + e->command = "logger set level {DEBUG|TRACE|NOTICE|WARNING|ERROR|VERBOSE|DTMF} {on|off}"; e->usage = - "Usage: logger set level {DEBUG|NOTICE|WARNING|ERROR|VERBOSE|DTMF} {on|off}\n" + "Usage: logger set level {DEBUG|TRACE|NOTICE|WARNING|ERROR|VERBOSE|DTMF} {on|off}\n" " Set a specific log level to enabled/disabled for this console.\n"; return NULL; case CLI_GENERATE: @@ -2281,6 +2281,68 @@ static void update_logchannels(void) AST_RWLIST_UNLOCK(&logchannels); } + +#ifdef AST_DEVMODE + +AST_THREADSTORAGE_RAW(trace_indent); +#define LOTS_O_SPACES " " + + +void __ast_trace(const char *file, int line, const char *func, enum ast_trace_indent_type indent_type, + const char* format, ...) +{ + va_list ap; + unsigned long indent = (unsigned long)ast_threadstorage_get_ptr(&trace_indent); + struct ast_str *fmt = ast_str_create(128); + char *direction; + + if (!fmt) { + return; + } + + if (indent_type == AST_TRACE_INDENT_INC_BEFORE) { + indent++; + ast_threadstorage_set_ptr(&trace_indent, (void*)indent); + } + if (indent_type == AST_TRACE_INDENT_DEC_BEFORE) { + indent--; + ast_threadstorage_set_ptr(&trace_indent, (void*)indent); + } + + switch(indent_type) { + case AST_TRACE_INDENT_NONE: + case AST_TRACE_INDENT_SAME: + direction = ""; + break; + case AST_TRACE_INDENT_INC_BEFORE: + case AST_TRACE_INDENT_INC_AFTER: + direction = "--> "; + break; + case AST_TRACE_INDENT_DEC_BEFORE: + case AST_TRACE_INDENT_DEC_AFTER: + direction = "<-- "; + break; + } + + ast_str_set(&fmt, 0, "%2d %-.*s%s%s:%d %s: %s", (int)indent, (indent_type == AST_TRACE_INDENT_NONE ? 0 : (int)(indent * 4)), + LOTS_O_SPACES, direction, file, line, func, S_OR(ast_skip_blanks(format), "\n")); + + if (indent_type == AST_TRACE_INDENT_INC_AFTER) { + indent++; + ast_threadstorage_set_ptr(&trace_indent, (void*)indent); + } + if (indent_type == AST_TRACE_INDENT_DEC_AFTER) { + indent--; + ast_threadstorage_set_ptr(&trace_indent, (void*)indent); + } + + va_start(ap, format); + ast_log_full(__LOG_TRACE, -1, NULL, 0, NULL, 0, ast_str_buffer(fmt), ap); + va_end(ap); + ast_free(fmt); +} +#endif + int ast_logger_register_level(const char *name) { unsigned int level; diff --git a/main/options.c b/main/options.c index 38a646e178..62f2c2da1c 100644 --- a/main/options.c +++ b/main/options.c @@ -67,6 +67,8 @@ int ast_verb_sys_level; int option_verbose; /*! Debug level */ int option_debug; +/*! Trace level */ +int option_trace; /*! Default to -1 to know if we have read the level from pjproject yet. */ int ast_pjproject_max_log_level = -1; int ast_option_pjproject_log_level; @@ -215,6 +217,7 @@ void load_asterisk_conf(void) /* Default to false for security */ int live_dangerously = 0; int option_debug_new = 0; + int option_trace_new = 0; int option_verbose_new = 0; /* init with buildtime config */ @@ -307,6 +310,11 @@ void load_asterisk_conf(void) if (sscanf(v->value, "%30d", &option_debug_new) != 1) { option_debug_new = ast_true(v->value) ? 1 : 0; } + } else if (!strcasecmp(v->name, "trace")) { + option_trace_new = 0; + if (sscanf(v->value, "%30d", &option_trace_new) != 1) { + option_trace_new = ast_true(v->value) ? 1 : 0; + } } else if (!strcasecmp(v->name, "refdebug")) { ast_set2_flag(&ast_options, ast_true(v->value), AST_OPT_FLAG_REF_DEBUG); #if HAVE_WORKING_FORK @@ -466,6 +474,7 @@ void load_asterisk_conf(void) } option_debug += option_debug_new; + option_trace += option_trace_new; option_verbose += option_verbose_new; ast_config_destroy(cfg); diff --git a/tests/test_scope_trace.c b/tests/test_scope_trace.c new file mode 100644 index 0000000000..6ab480aa4b --- /dev/null +++ b/tests/test_scope_trace.c @@ -0,0 +1,107 @@ +/* + * Asterisk -- An open source telephony toolkit. + * + * Copyright (C) 2020, Sangoma Technologies Corp + * + * George Joseph + * + * See http://www.asterisk.org for more information about + * the Asterisk project. Please do not directly contact + * any of the maintainers of this project for assistance; + * the project provides a web site, mailing lists and IRC + * channels for your use. + * + * This program is free software, distributed under the terms of + * the GNU General Public License Version 2. See the LICENSE file + * at the top of the source tree. + */ + +/*! + * \file + * \brief Test for Scope Trace + * + * \author\verbatim George Joseph \endverbatim + * + * tests for Scope Trace + * \ingroup tests + */ + +/*** MODULEINFO + TEST_FRAMEWORK + core + ***/ + +#include "asterisk.h" + +#include "asterisk/utils.h" +#include "asterisk/module.h" +#include "asterisk/test.h" +#include "asterisk/logger.h" + +static void test_scope2(void) +{ + SCOPE_TRACE(1); +} + +static void test_scope(void) +{ + SCOPE_TRACE(1, "nested function: %d * %d = %d\n", 6, 7, (6 * 7)); + + test_scope2(); + + ast_trace(1, "test no variables\n"); +} + + +AST_TEST_DEFINE(scope_test) +{ + SCOPE_TRACE(1, "top %s function\n", "scope_test"); + + ast_trace(1, "%s\n", "test outer"); + + switch (cmd) { + case TEST_INIT: + info->name = "scope_test"; + info->category = "/main/logging/"; + info->summary = "Scope Trace Tests"; + info->description = "Scope Trace Tests"; + return AST_TEST_NOT_RUN; + case TEST_EXECUTE: + { + SCOPE_TRACE(1, "CASE statement\n"); + ast_trace(1, "%s\n", "test case"); + } + break; + } + + if (1) { + SCOPE_TRACE(1, "IF block\n"); + + test_scope(); + } + + ast_trace(1); + + ast_trace(1, "test no variables\n"); + + + + + ast_trace(1, "%s\n", "test variable"); + + return AST_TEST_PASS; +} + +static int unload_module(void) +{ + AST_TEST_UNREGISTER(scope_test); + return 0; +} + +static int load_module(void) +{ + AST_TEST_REGISTER(scope_test); + return AST_MODULE_LOAD_SUCCESS; +} + +AST_MODULE_INFO_STANDARD(ASTERISK_GPL_KEY, "Scope Trace Test");