From: George Joseph Date: Wed, 19 Aug 2020 12:37:23 +0000 (-0600) Subject: scope_trace: Added debug messages and added additional macros X-Git-Tag: 19.0.0-rc1~344 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=64ca2d48da4df64eb25004a997e0868cda41c3ac;p=thirdparty%2Fasterisk.git scope_trace: Added debug messages and added additional macros 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 --- diff --git a/apps/app_dial.c b/apps/app_dial.c index 9e1148753c..e384b6da97 100644 --- a/apps/app_dial.c +++ b/apps/app_dial.c @@ -1224,7 +1224,7 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in, int sent_ring = 0; int sent_progress = 0; 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) { /* Turn off hold music, etc */ @@ -1240,7 +1240,8 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in, *to = -1; strcpy(pa->status, "CONGESTION"); 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) { 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); 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: /* This is our guy if someone answered. */ 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)); if (o->orig_chan_name && 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. */ 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_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) { 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 */ @@ -1741,7 +1742,8 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in, if (is_cc_recall) { 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); } @@ -1756,7 +1758,8 @@ static struct ast_channel *wait_for_answer(struct ast_channel *in, if (is_cc_recall) { 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) { 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) @@ -2284,7 +2288,7 @@ static int dial_exec_full(struct ast_channel *chan, const char *data, struct ast */ struct ast_party_caller caller; 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). */ 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_channel_name(chan)); 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)) { @@ -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"); 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 ?: ""); @@ -3340,7 +3344,7 @@ done: ast_free((char *)config.start_sound); } 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) diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h index 5514d8347c..72c938d3de 100644 --- a/include/asterisk/logger.h +++ b/include/asterisk/logger.h @@ -662,6 +662,7 @@ void __attribute__((format (printf, 6, 7))) __ast_trace(const char *file, int li * */ #define ast_trace_raw(level, indent_type, ...) \ + ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level)) { \ __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 */ #define ast_trace(level, ...) \ + ast_debug(level < 0 ? __scope_level : level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level)) { \ __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, ...) \ int __scope_level = level; \ int __scope_task = 0; \ + ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level)) { \ __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, ...) \ int __scope_level = level; \ int __scope_task = 1; \ + ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(level)) { \ __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. */ #define SCOPE_EXIT(...) \ + ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ @@ -814,6 +819,7 @@ unsigned long _ast_trace_dec_indent(void); * } */ #define SCOPE_EXIT_EXPR(__expr, ...) \ + ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ @@ -833,6 +839,7 @@ unsigned long _ast_trace_dec_indent(void); * needs to be returned. */ #define SCOPE_EXIT_RTN(...) \ + ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ @@ -853,6 +860,7 @@ unsigned long _ast_trace_dec_indent(void); * needs to be returned. */ #define SCOPE_EXIT_RTN_VALUE(__return_value, ...) \ + ast_debug(__scope_level, " " __VA_ARGS__); \ if (TRACE_ATLEAST(__scope_level)) { \ __ast_trace(__FILE__, __LINE__, __PRETTY_FUNCTION__, AST_TRACE_INDENT_DEC_BEFORE, 0, " " __VA_ARGS__); \ if (__scope_task) { \ @@ -861,21 +869,79 @@ unsigned long _ast_trace_dec_indent(void); } \ return(__return_value) -#else -#define ast_trace_raw(__level, __indent_type, ...) -#define ast_trace(__level, ...) +#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() #define SCOPE_TRACE(__level, ...) -#define SCOPE_ENTER(level, ...) -#define SCOPE_ENTER_TASK(level, indent, ...) -#define SCOPE_EXIT(...) -#define SCOPE_EXIT_EXPR(__expr, ...) __expr -#define SCOPE_EXIT_RTN(...) return -#define SCOPE_EXIT_RTN_VALUE(__return_value, ...) return __return_value -#endif + +#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_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) } diff --git a/main/stream.c b/main/stream.c index c97ae484c8..859018d5ff 100644 --- a/main/stream.c +++ b/main/stream.c @@ -542,6 +542,10 @@ struct ast_stream *ast_stream_create_resolved(struct ast_stream *pending_stream, struct ast_stream *joint_stream; enum ast_media_type media_type = pending_stream ? pending_stream->type : AST_MEDIA_TYPE_UNKNOWN; 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 || 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"); } ao2_cleanup(joint_caps); - return NULL; + SCOPE_EXIT_RTN_VALUE(NULL, "Invalid arguments\n"); } 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); - return NULL; + SCOPE_EXIT_RTN_VALUE(NULL, "No common formats available\n"); } 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); - 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)