diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h index e2a21c7f14..f01e11766c 100644 --- a/include/asterisk/logger.h +++ b/include/asterisk/logger.h @@ -526,19 +526,20 @@ void ast_logger_set_queue_limit(int queue_limit); int ast_logger_get_queue_limit(void); -/*! - \page Scope_Trace Scope Trace +/*! \defgroup Scope_Trace Scope Trace + * @{ +\page basic Basic Usage The Scope Trace facility allows you to instrument code and output scope entry and exit messages with associated data. - +\par 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: - \verbatim CLI> core set trace [ module ] \endverbatim - + - 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: +\verbatim CLI> core set trace [ module ] \endverbatim +\par 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. @@ -558,29 +559,29 @@ static struct pjmedia_sdp_session *create_local_sdp(pjsip_inv_session *inv, } \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 +\verbatim +[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 +\endverbatim 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. - +\par 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: - +\par 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: - +\par 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): - +\verbatim 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 @@ -594,11 +595,10 @@ TRACE[953402] : <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/1 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 - +\endverbatim \note The trace level indicates which messages to print and has no effect on indent. -Generic Trace Messages: - +\par 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 @@ -608,10 +608,62 @@ an entry/exit message. To do so, you can use the ast_trace macros... (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. +\note Final note: The trace facility, like debug, is only available when AST_DEVMODE is defined. +*/ + +/*! +\page TRACE_PREFIX TRACE_PREFIX +The default prefix to each log and trace line is +"filename:line function" which is defined in the +macro \c _A_ at the top of this file: +\code +#define _A_ __FILE__, __LINE__, __FUNCTION__ +\endcode +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 \c _TRACE_PREFIX_ +macro. Like \c _A_, it MUST resolve to 3 arguments: +\verbatim +const char *, int, const char * +\endverbatim +so the minimum would be: +\code +#define _TRACE_PREFIX_ "",0,"" +\endcode +Normally you should define \c _TRACE_PREFIX_ in your source +file before including logger.h. +\code +#define _TRACE_PREFIX_ "", __LINE__, "" +#include "asterisk/logger.h" +\endcode +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 \c _TRACE_PREFIX_DEFAULT_. +\code +#undef _TRACE_PREFIX_ +#define _TRACE_PREFIX_ "", __LINE__, "" + +#undef _TRACE_PREFIX_ +#define _TRACE_PREFIX_ _TRACE_PREFIX_DEFAULT_ +\endcode + +\note Macros have a compilation unit scope so +defining \c _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 \c _TRACE_PREFIX_ is defined in B, not A. */ +#define _TRACE_PREFIX_DEFAULT_ _A_ +#ifndef _TRACE_PREFIX_ +#define _TRACE_PREFIX_ _TRACE_PREFIX_DEFAULT_ +#endif + /*! * \brief Get the trace level for a module * \param module the name of module @@ -666,7 +718,7 @@ void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int li #define ast_trace_raw(level, indent_type, ...) \ ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level < 0 ? __scope_level : level)) { \ - __ast_trace(_A_, indent_type, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, indent_type, 0, " " __VA_ARGS__); \ } /*! @@ -680,7 +732,7 @@ void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int li #define ast_trace(level, ...) \ ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level < 0 ? __scope_level : level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_SAME, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_SAME, 0, " " __VA_ARGS__); \ } /*! @@ -768,7 +820,7 @@ unsigned long _ast_trace_dec_indent(void); int __scope_task = 0; \ ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \ } \ #define SCOPE_ENTER_TASK(level, indent, ...) \ @@ -776,7 +828,7 @@ unsigned long _ast_trace_dec_indent(void); int __scope_task = 1; \ ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_PROVIDED, indent, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_PROVIDED, indent, " " __VA_ARGS__); \ } \ /*! @@ -790,7 +842,7 @@ unsigned long _ast_trace_dec_indent(void); #define SCOPE_EXIT(...) \ ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ _ast_trace_set_indent(0); \ } \ @@ -819,7 +871,7 @@ unsigned long _ast_trace_dec_indent(void); #define SCOPE_EXIT_EXPR(__expr, ...) \ ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ _ast_trace_set_indent(0); \ } \ @@ -838,7 +890,7 @@ unsigned long _ast_trace_dec_indent(void); #define SCOPE_EXIT_RTN(...) \ ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ _ast_trace_set_indent(0); \ } \ @@ -858,7 +910,7 @@ unsigned long _ast_trace_dec_indent(void); #define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \ ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ - __ast_trace(_A_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ + __ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ _ast_trace_set_indent(0); \ } \ @@ -943,4 +995,8 @@ unsigned long _ast_trace_dec_indent(void); } #endif +/*! + * @} + */ + #endif /* _ASTERISK_LOGGER_H */