Asterisk - The Open Source Telephony Project  21.4.1
Macros | Enumerations | Functions
Scope Trace

Macros

#define _TRACE_PREFIX_   _TRACE_PREFIX_DEFAULT_
 
#define _TRACE_PREFIX_DEFAULT_   _A_
 
#define ast_trace(level, ...)   ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__)
 
#define ast_trace_dec_indent()
 
#define ast_trace_get_indent()   (0)
 
#define ast_trace_inc_indent()
 
#define ast_trace_log(__level, __log_level, ...)
 
#define ast_trace_raw(level, indent_type, ...)   ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__)
 
#define ast_trace_set_indent(indent)
 
#define SCOPE_CALL(level, __funcname, ...)   __funcname(__VA_ARGS__)
 
#define SCOPE_CALL_WITH_INT_RESULT(level, __funcname, ...)   __funcname(__VA_ARGS__)
 
#define SCOPE_CALL_WITH_RESULT(level, __var, __funcname, ...)   __var = __funcname(__VA_ARGS__)
 
#define SCOPE_ENTER(level, ...)
 
#define SCOPE_ENTER_TASK(level, indent, ...)
 
#define SCOPE_EXIT(...)   ast_debug(__scope_level, " " __VA_ARGS__)
 
#define SCOPE_EXIT_EXPR(__expr, ...)
 
#define SCOPE_EXIT_LOG(__log_level, ...)
 
#define SCOPE_EXIT_LOG_EXPR(__expr, __log_level, ...)
 
#define SCOPE_EXIT_LOG_RTN(__log_level, ...)
 
#define SCOPE_EXIT_LOG_RTN_VALUE(__value, __log_level, ...)
 
#define SCOPE_EXIT_RTN(...)
 
#define SCOPE_EXIT_RTN_VALUE(__return_value, ...)
 
#define SCOPE_TRACE(__level, ...)
 
#define TRACE_ATLEAST(level)
 

Enumerations

enum  ast_trace_indent_type {
  AST_TRACE_INDENT_SAME = 0, AST_TRACE_INDENT_INC_BEFORE, AST_TRACE_INDENT_INC_AFTER, AST_TRACE_INDENT_DEC_BEFORE,
  AST_TRACE_INDENT_DEC_AFTER, AST_TRACE_INDENT_PROVIDED, AST_TRACE_INDENT_NONE
}
 Controls if and when indenting is applied. More...
 

Functions

void ast_init_logger_for_socket_console (void)
 load logger.conf configuration for console socket connections
 
unsigned int ast_trace_get_by_module (const char *module)
 Get the trace level for a module. More...
 

Detailed Description

Basic Usage

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 destructor 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...

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));
...
}

would produce...

[2020-05-17 15:16:51 -0600] TRACE[953402] : --> res_pjsip_session.c:4283 create_local_sdp PJSIP/1173-00000001
[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...
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);
Note
Final note: The trace facility, like debug, is only available when AST_DEVMODE is defined.

TRACE_PREFIX

The default prefix to each log and trace line is "filename:line function" which is defined in the macro A at the top of this file:

#define _A_ __FILE__, __LINE__, __FUNCTION__

They become 3 arguments to the __ast_trace function and most of the ast_log* functions. For scope tracing, that may be unnecessary clutter in the trace output so you can now customise that with the TRACE_PREFIX macro. Like A, it MUST resolve to 3 arguments:

const char *, int, const char *

so the minimum would be:

#define _TRACE_PREFIX_ "",0,""

Normally you should define TRACE_PREFIX in your source file before including logger.h.

#define _TRACE_PREFIX_ "", __LINE__, ""
#include "asterisk/logger.h"

You can also define it later in your source file but because logger.h sets it to a default value, you'll have to undefine it first, then define it your your liking. If you want to go back to the default, you'll have to undefine it again, then define it to TRACE_PREFIX_DEFAULT.

#undef _TRACE_PREFIX_
#define _TRACE_PREFIX_ "", __LINE__, ""
<code>
#undef _TRACE_PREFIX_
#define _TRACE_PREFIX_ _TRACE_PREFIX_DEFAULT_
Note
Macros have a compilation unit scope so defining TRACE_PREFIX in one source file does NOT make it apply to any others. So if you define it in source file A, then call a function in source file B, the trace output from B will display based on how TRACE_PREFIX is defined in B, not A.

Macro Definition Documentation

#define ast_trace_log (   __level,
  __log_level,
  ... 
)
Value:
({ \
ast_log(__log_level, " " __VA_ARGS__); \
ast_trace(__level < 0 ? __scope_level : __level, " " __VA_ARGS__); \
})
void ast_log(int level, const char *file, int line, const char *function, const char *fmt,...)
Used for sending a log message This is the standard logger function. Probably the only way you will i...
Definition: ael_main.c:130

Definition at line 1072 of file include/asterisk/logger.h.

#define SCOPE_ENTER (   level,
  ... 
)
Value:
int __scope_level = level; \
ast_debug(level, " " __VA_ARGS__)
#define ast_debug(level,...)
Log a DEBUG message.

Definition at line 1009 of file include/asterisk/logger.h.

#define SCOPE_ENTER_TASK (   level,
  indent,
  ... 
)
Value:
int __scope_level = level; \
ast_debug(level, " " __VA_ARGS__)
#define ast_debug(level,...)
Log a DEBUG message.

