[Asterisk-code-review] Scope Tracing: A new facility for tracing scope enter/exit (asterisk[master])
George Joseph
asteriskteam at digium.com
Sun May 17 20:03:14 CDT 2020
George Joseph has uploaded this change for review. ( https://gerrit.asterisk.org/c/asterisk/+/14414 )
Change subject: Scope Tracing: A new facility for tracing scope enter/exit
......................................................................
Scope Tracing: A new facility for tracing scope enter/exit
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
Most of those messages were produced by including the following
at the top of each function:
SCOPE_TRACE_MSG(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() 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() or SCOPE_TRACE_MSG() 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(), ast_trace_msg(), SCOPE_TRACE(), and
SCOPE_TRACE_MSG() 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 accecss 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
---
M configs/samples/asterisk.conf.sample
M configs/samples/logger.conf.sample
M include/asterisk/logger.h
M include/asterisk/options.h
M main/asterisk.c
M main/asterisk.exports.in
M main/cli.c
M main/logger.c
M main/options.c
9 files changed, 479 insertions(+), 4 deletions(-)
git pull ssh://gerrit.asterisk.org:29418/asterisk refs/changes/14/14414/1
diff --git a/configs/samples/asterisk.conf.sample b/configs/samples/asterisk.conf.sample
index bf0bdba..3c1a403 100644
--- a/configs/samples/asterisk.conf.sample
+++ b/configs/samples/asterisk.conf.sample
@@ -14,6 +14,7 @@
[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 e5f0c55..d7dba3b 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
@@ -152,6 +153,7 @@
; 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 1d0c6bd..7cd1afe 100644
--- a/include/asterisk/logger.h
+++ b/include/asterisk/logger.h
@@ -245,6 +245,17 @@
#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,224 @@
*/
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 <trace_level> [ 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 namne of the function with an "existing" 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_MSG(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_MSG 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/exity message. To do so, you can use one of the ast_trace macros...
+\code
+ ast_trace_msg(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 __ast_trace(enum ast_trace_indent_type indent_type, const char* format, ...)
+ __attribute__((format (printf, 2, 3)));
+
+/*!
+ * \brief Print a trace message
+ *
+ * \param level The trace level
+ * \param indent_type One of the \ref ast_trace_indent_type values
+ * \param fmt A printf style format string
+ * \param ... Optional arguments
+ *
+ * The caller is responsible for specifying file, function, line, etc if needed.
+ */
+#define ast_trace_raw(level, indent_type, fmt, ...) \
+ if (TRACE_ATLEAST(level)) { \
+ __ast_trace(indent_type, fmt __VA_OPT__(,) __VA_ARGS__); \
+ }
+
+/*!
+ * \brief Print a basic trace message
+ *
+ * \param level The trace level
+ *
+ * This will print the file, line and function at the current indent level
+ */
+#define ast_trace(level) \
+ if (TRACE_ATLEAST(level)) { \
+ __ast_trace(AST_TRACE_INDENT_SAME, "%s:%d %s\n", __FILE__, __LINE__, __PRETTY_FUNCTION__); \
+ }
+
+/*!
+ * \brief Print a trace message with details
+ *
+ * \param level The trace level
+ * \param fmt A printf style format string
+ * \param ... Optional arguments
+ *
+ * This will print the file, line and function plus details at the current indent level
+ */
+#define ast_trace_msg(level, fmt, ...) \
+ if (TRACE_ATLEAST(level)) { \
+ __ast_trace(AST_TRACE_INDENT_SAME, "%s:%d %s " fmt, __FILE__, __LINE__, __PRETTY_FUNCTION__ __VA_OPT__(,) __VA_ARGS__); \
+ }
+
+/*!
+ * \brief Print a trace message with details when a scope is entered or existed.
+ *
+ * \param level The trace level
+ * \param fmt 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_MSG(level, fmt, ...) \
+ 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(AST_TRACE_INDENT_DEC_BEFORE, "%s:%d %s " fmt, __FILE__, __LINE__, __trace_funcname __VA_OPT__(,) __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(AST_TRACE_INDENT_INC_AFTER, "%s:%d %s " fmt, __FILE__, __LINE__, __trace_funcname __VA_OPT__(,) __VA_ARGS__); \
+ } \
+ return 0; \
+ } \
+ int __scopevar ## __LINE__ ## __RETURN __attribute__((unused)) = __scopevar ## __LINE__ ## __ENTER()
+
+/*!
+ * \brief Print a trace message when a scope is entered or exited.
+ *
+ * \param level The trace level
+ *
+ * This will print the file, line and function at the current indent level.
+ * \note Like RAII_VAR, this macro must be called before any code in the scope.
+ */
+#define SCOPE_TRACE(__level) SCOPE_TRACE_MSG(__level, "\n")
+
+#else
+#define ast_trace(__level)
+#define ast_trace_raw(__level, __indent_type, __fmt, ...)
+#define ast_trace_msg(__level, __indent_type, __fmt, ...)
+#define SCOPE_TRACE_MSG(__debug_level, __fmt, ...)
+#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 f8c813f..570100b 100644
--- a/include/asterisk/options.h
+++ b/include/asterisk/options.h
@@ -82,6 +82,8 @@
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 @@
#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 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 000e1a2..3e13d11 100644
--- a/main/asterisk.c
+++ b/main/asterisk.c
@@ -489,6 +489,7 @@
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 0232855..dfa72a6 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 ef73ba3..858d4ab 100644
--- a/main/cli.c
+++ b/main/cli.c
@@ -96,13 +96,14 @@
*/
struct module_level {
unsigned int level;
+ unsigned int trace_level;
AST_RWLIST_ENTRY(module_level) entry;
char module[0];
};
AST_RWLIST_HEAD(module_level_list, module_level);
-/*! list of module names and their debug levels */
+/*! list of module names and their debug/trace levels */
static struct module_level_list debug_modules = AST_RWLIST_HEAD_INIT_VALUE;
AST_THREADSTORAGE(ast_cli_buf);
@@ -148,6 +149,23 @@
return res;
}
+unsigned int ast_trace_get_by_module(const char *module)
+{
+ struct module_level *ml;
+ unsigned int res = 0;
+
+ AST_RWLIST_RDLOCK(&debug_modules);
+ AST_LIST_TRAVERSE(&debug_modules, ml, entry) {
+ if (!strcasecmp(ml->module, module)) {
+ res = ml->trace_level;
+ break;
+ }
+ }
+ AST_RWLIST_UNLOCK(&debug_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
@@ -562,6 +580,157 @@
return CLI_SUCCESS;
}
+static char *handle_trace(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;
+
+ 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->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->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");
+ }
+ } 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;
+ */
+
+ if (a->argc <= e->args) {
+ return CLI_SHOWUSAGE;
+ }
+
+ 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(&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 trace 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_TRACE_MODULE);
+ }
+ AST_RWLIST_UNLOCK(&debug_modules);
+ ast_cli(a->fd, "Core trace was %u and has been set to 0 for '%s'.\n",
+ ml->trace_level, mod);
+ ast_free(ml);
+ return CLI_SUCCESS;
+ }
+
+ if (ml) {
+ if ((atleast && newlevel < ml->trace_level) || ml->trace_level == newlevel) {
+ ast_cli(a->fd, "Core trace is still %u for '%s'.\n", ml->trace_level, mod);
+ AST_RWLIST_UNLOCK(&debug_modules);
+ return CLI_SUCCESS;
+ }
+ oldval = ml->trace_level;
+ ml->trace_level = newlevel;
+ } else {
+ ml = ast_calloc(1, sizeof(*ml) + strlen(mod) + 1);
+ if (!ml) {
+ AST_RWLIST_UNLOCK(&debug_modules);
+ return CLI_FAILURE;
+ }
+ oldval = ml->trace_level;
+ ml->trace_level = newlevel;
+ strcpy(ml->module, mod);
+ AST_RWLIST_INSERT_TAIL(&debug_modules, ml, entry);
+ }
+ ast_set_flag(&ast_options, AST_OPT_FLAG_TRACE_MODULE);
+
+ ast_cli(a->fd, "Core trace was %d and has been set to %u for '%s'.\n",
+ oldval, ml->trace_level, ml->module);
+
+ AST_RWLIST_UNLOCK(&debug_modules);
+
+ return CLI_SUCCESS;
+ }
+ }
+
+ /* 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_TRACE_MODULE);
+ AST_RWLIST_UNLOCK(&debug_modules);
+ }
+ oldval = option_trace;
+ if (!atleast || newlevel > option_trace) {
+ option_trace = newlevel;
+ }
+
+ /* Report debug level status */
+ status_debug_verbose(a, "Core trace", oldval, option_trace);
+
+ return CLI_SUCCESS;
+}
+
static char *handle_verbose(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
int oldval;
@@ -1836,6 +2005,7 @@
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 5a4b3fe..1ed7349 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -202,7 +202,7 @@
static char *levels[NUMLOGLEVELS] = {
"DEBUG",
- "---EVENT---", /* no longer used */
+ "TRACE",
"NOTICE",
"WARNING",
"ERROR",
@@ -1216,9 +1216,9 @@
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,64 @@
AST_RWLIST_UNLOCK(&logchannels);
}
+
+#ifdef AST_DEVMODE
+
+AST_THREADSTORAGE_RAW(trace_indent);
+#define LOTS_O_TABS "\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t\t"
+
+void __ast_trace(enum ast_trace_indent_type indent_type, const char* format, ...)
+{
+ va_list ap;
+ unsigned long indent = (unsigned long)ast_threadstorage_get_ptr(&trace_indent);
+ char *fmt;
+ char *dir;
+
+ 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);
+ }
+
+ fmt = ast_alloca(indent + 4 + strlen(format) + 1);
+
+ switch(indent_type) {
+ case AST_TRACE_INDENT_SAME:
+ dir = " ";
+ break;
+ case AST_TRACE_INDENT_INC_BEFORE:
+ case AST_TRACE_INDENT_INC_AFTER:
+ dir = "-->";
+ break;
+ case AST_TRACE_INDENT_DEC_BEFORE:
+ case AST_TRACE_INDENT_DEC_AFTER:
+ dir = "<--";
+ break;
+ case AST_TRACE_INDENT_NONE:
+ dir = "";
+ break;
+ }
+
+ sprintf(fmt, "%-.*s%s %s", indent_type == AST_TRACE_INDENT_NONE ? 0 : (int)indent, LOTS_O_TABS, dir, format);
+
+ 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, fmt, ap);
+ va_end(ap);
+}
+#endif
+
int ast_logger_register_level(const char *name)
{
unsigned int level;
diff --git a/main/options.c b/main/options.c
index 38a646e..62f2c2d 100644
--- a/main/options.c
+++ b/main/options.c
@@ -67,6 +67,8 @@
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 @@
/* 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 @@
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 @@
}
option_debug += option_debug_new;
+ option_trace += option_trace_new;
option_verbose += option_verbose_new;
ast_config_destroy(cfg);
--
To view, visit https://gerrit.asterisk.org/c/asterisk/+/14414
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings
Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
Gerrit-Change-Number: 14414
Gerrit-PatchSet: 1
Gerrit-Owner: George Joseph <gjoseph at digium.com>
Gerrit-MessageType: newchange
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20200517/1b149200/attachment-0001.html>
More information about the asterisk-code-review
mailing list