kenmirrors/asterisk
1
0
Fork 0
mirror of https://github.com/asterisk/asterisk.git synced 2025-09-05 12:16:00 +00:00
Code Issues Packages Projects Releases Wiki Activity

scope_trace: Added debug messages and added additional macros

Browse Source 
The SCOPE_ENTER and SCOPE_EXIT* macros now print debug messages
at the same level as the scope level.  This allows the same
messages to be printed to the debug log when AST_DEVMODE
isn't enabled.

Also added a few variants of the SCOPE_EXIT macros that will
also call ast_log instead of ast_debug to make it easier to
use scope tracing and still print error messages.

Change-Id: I7fe55f7ec28069919a0fc0b11a82235ce904cc21
This commit is contained in:
George Joseph
2020-08-19 06:37:23 -06:00
parent 118cb3f0dd
commit 64ca2d48da
3 changed files with 100 additions and 26 deletions
Download Patch File Download Diff File Expand all files Collapse all files

30
apps/app_dial.c
View File

@@ -1224,7 +1224,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
int sent_ring = 0; int sent_ring = 0;
int sent_progress = 0; int sent_progress = 0;
struct timeval start = ast_tvnow(); struct timeval start = ast_tvnow();
SCOPE_TRACE(1, "%s\n", ast_channel_name(in)); SCOPE_ENTER(3, "%s\n", ast_channel_name(in));
if (single) { if (single) {
/* Turn off hold music, etc */ /* Turn off hold music, etc */
@@ -1240,7 +1240,8 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
*to = -1; *to = -1;
strcpy(pa->status, "CONGESTION"); strcpy(pa->status, "CONGESTION");
ast_channel_publish_dial(in, outgoing->chan, NULL, pa->status); ast_channel_publish_dial(in, outgoing->chan, NULL, pa->status);
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "%s: can't be made compat with %s\n",
ast_channel_name(in), ast_channel_name(outgoing->chan));
} }
} }
@@ -1282,7 +1283,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
if (is_cc_recall) { if (is_cc_recall) {
ast_cc_failed(cc_recall_core_id, "Everyone is busy/congested for the recall. How sad"); ast_cc_failed(cc_recall_core_id, "Everyone is busy/congested for the recall. How sad");
} }
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "%s: No outging channels available\n", ast_channel_name(in));
} }
winner = ast_waitfor_n(watchers, pos, to); winner = ast_waitfor_n(watchers, pos, to);
AST_LIST_TRAVERSE(out_chans, o, node) { AST_LIST_TRAVERSE(out_chans, o, node) {
@@ -1391,7 +1392,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
case AST_CONTROL_ANSWER: case AST_CONTROL_ANSWER:
/* This is our guy if someone answered. */ /* This is our guy if someone answered. */
if (!peer) { if (!peer) {
ast_trace(1, "%s answered %s\n", ast_channel_name(c), ast_channel_name(in)); ast_trace(-1, "%s answered %s\n", ast_channel_name(c), ast_channel_name(in));
ast_verb(3, "%s answered %s\n", ast_channel_name(c), ast_channel_name(in)); ast_verb(3, "%s answered %s\n", ast_channel_name(c), ast_channel_name(in));
if (o->orig_chan_name if (o->orig_chan_name
&& strcmp(o->orig_chan_name, ast_channel_name(c))) { && strcmp(o->orig_chan_name, ast_channel_name(c))) {
@@ -1426,7 +1427,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
* from being cleaned up when the frame is cleaned up. * from being cleaned up when the frame is cleaned up.
*/ */
config->answer_topology = ao2_bump(f->subclass.topology); config->answer_topology = ao2_bump(f->subclass.topology);
ast_trace(2, "%s Found topology in frame: %p %p %s\n", ast_trace(-1, "%s Found topology in frame: %p %p %s\n",
ast_channel_name(peer), f, config->answer_topology, ast_channel_name(peer), f, config->answer_topology,
ast_str_tmp(256, ast_stream_topology_to_str(config->answer_topology, &STR_TMP))); ast_str_tmp(256, ast_stream_topology_to_str(config->answer_topology, &STR_TMP)));
} }
@@ -1721,7 +1722,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
if (is_cc_recall) { if (is_cc_recall) {
ast_cc_completed(in, "CC completed, although the caller hung up (cancelled)"); ast_cc_completed(in, "CC completed, although the caller hung up (cancelled)");
} }
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "%s: Caller hung up\n", ast_channel_name(in));
} }
/* now f is guaranteed non-NULL */ /* now f is guaranteed non-NULL */
@@ -1741,7 +1742,8 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
if (is_cc_recall) { if (is_cc_recall) {
ast_cc_completed(in, "CC completed, but the caller used DTMF to exit"); ast_cc_completed(in, "CC completed, but the caller used DTMF to exit");
} }
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "%s: Caller pressed %c to end call\n",
ast_channel_name(in), f->subclass.integer);
} }
ast_channel_unlock(in); ast_channel_unlock(in);
} }
@@ -1756,7 +1758,8 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in,
if (is_cc_recall) { if (is_cc_recall) {
ast_cc_completed(in, "CC completed, but the caller hung up with DTMF"); ast_cc_completed(in, "CC completed, but the caller hung up with DTMF");
} }
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "%s: Caller requested disconnect\n",
ast_channel_name(in));
} }
} }
@@ -1862,7 +1865,8 @@ skip_frame:;
if (is_cc_recall) { if (is_cc_recall) {
ast_cc_completed(in, "Recall completed!"); ast_cc_completed(in, "Recall completed!");
} }
return peer; SCOPE_EXIT_RTN_VALUE(peer, "%s: %s%s\n", ast_channel_name(in),
peer ? "Answered by " : "No answer", peer ? ast_channel_name(peer) : "");
} }
static int detect_disconnect(struct ast_channel *chan, char code, struct ast_str **featurecode) static int detect_disconnect(struct ast_channel *chan, char code, struct ast_str **featurecode)
@@ -2284,7 +2288,7 @@ static int dial_exec_full(struct ast_channel *chan, const char *data, struct ast
*/ */
struct ast_party_caller caller; struct ast_party_caller caller;
int max_forwards; int max_forwards;
SCOPE_TRACE(1, "%s Data: %s\n", ast_channel_name(chan), data); SCOPE_ENTER(1, "%s: Data: %s\n", ast_channel_name(chan), data);
/* Reset all DIAL variables back to blank, to prevent confusion (in case we don't reset all of them). */ /* Reset all DIAL variables back to blank, to prevent confusion (in case we don't reset all of them). */
ast_channel_lock(chan); ast_channel_lock(chan);
@@ -2308,7 +2312,7 @@ static int dial_exec_full(struct ast_channel *chan, const char *data, struct ast
ast_log(LOG_WARNING, "Cannot place outbound call from channel '%s'. Max forwards exceeded\n", ast_log(LOG_WARNING, "Cannot place outbound call from channel '%s'. Max forwards exceeded\n",
ast_channel_name(chan)); ast_channel_name(chan));
pbx_builtin_setvar_helper(chan, "DIALSTATUS", "BUSY"); pbx_builtin_setvar_helper(chan, "DIALSTATUS", "BUSY");
return -1; SCOPE_EXIT_RTN_VALUE(-1, "%s: Max forwards exceeded\n", ast_channel_name(chan));
} }
if (ast_check_hangup_locked(chan)) { if (ast_check_hangup_locked(chan)) {
@@ -2326,7 +2330,7 @@ static int dial_exec_full(struct ast_channel *chan, const char *data, struct ast
*/ */
ast_verb(3, "Caller hung up before dial.\n"); ast_verb(3, "Caller hung up before dial.\n");
pbx_builtin_setvar_helper(chan, "DIALSTATUS", "CANCEL"); pbx_builtin_setvar_helper(chan, "DIALSTATUS", "CANCEL");
return -1; SCOPE_EXIT_RTN_VALUE(-1, "%s: Caller hung up before dial\n", ast_channel_name(chan));
} }
parse = ast_strdupa(data ?: ""); parse = ast_strdupa(data ?: "");
@@ -3340,7 +3344,7 @@ done:
ast_free((char *)config.start_sound); ast_free((char *)config.start_sound);
} }
ast_ignore_cc(chan); ast_ignore_cc(chan);
return res; SCOPE_EXIT_RTN_VALUE(res, "%s: Done\n", ast_channel_name(chan));
} }
static int dial_exec(struct ast_channel *chan, const char *data) static int dial_exec(struct ast_channel *chan, const char *data)

