kenmirrors/asterisk
1
0
Fork 0
mirror of https://github.com/asterisk/asterisk.git synced 2025-09-18 18:58:22 +00:00
Code Issues Packages Projects Releases Wiki Activity
Files
823727501d1abd5cdcaf830387c6d9ccb1d5de8f
asterisk/tests/test_scope_trace.c

127 lines
2.9 KiB
C
Raw Normal View History

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
/*
* Asterisk -- An open source telephony toolkit.
*
* Copyright (C) 2020, Sangoma Technologies Corp
*
* George Joseph <gjoseph@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 Test for Scope Trace
*
* \author\verbatim George Joseph <gjoseph@digium.com> \endverbatim
*
* tests for Scope Trace
* \ingroup tests
*/
/*** MODULEINFO
<depend>TEST_FRAMEWORK</depend>
<support_level>core</support_level>
***/
#include "asterisk.h"
#include "asterisk/utils.h"
#include "asterisk/module.h"
#include "asterisk/test.h"
#include "asterisk/logger.h"
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
static const char *str_appender(struct ast_str**buf, char *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
{
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
ast_str_append(buf, 0, "<append %s>", a);
return ast_str_buffer(*buf);
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
}
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
static void test_scope_trace(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
{
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
SCOPE_ENTER(1, "subfunction\n");
SCOPE_EXIT_RTN("got out\n");
}
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
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
static int test_scope_enter_function(void)
{
SCOPE_ENTER(1, "%s %s %s %s %s %s %s\n",
ast_str_tmp(12, str_appender(&STR_TMP, "str1")),
ast_str_tmp(12, str_appender(&STR_TMP, "str2")),
ast_str_tmp(32, str_appender(&STR_TMP, "AAAAAAAAAAAAAAAAAAAAAAAA")),
ast_str_tmp(12, str_appender(&STR_TMP, "B")),
"ccccccccccccc",
ast_str_tmp(12, str_appender(&STR_TMP, "DDDDD")),
ast_str_tmp(12, str_appender(&STR_TMP, "ww"))
);
test_scope_trace();
SCOPE_EXIT_RTN_VALUE(AST_TEST_PASS, "test no variables\n");
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
}
AST_TEST_DEFINE(scope_test)
{
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
SCOPE_ENTER(1, "top %s function\n", "scope_test");
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
ast_trace(1, "%s\n", "test outer");
switch (cmd) {
case TEST_INIT:
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
{
SCOPE_ENTER(1, "TEST_INIT\n");
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
info->name = "scope_test";
info->category = "/main/logging/";
info->summary = "Scope Trace Tests";
info->description = "Scope Trace Tests";
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
/* need to exit the case scope */
SCOPE_EXIT("TEST_INIT\n");
/* need to exit the function */
SCOPE_EXIT_RTN_VALUE(AST_TEST_NOT_RUN, "BYE\n");
}
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
case TEST_EXECUTE:
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
{
SCOPE_ENTER(1, "TEST_EXECUTE\n");
ast_trace(1, "%s\n", "test execute");
SCOPE_EXIT_EXPR(break, "TEST_EXECUTE\n");
}
default:
ast_test_status_update(test, "Shouldn't have gotten here\n");
return AST_TEST_FAIL;
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 (1) {
SCOPE_TRACE(1, "IF block\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
test_scope_enter_function();
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
}
ast_trace(1);
ast_trace(1, "test no variables\n");
ast_trace(1, "%s\n", "test variable");
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
SCOPE_EXIT_RTN_VALUE(AST_TEST_PASS, "Something: %d\n", AST_TEST_PASS);
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
}
static int unload_module(void)
{
AST_TEST_UNREGISTER(scope_test);
return 0;
}
static int load_module(void)
{
AST_TEST_REGISTER(scope_test);
return AST_MODULE_LOAD_SUCCESS;
}
AST_MODULE_INFO_STANDARD(ASTERISK_GPL_KEY, "Scope Trace Test");
Reference in New Issue Copy Permalink