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_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 More...
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

_TRACE_PREFIX_

#define _TRACE_PREFIX_   _TRACE_PREFIX_DEFAULT_

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

_TRACE_PREFIX_DEFAULT_

#define _TRACE_PREFIX_DEFAULT_   _A_

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

ast_trace

#define ast_trace	(		level,
			...
	)		ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__)

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

ast_trace_dec_indent

#define ast_trace_dec_indent

(

)

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

ast_trace_get_indent

#define ast_trace_get_indent

(

)

(0)

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

ast_trace_inc_indent

#define ast_trace_inc_indent

(

)

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

ast_trace_log

#define ast_trace_log	(		__level,
			__log_level,
			...
	)

Value:

({ \
    ast_log(__log_level, " " __VA_ARGS__); \
    ast_trace(__level < 0 ? __scope_level : __level, " " __VA_ARGS__); \
})

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

ast_trace_raw

#define ast_trace_raw	(		level,
			indent_type,
			...
	)		ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__)

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

ast_trace_set_indent

#define ast_trace_set_indent

(

indent

)

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

SCOPE_CALL

#define SCOPE_CALL	(		level,
			__funcname,
			...
	)		__funcname(__VA_ARGS__)

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

SCOPE_CALL_WITH_RESULT

#define SCOPE_CALL_WITH_RESULT	(		level,
			__var,
			__funcname,
			...
	)		__var = __funcname(__VA_ARGS__)

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

SCOPE_ENTER

#define SCOPE_ENTER	(		level,
			...
	)

Value:

    int __scope_level = level; \
    ast_debug(level, " " __VA_ARGS__)

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

SCOPE_ENTER_TASK

#define SCOPE_ENTER_TASK	(		level,
			indent,
			...
	)

Value:

    int __scope_level = level; \
    ast_debug(level, " " __VA_ARGS__)

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

SCOPE_EXIT

#define SCOPE_EXIT

(

...

)

ast_debug(__scope_level, " " __VA_ARGS__)

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

SCOPE_EXIT_EXPR

#define SCOPE_EXIT_EXPR	(		__expr,
			...
	)

Value:

    ast_debug(__scope_level, " " __VA_ARGS__); \
    __expr

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

SCOPE_EXIT_LOG

#define SCOPE_EXIT_LOG	(		__log_level,
			...
	)

Value:

({ \
    ast_log(__log_level, " " __VA_ARGS__); \
    SCOPE_EXIT(" " __VA_ARGS__); \
})

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

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

SCOPE_EXIT_LOG_EXPR

#define SCOPE_EXIT_LOG_EXPR	(		__expr,
			__log_level,
			...
	)

Value:

({ \
    ast_log(__log_level, " " __VA_ARGS__); \
    SCOPE_EXIT_EXPR(__expr, " " __VA_ARGS__); \
})

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

SCOPE_EXIT_LOG_RTN

#define SCOPE_EXIT_LOG_RTN	(		__log_level,
			...
	)

Value:

({ \
    ast_log(__log_level, " " __VA_ARGS__); \
    SCOPE_EXIT_RTN(" " __VA_ARGS__); \
})

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

SCOPE_EXIT_LOG_RTN_VALUE

#define SCOPE_EXIT_LOG_RTN_VALUE	(		__value,
			__log_level,
			...
	)

Value:

({ \
    ast_log(__log_level, " " __VA_ARGS__); \
    SCOPE_EXIT_RTN_VALUE(__value, " " __VA_ARGS__); \
})

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

SCOPE_EXIT_RTN

#define SCOPE_EXIT_RTN

(

...

)

Value:

    ast_debug(__scope_level, " " __VA_ARGS__); \
    return

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

SCOPE_EXIT_RTN_VALUE

#define SCOPE_EXIT_RTN_VALUE	(		__return_value,
			...
	)

Value:

    ast_debug(__scope_level, " " __VA_ARGS__); \
    return __return_value

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

SCOPE_TRACE

#define SCOPE_TRACE	(		__level,
			...
	)

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

TRACE_ATLEAST

#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))))

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

Enumeration Type Documentation

ast_trace_indent_type

enum ast_trace_indent_type

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 688 of file include/asterisk/logger.h.

                           {
    /*! 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,
    /*! Set the indent to the one provided */
    AST_TRACE_INDENT_PROVIDED,
    /*! Don't use or alter the level */
    AST_TRACE_INDENT_NONE,
};

Function Documentation

ast_init_logger_for_socket_console()

void ast_init_logger_for_socket_console

(

void

)

load logger.conf configuration for console socket connections

Definition at line 701 of file logger.c.

{
    struct ast_config *cfg;
    const char *s;
    struct ast_flags config_flags = { 0 };
 
    if (!(cfg = ast_config_load2("logger.conf", "logger", config_flags)) || cfg == CONFIG_STATUS_FILEINVALID) {
        return;
    }
 
    if ((s = ast_variable_retrieve(cfg, "general", "dateformat"))) {
        ast_copy_string(dateformat, s, sizeof(dateformat));
    }
 
    ast_config_destroy(cfg);
}

References ast_config_destroy(), ast_config_load2(), ast_copy_string(), ast_variable_retrieve(), CONFIG_STATUS_FILEINVALID, and dateformat.

Referenced by ast_remotecontrol().

ast_trace_get_by_module()

unsigned int ast_trace_get_by_module

(

const char *

module

)

Get the trace level for a module.

Parameters

module

the name of module

Returns

the trace level

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

{
    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;
}

References AST_LIST_TRAVERSE, AST_RWLIST_RDLOCK, AST_RWLIST_UNLOCK, module_level::level, and trace_modules.