86
include/asterisk/logger.h
View File

@@ -662,6 +662,7 @@ void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int li
* *
*/ */
#define ast_trace_raw(level, indent_type, ...) \ #define ast_trace_raw(level, indent_type, ...) \
ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(level)) { \ if (TRACE_ATLEAST(level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, indent_type, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, indent_type, 0, " " __VA_ARGS__); \
} }
@@ -676,6 +677,7 @@ void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int li
* This will print the file, line and function at the current indent level * This will print the file, line and function at the current indent level
*/ */
#define ast_trace(level, ...) \ #define ast_trace(level, ...) \
ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(level)) { \ if (TRACE_ATLEAST(level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_SAME, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_SAME, 0, " " __VA_ARGS__); \
} }
@@ -765,6 +767,7 @@ unsigned long _ast_trace_dec_indent(void);
#define SCOPE_ENTER(level, ...) \ #define SCOPE_ENTER(level, ...) \
int __scope_level = level; \ int __scope_level = level; \
int __scope_task = 0; \ int __scope_task = 0; \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(level)) { \ if (TRACE_ATLEAST(level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_INC_AFTER, 0, " " __VA_ARGS__); \
} \ } \
@@ -772,6 +775,7 @@ unsigned long _ast_trace_dec_indent(void);
#define SCOPE_ENTER_TASK(level, indent, ...) \ #define SCOPE_ENTER_TASK(level, indent, ...) \
int __scope_level = level; \ int __scope_level = level; \
int __scope_task = 1; \ int __scope_task = 1; \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(level)) { \ if (TRACE_ATLEAST(level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_PROVIDED, indent, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_PROVIDED, indent, " " __VA_ARGS__); \
} \ } \
@@ -786,6 +790,7 @@ unsigned long _ast_trace_dec_indent(void);
* This macro can be used at the exit points of a statement block since it just prints the message. * This macro can be used at the exit points of a statement block since it just prints the message.
*/ */
#define SCOPE_EXIT(...) \ #define SCOPE_EXIT(...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(__scope_level)) { \ if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \ if (__scope_task) { \
@@ -814,6 +819,7 @@ unsigned long _ast_trace_dec_indent(void);
* } * }
*/ */
#define SCOPE_EXIT_EXPR(__expr, ...) \ #define SCOPE_EXIT_EXPR(__expr, ...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(__scope_level)) { \ if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \ if (__scope_task) { \
@@ -833,6 +839,7 @@ unsigned long _ast_trace_dec_indent(void);
* needs to be returned. * needs to be returned.
*/ */
#define SCOPE_EXIT_RTN(...) \ #define SCOPE_EXIT_RTN(...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(__scope_level)) { \ if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \ if (__scope_task) { \
@@ -853,6 +860,7 @@ unsigned long _ast_trace_dec_indent(void);
* needs to be returned. * needs to be returned.
*/ */
#define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \ #define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \
ast_debug(__scope_level, " " __VA_ARGS__); \
if (TRACE_ATLEAST(__scope_level)) { \ if (TRACE_ATLEAST(__scope_level)) { \
__ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \
if (__scope_task) { \ if (__scope_task) { \
@@ -861,21 +869,79 @@ unsigned long _ast_trace_dec_indent(void);
} \ } \
return(__return_value) return(__return_value)
#else #else /* AST_DEVMODE */
#define ast_trace_raw(__level, __indent_type, ...) #define ast_trace_raw(level, indent_type, ...) \
#define ast_trace(__level, ...) 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_get_indent() (0)
#define ast_trace_set_indent(indent) #define ast_trace_set_indent(indent)
#define ast_trace_inc_indent() #define ast_trace_inc_indent()
#define ast_trace_dec_indent() #define ast_trace_dec_indent()
#define SCOPE_TRACE(__level, ...) #define SCOPE_TRACE(__level, ...)
#define SCOPE_ENTER(level, ...)
#define SCOPE_ENTER_TASK(level, indent, ...) #define SCOPE_ENTER(level, ...) \
#define SCOPE_EXIT(...) int __scope_level = level; \
#define SCOPE_EXIT_EXPR(__expr, ...) __expr ast_debug(level, " " __VA_ARGS__)
#define SCOPE_EXIT_RTN(...) return
#define SCOPE_EXIT_RTN_VALUE(__return_value, ...) return __return_value #define SCOPE_ENTER_TASK(level, indent, ...) \
#endif int __scope_level = level; \
ast_debug(level, " " __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__); \
})
#if defined(__cplusplus) || defined(c_plusplus) #if defined(__cplusplus) || defined(c_plusplus)
} }

