logger.h: Add ability to change the prefix on SCOPE_TRACE output

You can now define the _TRACE_PREFIX_ macro to change the default trace line prefix of "file:line function" to something else. Full documentation in logger.h.
2 years ago · b52e07ee1b
parent a9d4175e1d
commit b52e07ee1b
1 changed files with 85 additions and 29 deletions
--- 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 <trace_level> [ 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 <trace_level> [ 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
+<tt>"filename:line function"</tt> 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__, ""
+<code>
+#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 */