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