Files
asterisk/include/asterisk/logger.h

1085 lines
35 KiB
C
Raw Normal View History

/*
* Asterisk -- An open source telephony toolkit.
*
* Copyright (C) 1999 - 2005, Digium, Inc.
*
* Mark Spencer <markster@digium.com>
*
* See http://www.asterisk.org for more information about
* the Asterisk project. Please do not directly contact
* any of the maintainers of this project for assistance;
* the project provides a web site, mailing lists and IRC
* channels for your use.
*
* This program is free software, distributed under the terms of
* the GNU General Public License Version 2. See the LICENSE file
* at the top of the source tree.
*/
/*!
* \file
*
* \brief Support for logging to various files, console and syslog
* Configuration in file logger.conf
*/
#ifndef _ASTERISK_LOGGER_H
#define _ASTERISK_LOGGER_H
#include "asterisk/options.h" /* need option_debug */
#if defined(__cplusplus) || defined(c_plusplus)
extern "C" {
#endif
#define EVENTLOG "event_log"
#define QUEUELOG "queue_log"
#define DEBUG_M(a) { \
a; \
}
#define _A_ __FILE__, __LINE__, __FUNCTION__
#define VERBOSE_PREFIX_1 " "
#define VERBOSE_PREFIX_2 " == "
#define VERBOSE_PREFIX_3 " -- "
#define VERBOSE_PREFIX_4 " > "
#define VERBOSE_PREFIX_5 " > "
#define VERBOSE_PREFIX_6 " > "
#define VERBOSE_PREFIX_7 " > "
#define VERBOSE_PREFIX_8 " > "
#define VERBOSE_PREFIX_9 " > "
#define VERBOSE_PREFIX_10 " > "
#define AST_CALLID_BUFFER_LENGTH 13
enum ast_logger_results {
AST_LOGGER_SUCCESS = 0, /*!< Log channel was created or deleted successfully*/
AST_LOGGER_FAILURE = 1, /*!< Log channel already exists for create or doesn't exist for deletion of log channel */
AST_LOGGER_DECLINE = -1, /*!< Log channel request was not accepted */
AST_LOGGER_ALLOC_ERROR = -2 /*!< filename allocation error */
};
/*! \brief Used for sending a log message
This is the standard logger function. Probably the only way you will invoke it would be something like this:
ast_log(AST_LOG_WHATEVER, "Problem with the %s Captain. We should get some more. Will %d be enough?\n", "flux capacitor", 10);
where WHATEVER is one of ERROR, DEBUG, EVENT, NOTICE, or WARNING depending
on which log you wish to output to. These are implemented as macros, that
will provide the function with the needed arguments.
\param level Type of log event
\param file Will be provided by the AST_LOG_* macro
\param line Will be provided by the AST_LOG_* macro
\param function Will be provided by the AST_LOG_* macro
\param fmt This is what is important. The format is the same as your favorite breed of printf. You know how that works, right? :-)
*/
void ast_log(int level, const char *file, int line, const char *function, const char *fmt, ...)
__attribute__((format(printf, 5, 6)));
void ast_log_ap(int level, const char *file, int line, const char *function, const char *fmt, va_list ap)
__attribute__((format(printf, 5, 0)));
/*!
* \brief Used for sending a log message with protection against recursion.
*
* \note This function should be used by all error messages that might be directly
* or indirectly caused by logging.
*
* \see ast_log for documentation on the parameters.
*/
void ast_log_safe(int level, const char *file, int line, const char *function, const char *fmt, ...)
__attribute__((format(printf, 5, 6)));
/* XXX needs documentation */
typedef unsigned int ast_callid;
/*! \brief Used for sending a log message with a known call_id
This is a modified logger function which is functionally identical to the above logger function,
it just include a call_id argument as well. If NULL is specified here, no attempt will be made to
join the log message with a call_id.
\param level Type of log event
\param file Will be provided by the AST_LOG_* macro
\param line Will be provided by the AST_LOG_* macro
\param function Will be provided by the AST_LOG_* macro
\param callid This is the ast_callid that is associated with the log message. May be NULL.
\param fmt This is what is important. The format is the same as your favorite breed of printf. You know how that works, right? :-)
*/
void ast_log_callid(int level, const char *file, int line, const char *function, ast_callid callid, const char *fmt, ...)
__attribute__((format(printf, 6, 7)));
/*!
* \brief Retrieve the existing log channels
* \param logentry A callback to an updater function
* \param data Data passed into the callback for manipulation
*
* For each of the logging channels, logentry will be executed with the
* channel file name, log type, status of the log, and configuration levels.
*
* \retval 0 on success
* \retval 1 on failure
* \retval -2 on allocation error
*/
int ast_logger_get_channels(int (*logentry)(const char *channel, const char *type,
const char *status, const char *configuration, void *data), void *data);
/*!
* \brief Create a log channel
*
* \param log_channel Log channel to create
* \param components Logging config levels to add to the log channel
*/
int ast_logger_create_channel(const char *log_channel, const char *components);
/*!
* \brief Delete the specified log channel
*
* \param log_channel The log channel to delete
*/
int ast_logger_remove_channel(const char *log_channel);
/*!
* \brief Log a backtrace of the current thread's execution stack to the Asterisk log
*/
void ast_log_backtrace(void);
/*! \brief Reload logger while rotating log files */
int ast_logger_rotate(void);
/*!
* \brief Rotate the specified log channel.
*
* \param log_channel The log channel to rotate
*/
int ast_logger_rotate_channel(const char *log_channel);
void __attribute__((format(printf, 5, 6))) ast_queue_log(const char *queuename, const char *callid, const char *agent, const char *event, const char *fmt, ...);
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
/*!
* \brief Send a verbose message (based on verbose level)
*
* \details This works like ast_log, but prints verbose messages to the console depending on verbosity level set.
*
* ast_verbose(VERBOSE_PREFIX_3 "Whatever %s is happening\n", "nothing");
*
* This will print the message to the console if the verbose level is set to a level >= 3
*
* Note the absence of a comma after the VERBOSE_PREFIX_3. This is important.
* VERBOSE_PREFIX_1 through VERBOSE_PREFIX_10 are defined.
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
*
* \version 11 added level parameter
*/
void __attribute__((format(printf, 5, 6))) __ast_verbose(const char *file, int line, const char *func, int level, const char *fmt, ...);
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
/*!
* \brief Send a verbose message (based on verbose level) with deliberately specified callid
*
* \details just like __ast_verbose, only __ast_verbose_callid allows you to specify which callid is being used
* for the log without needing to bind it to a thread. NULL is a valid argument for this function and will
* allow you to specify that a log will never display a call id even when there is a call id bound to the
* thread.
*/
void __attribute__((format(printf, 6, 7))) __ast_verbose_callid(const char *file, int line, const char *func, int level, ast_callid callid, const char *fmt, ...);
#define ast_verbose(...) __ast_verbose(_A_, -1, __VA_ARGS__)
#define ast_verbose_callid(callid, ...) __ast_verbose_callid(_A_, -1, callid, __VA_ARGS__)
void __attribute__((format(printf, 6, 0))) __ast_verbose_ap(const char *file, int line, const char *func, int level, ast_callid callid, const char *fmt, va_list ap);
void __attribute__((format(printf, 2, 3))) ast_child_verbose(int level, const char *fmt, ...);
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
/*
* These gymnastics are due to platforms which designate char as unsigned by
* default. Level is the negative character -- offset by 1, because \0 is
* the string terminator.
*/
#define VERBOSE_MAGIC2LEVEL(x) (((char) -*(signed char *) (x)) - 1)
#define VERBOSE_HASMAGIC(x) (*(signed char *) (x) < 0)
void ast_console_puts(const char *string);
/*!
logger: Support JSON logging with Verbose messages When 2d7a4a3357 was merged, it missed the fact that Verbose log messages are formatted and handled by 'verbosers'. Verbosers are registered functions that handle verbose messages only; they exist as a separate class of callbacks. This was done to handle the 'magic' that must be inserted into Verbose messages sent to remote consoles, so that the consoles can format the messages correctly, i.e., the leading tabs/characters. In reality, verbosers are a weird appendage: they're a separate class of formatters/message handlers outside of what handles all other log messages in Asterisk. After some code inspection, it became clear that simply passing a Verbose message along with its 'sublevel' importance through the normal logging mechanisms removes the need for verbosers altogether. This patch removes the verbosers, and makes the default log formatter aware that, if the log channel is a console log, it should simply insert the 'verbose magic' into the log messages itself. This allows the console handlers to interpret and format the verbose message themselves. This simplifies the code quite a lot, and should improve the performance of printing verbose messages by a reasonable factor: (1) It removes a number of memory allocations that were done on each verobse message (2) It removes the need to strip the verbose magic out of the verbose log messages before passing them to non-console log channels (3) It now performs fewer iterations over lists when handling verbose messages Since verbose messages are now handled like other log messages (for the most part), the JSON formatting of the messages works as well. ASTERISK-25425 Change-Id: I21bf23f0a1e489b5102f8a035fe8871552ce4f96
2016-05-14 07:24:07 -05:00
* \brief log the string to the console, and all attached console clients
*
* \param string The message to write to the console
* \param level The log level of the message
*
* \version 1.6.1 added level parameter
*/
void ast_console_puts_mutable(const char *string, int level);
logger: Support JSON logging with Verbose messages When 2d7a4a3357 was merged, it missed the fact that Verbose log messages are formatted and handled by 'verbosers'. Verbosers are registered functions that handle verbose messages only; they exist as a separate class of callbacks. This was done to handle the 'magic' that must be inserted into Verbose messages sent to remote consoles, so that the consoles can format the messages correctly, i.e., the leading tabs/characters. In reality, verbosers are a weird appendage: they're a separate class of formatters/message handlers outside of what handles all other log messages in Asterisk. After some code inspection, it became clear that simply passing a Verbose message along with its 'sublevel' importance through the normal logging mechanisms removes the need for verbosers altogether. This patch removes the verbosers, and makes the default log formatter aware that, if the log channel is a console log, it should simply insert the 'verbose magic' into the log messages itself. This allows the console handlers to interpret and format the verbose message themselves. This simplifies the code quite a lot, and should improve the performance of printing verbose messages by a reasonable factor: (1) It removes a number of memory allocations that were done on each verobse message (2) It removes the need to strip the verbose magic out of the verbose log messages before passing them to non-console log channels (3) It now performs fewer iterations over lists when handling verbose messages Since verbose messages are now handled like other log messages (for the most part), the JSON formatting of the messages works as well. ASTERISK-25425 Change-Id: I21bf23f0a1e489b5102f8a035fe8871552ce4f96
2016-05-14 07:24:07 -05:00
/*!
* \brief log the string to the console, and all attached console clients
* \since 14.0.0
*
* \param message The message to write to the console
* \param sublevel If the log level supports it, the sub-level of the message
* \param level The log level of the message
*/
void ast_console_puts_mutable_full(const char *message, int level, int sublevel);
void ast_console_toggle_mute(int fd, int silent);
/*!
* \brief enables or disables logging of a specified level to the console
* fd specifies the index of the console receiving the level change
* level specifies the index of the logging level being toggled
* state indicates whether logging will be on or off (0 for off, 1 for on)
*/
void ast_console_toggle_loglevel(int fd, int level, int state);
/* Note: The AST_LOG_* macros below are the same as
* the LOG_* macros and are intended to eventually replace
* the LOG_* macros to avoid name collisions with the syslog(3)
* log levels. However, please do NOT remove
* the LOG_* macros from the source since these may be still
* needed for third-party modules
*/
#ifdef LOG_DEBUG
#undef LOG_DEBUG
#endif
#define __LOG_DEBUG 0
#define LOG_DEBUG __LOG_DEBUG, _A_
#ifdef AST_LOG_DEBUG
#undef AST_LOG_DEBUG
#endif
#define AST_LOG_DEBUG __LOG_DEBUG, _A_
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
#ifdef LOG_TRACE
#undef LOG_TRACE
#endif
#define __LOG_TRACE 1
#define LOG_TRACE __LOG_TRACE, _A_
#ifdef AST_LOG_TRACE
#undef AST_LOG_TRACE
#endif
#define AST_LOG_TRACE __LOG_TRACE, _A_
#ifdef LOG_NOTICE
#undef LOG_NOTICE
#endif
#define __LOG_NOTICE 2
#define LOG_NOTICE __LOG_NOTICE, _A_
#ifdef AST_LOG_NOTICE
#undef AST_LOG_NOTICE
#endif
#define AST_LOG_NOTICE __LOG_NOTICE, _A_
#ifdef LOG_WARNING
#undef LOG_WARNING
#endif
#define __LOG_WARNING 3
#define LOG_WARNING __LOG_WARNING, _A_
#ifdef AST_LOG_WARNING
#undef AST_LOG_WARNING
#endif
#define AST_LOG_WARNING __LOG_WARNING, _A_
#ifdef LOG_ERROR
#undef LOG_ERROR
#endif
#define __LOG_ERROR 4
#define LOG_ERROR __LOG_ERROR, _A_
#ifdef AST_LOG_ERROR
#undef AST_LOG_ERROR
#endif
#define AST_LOG_ERROR __LOG_ERROR, _A_
#ifdef LOG_VERBOSE
#undef LOG_VERBOSE
#endif
#define __LOG_VERBOSE 5
#define LOG_VERBOSE __LOG_VERBOSE, _A_
#ifdef AST_LOG_VERBOSE
#undef AST_LOG_VERBOSE
#endif
#define AST_LOG_VERBOSE __LOG_VERBOSE, _A_
#ifdef LOG_DTMF
#undef LOG_DTMF
#endif
#define __LOG_DTMF 6
#define LOG_DTMF __LOG_DTMF, _A_
#ifdef AST_LOG_DTMF
#undef AST_LOG_DTMF
#endif
#define AST_LOG_DTMF __LOG_DTMF, _A_
#define NUMLOGLEVELS 32
/*!
* \brief Get the debug level for a module
* \param module the name of module
* \return the debug level
*/
unsigned int ast_debug_get_by_module(const char *module);
/*!
* \brief Register a new logger level
* \param name The name of the level to be registered
* \retval -1 if an error occurs
* \retval non-zero level to be used with ast_log for sending messages to this level
* \since 1.8
*/
int ast_logger_register_level(const char *name);
/*!
* \brief Retrieve dynamic logging level id
* \param name The name of the level
* \return The unique integer id for the given level
* \retval -1 if level name not found
*/
int ast_logger_get_dynamic_level(const char *name);
/*!
* \brief Unregister a previously registered logger level
* \param name The name of the level to be unregistered
* \since 1.8
*/
void ast_logger_unregister_level(const char *name);
Logger/CLI/etc.: Fix some aesthetic issues; reduce chatty verbose messages This patch addresses some aesthetic issues in Asterisk. These are all just minor tweaks to improve the look of the CLI when used in a variety of settings. Specifically: * A number of chatty verbose messages were removed or demoted to DEBUG messages. Verbose messages with a verbosity level of 5 or higher were - if kept as verbose messages - demoted to level 4. Several messages that were emitted at verbose level 3 were demoted to 4, as announcement of dialplan applications being executed occur at level 3 (and so the effects of those applications should generally be less). * Some verbose messages that only appear when their respective 'debug' options are enabled were bumped up to always be displayed. * Prefix/timestamping of verbose messages were moved to the verboser handlers. This was done to prevent duplication of prefixes when the timestamp option (-T) is used with the CLI. * Verbose magic is removed from messages before being emitted to non-verboser handlers. This prevents the magic in multi-line verbose messages (such as SIP debug traces or the output of DumpChan) from being written to files. * _Slightly_ better support for the "light background" option (-W) was added. This includes using ast_term_quit in the output of XML documentation help, as well as changing the "Asterisk Ready" prompt to bright green on the default background (which stands a better chance of being displayed properly than bright white). Review: https://reviewboard.asterisk.org/r/3547/ git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@414798 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-05-28 22:54:12 +00:00
/*!
* \brief Get the logger configured date format
*
* \return The date format string
Logger/CLI/etc.: Fix some aesthetic issues; reduce chatty verbose messages This patch addresses some aesthetic issues in Asterisk. These are all just minor tweaks to improve the look of the CLI when used in a variety of settings. Specifically: * A number of chatty verbose messages were removed or demoted to DEBUG messages. Verbose messages with a verbosity level of 5 or higher were - if kept as verbose messages - demoted to level 4. Several messages that were emitted at verbose level 3 were demoted to 4, as announcement of dialplan applications being executed occur at level 3 (and so the effects of those applications should generally be less). * Some verbose messages that only appear when their respective 'debug' options are enabled were bumped up to always be displayed. * Prefix/timestamping of verbose messages were moved to the verboser handlers. This was done to prevent duplication of prefixes when the timestamp option (-T) is used with the CLI. * Verbose magic is removed from messages before being emitted to non-verboser handlers. This prevents the magic in multi-line verbose messages (such as SIP debug traces or the output of DumpChan) from being written to files. * _Slightly_ better support for the "light background" option (-W) was added. This includes using ast_term_quit in the output of XML documentation help, as well as changing the "Asterisk Ready" prompt to bright green on the default background (which stands a better chance of being displayed properly than bright white). Review: https://reviewboard.asterisk.org/r/3547/ git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@414798 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-05-28 22:54:12 +00:00
*
* \since 13.0.0
*/
const char *ast_logger_get_dateformat(void);
/*!
* \brief factory function to create a new uniquely identifying callid.
*
* \return The call id
*/
ast_callid ast_create_callid(void);
/*!
* \brief extracts the callerid from the thread
*
* \retval Non-zero Call id related to the thread
* \retval 0 if no call_id is present in the thread
*/
ast_callid ast_read_threadstorage_callid(void);
/*!
* \brief Sets what is stored in the thread storage to the given
* callid if it does not match what is already there.
*
* \retval 0 - success
* \retval non-zero - failure
*/
int ast_callid_threadassoc_change(ast_callid callid);
/*!
* \brief Adds a known callid to thread storage of the calling thread
*
* \retval 0 - success
* \retval non-zero - failure
*/
int ast_callid_threadassoc_add(ast_callid callid);
/*!
* \brief Removes callid from thread storage of the calling thread
*
* \retval 0 - success
* \retval non-zero - failure
*/
int ast_callid_threadassoc_remove(void);
/*!
* \brief Checks thread storage for a callid and stores a reference if it exists.
* If not, then a new one will be created, bound to the thread, and a reference
* to it will be stored.
*
* \param callid pointer to store the callid
* \retval 0 - callid was found
* \retval 1 - callid was created
* \retval -1 - the function failed somehow (presumably memory problems)
*/
int ast_callid_threadstorage_auto(ast_callid *callid);
/*!
* \brief Use in conjunction with ast_callid_threadstorage_auto. Cleans up the
* references and if the callid was created by threadstorage_auto, unbinds
* the callid from the threadstorage
* \param callid The callid set by ast_callid_threadstorage_auto
* \param callid_created The integer returned through ast_callid_threadstorage_auto
*/
void ast_callid_threadstorage_auto_clean(ast_callid callid, int callid_created);
/*!
* \brief copy a string representation of the callid into a target string
*
* \param buffer destination of callid string (should be able to store 13 characters or more)
* \param buffer_size maximum writable length of the string (Less than 13 will result in truncation)
* \param callid Callid for which string is being requested
*/
void ast_callid_strnprint(char *buffer, size_t buffer_size, ast_callid callid);
/*!
* \brief Send a log message to a dynamically registered log level
* \param level The log level to send the message to
*
* Like ast_log, the log message may include printf-style formats, and
* the data for these must be provided as additional parameters after
* the log message.
*
* \since 1.8
*/
#define ast_log_dynamic_level(level, ...) ast_log(level, _A_, __VA_ARGS__)
#define DEBUG_ATLEAST(level) \
(option_debug >= (level) \
|| (ast_opt_dbg_module \
&& ((int)ast_debug_get_by_module(AST_MODULE) >= (level) \
|| (int)ast_debug_get_by_module(__FILE__) >= (level))))
/*!
* \brief Log a DEBUG message
* \param level The minimum value of option_debug for this message
* to get logged
*/
#define ast_debug(level, ...) \
do { \
if (DEBUG_ATLEAST(level)) { \
ast_log(AST_LOG_DEBUG, __VA_ARGS__); \
} \
} while (0)
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
extern int ast_verb_sys_level;
#define VERBOSITY_ATLEAST(level) ((level) <= ast_verb_sys_level)
#define ast_verb(level, ...) \
do { \
if (VERBOSITY_ATLEAST(level) ) { \
__ast_verbose(_A_, level, __VA_ARGS__); \
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
} \
} while (0)
#define ast_verb_callid(level, callid, ...) \
do { \
if (VERBOSITY_ATLEAST(level) ) { \
__ast_verbose_callid(_A_, level, callid, __VA_ARGS__); \
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
} \
} while (0)
/*!
* \brief Re-evaluate the system max verbosity level (ast_verb_sys_level).
*/
void ast_verb_update(void);
/*!
* \brief Register this thread's console verbosity level pointer.
*
* \param level Where the verbose level value is.
*/
void ast_verb_console_register(int *level);
/*!
* \brief Unregister this thread's console verbosity level.
*/
void ast_verb_console_unregister(void);
/*!
* \brief Get this thread's console verbosity level.
*
* \return verbosity level of the console.
verbosity: Fix performance of console verbose messages. The per console verbose level feature as previously implemented caused a large performance penalty. The fix required some minor incompatibilities if the new rasterisk is used to connect to an earlier version. If the new rasterisk connects to an older Asterisk version then the root console verbose level is always affected by the "core set verbose" command of the remote console even though it may appear to only affect the current console. If an older version of rasterisk connects to the new version then the "core set verbose" command will have no effect. * Fixed the verbose performance by not generating a verbose message if nothing is going to use it and then filtered any generated verbose messages before actually sending them to the remote consoles. * Split the "core set debug" and "core set verbose" CLI commands to remove the per module verbose support that cannot work with the per console verbose level. * Added a silent option to the "core set verbose" command. * Fixed "core set debug off" tab completion. * Made "core show settings" list the current console verbosity in addition to the root console verbosity. * Changed the default verbose level of the 'verbose' setting in the logger.conf [logfiles] section. The default is now to once again follow the current root console level. As a result, using the AMI Command action with "core set verbose" could again set the root console verbose level and affect the verbose level logged. (closes issue AST-1252) Reported by: Guenther Kelleter Review: https://reviewboard.asterisk.org/r/3114/ ........ Merged revisions 405431 from http://svn.asterisk.org/svn/asterisk/branches/11 ........ Merged revisions 405432 from http://svn.asterisk.org/svn/asterisk/branches/12 git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@405436 65c4cc65-6c06-0410-ace0-fbb531ad65f3
2014-01-14 18:14:02 +00:00
*/
int ast_verb_console_get(void);
/*!
* \brief Set this thread's console verbosity level.
*
* \param verb_level New level to set.
*/
void ast_verb_console_set(int verb_level);
/*!
* \brief Test if logger is initialized
*
* \retval true if the logger is initialized
*/
int ast_is_logger_initialized(void);
/*!
* \brief Set the maximum number of messages allowed in the processing queue
*
* \param queue_limit
*/
void ast_logger_set_queue_limit(int queue_limit);
/*!
* \brief Get the maximum number of messages allowed in the processing queue
*
* \return Queue limit
*/
int ast_logger_get_queue_limit(void);
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
/*! \defgroup Scope_Trace Scope Trace
* @{
\page basic Basic Usage
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
The Scope Trace facility allows you to instrument code and output scope entry
and exit messages with associated data.
\par
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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
\par
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
Its simplest usage requires only 1 macro call that...
- Registers a destructor for a special variable that gets called when the
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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...
\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));
...
}
\endcode
would produce...
\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
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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.
\par Scope Output and Level:
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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.
\par Scope Indenting:
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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
\endverbatim
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
\note The trace level indicates which messages to print and has no effect on indent.
\par Generic Trace Messages:
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
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...
\code
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);
\endcode
\note Final note: The trace facility, like debug, is only available when AST_DEVMODE is defined.
*/
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
/*!
\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.
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
*/
#define _TRACE_PREFIX_DEFAULT_ _A_
#ifndef _TRACE_PREFIX_
#define _TRACE_PREFIX_ _TRACE_PREFIX_DEFAULT_
#endif
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
/*!
* \brief Get the trace level for a module
* \param module the name of module
* \return the trace level
*/
unsigned int ast_trace_get_by_module(const char *module);
/*!
* \brief load logger.conf configuration for console socket connections
*/
void ast_init_logger_for_socket_console(void);
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
#define TRACE_ATLEAST(level) \
(option_trace >= (level) \
|| (ast_opt_trace_module \
&& ((int)ast_trace_get_by_module(AST_MODULE) >= (level) \
|| (int)ast_trace_get_by_module(__FILE__) >= (level))))
/*!
* \brief Controls if and when indenting is applied.
*/
enum ast_trace_indent_type {
/*! 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,
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
/*! Don't use or alter the level */
AST_TRACE_INDENT_NONE,
};
#ifdef AST_DEVMODE
void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int line, const char *func,
enum ast_trace_indent_type indent_type, unsigned long indent, const char* format, ...);
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
/*!
* \brief Print a trace message
*
* \param level The trace level
* \param indent_type One of the \ref ast_trace_indent_type values
* \param ... A printf style format string, optionally with arguments
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
*
*/
#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(_TRACE_PREFIX_, indent_type, 0, " " __VA_ARGS__); \
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
}
/*!
* \brief Print a basic trace message
*
* \param level The trace level
* \param ... A printf style format string, optionally with arguments
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
*
* This will print the file, line and function at the current indent level
*/
#define ast_trace(level, ...) \
ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(level < 0 ? __scope_level : level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_SAME, 0, " " __VA_ARGS__); \
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
}
/*!
* \brief Get the current indent level
*
* \return The current indent level
*/
unsigned long _ast_trace_get_indent(void);
#define ast_trace_get_indent() _ast_trace_get_indent()
/*!
* \brief Set the current indent level
*
* \param indent The new indent level
*/
void _ast_trace_set_indent(unsigned long indent);
#define ast_trace_set_indent(indent) _ast_trace_set_indent(indent)
/*!
* \brief Increment the indent level
*
* \return The new indent level
*/
unsigned long _ast_trace_inc_indent(void);
#define ast_trace_inc_indent() _ast_trace_inc_indent()
/*!
* \brief Decrement the indent level
*
* \return The new indent level
*/
unsigned long _ast_trace_dec_indent(void);
#define ast_trace_dec_indent() _ast_trace_dec_indent()
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
/*!
* \brief Print a trace message with details when a scope is entered or existed.
*
* \param level The trace level
* \param ... A printf style format string, optionally with arguments
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
*
* This will print the file, line and function plus details at the current indent level.
* \note Like RAII_VAR, this macro must be called before any code in the scope.
*
* \note The variables used to detect scope change will look like
* __scopevar1234__EXIT and __scopevar1234__ENTER.
* The ENTER variable and function are needed to prevent mixed code and declaration issues.
* If we simple called __ast_trace, then this macro would need to be the last line
* of scope variable declaration. The following would fail.
*
* SCOPE_TRACE(1, "Help!\n");
* int i;
*/
#define SCOPE_TRACE(level, ...) \
const char *__trace_funcname = __PRETTY_FUNCTION__; \
auto void __scopevar ## __LINE__ ## __EXIT(void * v); \
void __scopevar ## __LINE__ ## __EXIT(void * v __attribute__((unused))) { \
if (TRACE_ATLEAST(level)) { \
__ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
} \
} \
void *__scopevar ## __LINE__ ## __TRACER __attribute__((cleanup(__scopevar ## __LINE__ ## __EXIT))) = (void *) __PRETTY_FUNCTION__ ; \
auto int __scopevar ## __LINE__ ## __ENTER(void); \
int __scopevar ## __LINE__ ## __ENTER(void) { \
if (TRACE_ATLEAST(level)) { \
__ast_trace(__FILE__, __LINE__, __trace_funcname, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
} \
return 0; \
} \
int __scopevar ## __LINE__ ## __RETURN __attribute__((unused)) = __scopevar ## __LINE__ ## __ENTER()
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
/*!
* \brief Non RAII_VAR Scope Trace macros
* The advantage of these macros is that the EXITs will have the actual
* line number where the scope exited. Much less code is required as well.
*/
/*!
* \brief Scope Enter
*
* \param level The trace level
* \param ... A printf style format string, optionally with arguments
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
*/
#define SCOPE_ENTER(level, ...) \
int __scope_level = level; \
int __scope_task = 0; \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \
} \
#define SCOPE_ENTER_TASK(level, indent, ...) \
int __scope_level = level; \
int __scope_task = 1; \
ast_debug(__scope_level, " " __VA_ARGS__); \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
if (TRACE_ATLEAST(level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_PROVIDED, indent, " " __VA_ARGS__); \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
} \
/*!
* \def SCOPE_CALL
* \brief Wrap a function call in "--> Calling:" and "<-- Return from:" trace messages
*
* \param level The trace level (usually -1 to use the same level as the calling function)
* \param __funcname The name of the function to call (return value, if any, is ignored)
* \param ... Arguments to pass to the function
*
* Simple Example:
* The following code called from inside the app_voicemail.c leave_voicemail function...
\code
SCOPE_CALL(-1, store_file, dir, vmu->mailbox, vmu->context, msgnum);
\endcode
* would produce...
\verbatim
1 app_voicemail_odbc.c:7161 leave_voicemail: --> Calling store_file
1 --> app_voicemail_odbc.c:4483 store_file: dir: /var/spool/asterisk/voicemail/default/1179/INBOX user: 1179 context: default msgnum: 8
2 app_voicemail_odbc.c:4502 store_file: Formats: wav49|gsm|wav Using format: 'WAV'
2 app_voicemail_odbc.c:4510 store_file: Base path: '/var/spool/asterisk/voicemail/default/1179/INBOX/msg0008'
2 app_voicemail_odbc.c:4513 store_file: Basename: 'msg0008'
1 <-- app_voicemail_odbc.c:4597 store_file: Success
1 app_voicemail_odbc.c:7161 leave_voicemail: <-- Return from store_file
\endverbatim
*/
#define SCOPE_CALL(level, __funcname, ...) \
({ \
ast_trace(level, "--> Calling %s\n", #__funcname); \
__funcname(__VA_ARGS__); \
ast_trace(level, "<-- Return from %s\n", #__funcname); \
})
/*!
* \def SCOPE_CALL_WITH_RESULT
* \brief Wrap a function call returning a value in "--> Calling:" and "<-- Return from:" trece messages
*
* \param level The trace level (usually -1 to use the same level as the calling function)
* \param __type The return type of the function
* \param __funcname The name of the function to call
* \param ... Arguments to pass to the function
*
* Simple Example:
* The following code called from inside the app_voicemail.c leave_voicemail function...
\code
int res = 0;
res = SCOPE_CALL_WITH_RESULT(-1, int, store_file, dir, vmu->mailbox, vmu->context, msgnum);
\endcode
* would produce...
\verbatim
1 app_voicemail_odbc.c:7161 leave_voicemail: --> Calling store_file
1 --> app_voicemail_odbc.c:4483 store_file: dir: /var/spool/asterisk/voicemail/default/1179/INBOX user: 1179 context: default msgnum: 8
2 app_voicemail_odbc.c:4502 store_file: Formats: wav49|gsm|wav Using format: 'WAV'
2 app_voicemail_odbc.c:4510 store_file: Base path: '/var/spool/asterisk/voicemail/default/1179/INBOX/msg0008'
2 app_voicemail_odbc.c:4513 store_file: Basename: 'msg0008'
1 <-- app_voicemail_odbc.c:4597 store_file: Success
1 app_voicemail_odbc.c:7161 leave_voicemail: <-- Return from store_file
\endverbatim
* ...and the return value of the store_file function would be assigned to the variable res.
*/
#define SCOPE_CALL_WITH_RESULT(level, __type, __funcname, ...) \
({ \
__type __var; \
ast_trace(level, "--> Calling %s\n", #__funcname); \
__var = __funcname(__VA_ARGS__); \
ast_trace(level, "<-- Return from %s\n", #__funcname); \
__var; \
})
#define SCOPE_CALL_WITH_INT_RESULT(level, __funcname, ...) \
SCOPE_CALL_WITH_RESULT(level, int, __funcname, __VA_ARGS__)
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
/*!
* \brief Scope Exit
*
* \param ... A printf style format string, optionally with arguments
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
*
* \details
* This macro can be used at the exit points of a statement block since it just prints the message.
*/
#define SCOPE_EXIT(...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \
_ast_trace_set_indent(0); \
} \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
} \
/*!
* \brief Scope Exit with expression
*
* \param __expr An expression to execute after printing the message
* \param ... A printf style format string, optionally with arguments
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
*
* \details
* Handy for getting out of or continuing loops.
*
* \code
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
* while(something) {
* SCOPE_ENTER(2, "In a while\n");
* if (something) {
* SCOPE_EXIT_EXPR(break, "Somethiung broke me\n");
* } else {
* SCOPE_EXIT_EXPR(continue, "Somethiung continued me\n");
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
* }
* }
* \endcode
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
*/
#define SCOPE_EXIT_EXPR(__expr, ...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \
_ast_trace_set_indent(0); \
} \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
} \
__expr
/*!
* \brief Scope Exit with return
*
* \param ... A printf style format string, optionally with arguments
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
*
* \details
* This macro can be used at the exit points of a function when no value
* needs to be returned.
*/
#define SCOPE_EXIT_RTN(...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \
_ast_trace_set_indent(0); \
} \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
} \
return
/*!
* \brief Scope Exit with return value
*
* \param __return_value The return value
* \param ... A printf style format string, optionally with arguments
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
*
* \details
* This macro can be used at the exit points of a function when a value
* needs to be returned.
*/
#define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(_TRACE_PREFIX_, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \
_ast_trace_set_indent(0); \
} \
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
} \
return(__return_value)
#else /* AST_DEVMODE */
#define ast_trace_raw(level, indent_type, ...) \
ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__)
#define ast_trace(level, ...) \
ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__)
#define ast_trace_get_indent() (0)
#define ast_trace_set_indent(indent)
#define ast_trace_inc_indent()
#define ast_trace_dec_indent()
Scope Trace: Add some new tracing macros and an ast_str helper Created new SCOPE_ functions that don't depend on RAII_VAR. Besides generating less code, the use of the explicit SCOPE_EXIT macros capture the line number where the scope exited. The RAII_VAR versions can't do that. * SCOPE_ENTER(level, ...): Like SCOPE_TRACE but doesn't use RAII_VAR and therefore needs needs one of... * SCOPE_EXIT(...): Decrements the trace stack counter and optionally prints a message. * SCOPE_EXIT_EXPR(__expr, ...): Decrements the trace stack counter, optionally prints a message, then executes the expression. SCOPE_EXIT_EXPR(break, "My while got broken\n"); * SCOPE_EXIT_RTN(, ...): Decrements the trace stack counter, optionally prints a message, then returns without a value. SCOPE_EXIT_RTN("Bye\n"); * SCOPE_EXIT_RTN_VALUE(__return_value, ...): Decrements the trace stack counter, optionally prints a message, then returns the value specified. SCOPE_EXIT_RTN_VALUE(rc, "Returning with RC: %d\n", rc); Create an ast_str helper ast_str_tmp() that allocates a temporary ast_str that can be passed to a function that needs it, then frees it. This makes using the above macros easier. Example: SCOPE_ENTER(1, Format Caps 1: %s Format Caps 2: %s\n", ast_str_tmp(32, ast_format_cap_get_names(cap1, &STR_TMP), ast_str_tmp(32, ast_format_cap_get_names(cap2, &STR_TMP)); The calls to ast_str_tmp create an ast_str of the specified initial length which can be referenced as STR_TMP. It then calls the expression, which must return a char *, ast_strdupa's it, frees STR_TMP, then returns the ast_strdupa'd string. That string is freed when the function returns. Change-Id: I44059b20d55a889aa91440d2f8a590865998be51
2020-06-30 07:56:34 -06:00
#define SCOPE_TRACE(__level, ...)
#define SCOPE_ENTER(level, ...) \
int __scope_level = level; \
ast_debug(level, " " __VA_ARGS__)
#define SCOPE_ENTER_TASK(level, indent, ...) \
int __scope_level = level; \
ast_debug(level, " " __VA_ARGS__)
#define SCOPE_CALL(level, __funcname, ...) \
__funcname(__VA_ARGS__)
#define SCOPE_CALL_WITH_RESULT(level, __var, __funcname, ...) \
__funcname(__VA_ARGS__)
#define SCOPE_CALL_WITH_INT_RESULT(level, __funcname, ...) \
__funcname(__VA_ARGS__)
#define SCOPE_EXIT(...) \
ast_debug(__scope_level, " " __VA_ARGS__)
#define SCOPE_EXIT_EXPR(__expr, ...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
__expr
#define SCOPE_EXIT_RTN(...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
return
#define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
return __return_value
#endif /* AST_DEVMODE */
/*!
* The following macros will print log messages before running
* the associated SCOPE_ macro.
*/
#define SCOPE_EXIT_LOG(__log_level, ...) \
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT(" " __VA_ARGS__); \
})
#define SCOPE_EXIT_LOG_RTN(__log_level, ...) \
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT_RTN(" " __VA_ARGS__); \
})
#define SCOPE_EXIT_LOG_RTN_VALUE(__value, __log_level, ...) \
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT_RTN_VALUE(__value, " " __VA_ARGS__); \
})
#define SCOPE_EXIT_LOG_EXPR(__expr, __log_level, ...) \
({ \
ast_log(__log_level, " " __VA_ARGS__); \
SCOPE_EXIT_EXPR(__expr, " " __VA_ARGS__); \
})
#define ast_trace_log(__level, __log_level, ...) \
({ \
ast_log(__log_level, " " __VA_ARGS__); \
ast_trace(__level < 0 ? __scope_level : __level, " " __VA_ARGS__); \
})
Scope Tracing: A new facility for tracing scope enter/exit What's wrong with ast_debug? ast_debug is fine for general purpose debug output but it's not really geared for scope tracing since it doesn't present its output in a way that makes capturing and analyzing flow through Asterisk easy. How is scope tracing better? Scope tracing uses the same "cleanup" attribute that RAII_VAR uses to print messages to a separate "trace" log level. Even better, the messages are indented and unindented based on a thread-local call depth counter. When output to a separate log file, the output is uncluttered and easy to follow. Here's an example of the output. The leading timestamps and thread ids are removed and the output cut off at 68 columns for commit message restrictions but you get the idea. --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 --> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 --> res_pjsip_session.c:3669 handle_incoming_response PJSIP/ --> chan_pjsip.c:3265 chan_pjsip_incoming_response_after --> chan_pjsip.c:3194 chan_pjsip_incoming_response P chan_pjsip.c:3245 chan_pjsip_incoming_respon <-- chan_pjsip.c:3194 chan_pjsip_incoming_response P <-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after <-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/ <-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173 <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001 The messages with the "-->" or "<--" were produced by including the following at the top of each function: SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session)); Scope isn't limited to functions any more than RAII_VAR is. You can also see entry and exit from "if", "for", "while", etc blocks. There is also an ast_trace() macro that doesn't track entry or exit but simply outputs a message to the trace log using the current indent level. The deepest message in the sample (chan_pjsip.c:3245) was used to indicate which "case" in a "select" was executed. How do you use it? More documentation is available in logger.h but here's an overview: * Configure with --enable-dev-mode. Like debug, scope tracing is #ifdef'd out if devmode isn't enabled. * Add a SCOPE_TRACE() call to the top of your function. * Set a logger channel in logger.conf to output the "trace" level. * Use the CLI (or cli.conf) to set a trace level similar to setting debug level... CLI> core set trace 2 res_pjsip.so Summary Of Changes: * Added LOG_TRACE logger level. Actually it occupies the slot formerly occupied by the now defunct "event" level. * Added core asterisk option "trace" similar to debug. Includes ability to specify global trace level in asterisk.conf and CLI commands to turn on/off and set levels. Levels can be set globally (probably not a good idea), or by module/source file. * Updated sample asterisk.conf and logger.conf. Tracing is disabled by default in both. * Added __ast_trace() to logger.c which keeps track of the indent level using TLS. It's #ifdef'd out if devmode isn't enabled. * Added ast_trace() and SCOPE_TRACE() macros to logger.h. These are all #ifdef'd out if devmode isn't enabled. Why not use gcc's -finstrument-functions capability? gcc's facility doesn't allow access to local data and doesn't operate on non-function scopes. Known Issues: The only know issue is that we currently don't know the line number where the scope exited. It's reported as the same place the scope was entered. There's probably a way to get around it but it might involve looking at the stack and doing an 'addr2line' to get the line number. Kind of like ast_backtrace() does. Not sure if it's worth it. Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
2020-05-14 12:24:19 -06:00
#if defined(__cplusplus) || defined(c_plusplus)
}
#endif
/*!
* @}
*/
#endif /* _ASTERISK_LOGGER_H */