10
main/stream.c
View File

@@ -542,6 +542,10 @@ struct ast_stream *ast_stream_create_resolved(struct ast_stream *pending_stream,
struct ast_stream *joint_stream; struct ast_stream *joint_stream;
enum ast_media_type media_type = pending_stream ? pending_stream->type : AST_MEDIA_TYPE_UNKNOWN; enum ast_media_type media_type = pending_stream ? pending_stream->type : AST_MEDIA_TYPE_UNKNOWN;
int res = 0; int res = 0;
SCOPE_ENTER(4, "Pending: %s Validation: %s Prefs: %s\n",
ast_str_tmp(128, ast_stream_to_str(pending_stream, &STR_TMP)),
ast_str_tmp(128, ast_stream_to_str(validation_stream, &STR_TMP)),
ast_str_tmp(128, ast_stream_codec_prefs_to_str(prefs, &STR_TMP)));
if (!pending_stream || !validation_stream || !prefs || !joint_caps if (!pending_stream || !validation_stream || !prefs || !joint_caps
|| media_type == AST_MEDIA_TYPE_UNKNOWN) { || media_type == AST_MEDIA_TYPE_UNKNOWN) {
@@ -549,7 +553,7 @@ struct ast_stream *ast_stream_create_resolved(struct ast_stream *pending_stream,
ast_str_append(error_message, 0, "Invalid arguments"); ast_str_append(error_message, 0, "Invalid arguments");
} }
ao2_cleanup(joint_caps); ao2_cleanup(joint_caps);
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "Invalid arguments\n");
} }
if (prefs->prefer == CODEC_NEGOTIATION_PREFER_PENDING) { if (prefs->prefer == CODEC_NEGOTIATION_PREFER_PENDING) {
@@ -593,7 +597,7 @@ struct ast_stream *ast_stream_create_resolved(struct ast_stream *pending_stream,
} }
ao2_cleanup(joint_caps); ao2_cleanup(joint_caps);
return NULL; SCOPE_EXIT_RTN_VALUE(NULL, "No common formats available\n");
} }
if (!ast_format_cap_empty(joint_caps)) { if (!ast_format_cap_empty(joint_caps)) {
@@ -641,7 +645,7 @@ struct ast_stream *ast_stream_create_resolved(struct ast_stream *pending_stream,
} }
ao2_cleanup(joint_caps); ao2_cleanup(joint_caps);
return joint_stream; SCOPE_EXIT_RTN_VALUE(joint_stream, "Joint stream: %s\n", ast_str_tmp(128, ast_stream_to_str(joint_stream, &STR_TMP)));
} }
static void stream_topology_destroy(void *data) static void stream_topology_destroy(void *data)