Definition at line 1013 of file include/asterisk/logger.h.

#define SCOPE_EXIT_EXPR (   __expr,
  ... 
)
Value:
ast_debug(__scope_level, " " __VA_ARGS__); \
__expr
#define ast_debug(level,...)
Log a DEBUG message.

Definition at line 1029 of file include/asterisk/logger.h.

#define SCOPE_EXIT_LOG (   __log_level,
  ... 
)
Value:
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT(" " __VA_ARGS__); \
})
void ast_log(int level, const char *file, int line, const char *function, const char *fmt,...)
Used for sending a log message This is the standard logger function. Probably the only way you will i...
Definition: ael_main.c:130

The following macros will print log messages before running the associated SCOPE_ macro.

Definition at line 1048 of file include/asterisk/logger.h.

#define SCOPE_EXIT_LOG_EXPR (   __expr,
  __log_level,
  ... 
)
Value:
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT_EXPR(__expr, " " __VA_ARGS__); \
})
void ast_log(int level, const char *file, int line, const char *function, const char *fmt,...)
Used for sending a log message This is the standard logger function. Probably the only way you will i...
Definition: ael_main.c:130

Definition at line 1066 of file include/asterisk/logger.h.

#define SCOPE_EXIT_LOG_RTN (   __log_level,
  ... 
)
Value:
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT_RTN(" " __VA_ARGS__); \
})
void ast_log(int level, const char *file, int line, const char *function, const char *fmt,...)
Used for sending a log message This is the standard logger function. Probably the only way you will i...
Definition: ael_main.c:130

Definition at line 1054 of file include/asterisk/logger.h.

#define SCOPE_EXIT_LOG_RTN_VALUE (   __value,
  __log_level,
  ... 
)
Value:
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT_RTN_VALUE(__value, " " __VA_ARGS__); \
})
void ast_log(int level, const char *file, int line, const char *function, const char *fmt,...)
Used for sending a log message This is the standard logger function. Probably the only way you will i...
Definition: ael_main.c:130

Definition at line 1060 of file include/asterisk/logger.h.

#define SCOPE_EXIT_RTN (   ...)
Value:
ast_debug(__scope_level, " " __VA_ARGS__); \
return
#define ast_debug(level,...)
Log a DEBUG message.

Definition at line 1033 of file include/asterisk/logger.h.

#define SCOPE_EXIT_RTN_VALUE (   __return_value,
  ... 
)
Value:
ast_debug(__scope_level, " " __VA_ARGS__); \
return __return_value
#define ast_debug(level,...)
Log a DEBUG message.

Definition at line 1037 of file include/asterisk/logger.h.

#define TRACE_ATLEAST (   level)
Value:
(option_trace >= (level) \
|| (ast_opt_trace_module \
&& ((int)ast_trace_get_by_module(AST_MODULE) >= (level) \
|| (int)ast_trace_get_by_module(__FILE__) >= (level))))
unsigned int ast_trace_get_by_module(const char *module)
Get the trace level for a module.
Definition: main/cli.c:153
int option_trace
Definition: options.c:71

Definition at line 685 of file include/asterisk/logger.h.

Enumeration Type Documentation

Controls if and when indenting is applied.

Enumerator
AST_TRACE_INDENT_SAME 

Use the existing indent level

AST_TRACE_INDENT_INC_BEFORE 

Increment the indent before printing the message

AST_TRACE_INDENT_INC_AFTER 

Increment the indent after printing the message

AST_TRACE_INDENT_DEC_BEFORE 

Decrement the indent before printing the message

AST_TRACE_INDENT_DEC_AFTER 

Decrement the indent after printing the message

AST_TRACE_INDENT_PROVIDED 

Set the indent to the one provided

AST_TRACE_INDENT_NONE 

Don't use or alter the level

Definition at line 694 of file include/asterisk/logger.h.

694  {
695  /*! Use the existing indent level */
697  /*! Increment the indent before printing the message */
699  /*! Increment the indent after printing the message */
701  /*! Decrement the indent before printing the message */
703  /*! Decrement the indent after printing the message */
705  /*! Set the indent to the one provided */
707  /*! Don't use or alter the level */
709 };

Function Documentation

unsigned int ast_trace_get_by_module ( const char *  module)

Get the trace level for a module.

Parameters
modulethe name of module
Returns
the trace level

Definition at line 153 of file main/cli.c.

References AST_LIST_TRAVERSE, AST_RWLIST_RDLOCK, and AST_RWLIST_UNLOCK.

154 {
155  struct module_level *ml;
156  unsigned int res = 0;
157 
158  AST_RWLIST_RDLOCK(&trace_modules);
159  AST_LIST_TRAVERSE(&trace_modules, ml, entry) {
160  if (!strcasecmp(ml->module, module)) {
161  res = ml->level;
162  break;
163  }
164  }
165  AST_RWLIST_UNLOCK(&trace_modules);
166 
167  return res;
168 }
#define AST_RWLIST_RDLOCK(head)
Read locks a list.
Definition: linkedlists.h:78
map a debug or verbose level to a module name
Definition: main/cli.c:98
#define AST_LIST_TRAVERSE(head, var, field)
Loops over (traverses) the entries in a list.
Definition: linkedlists.h:491
Definition: search.h:40
#define AST_RWLIST_UNLOCK(head)
Attempts to unlock a read/write based list.
Definition: linkedlists.h:151