[Asterisk-code-review] scope_trace: Added debug messages and added additional macros (asterisk[master])

Friendly Automation asteriskteam at digium.com
Tue Aug 25 09:23:08 CDT 2020


Friendly Automation has submitted this change. ( https://gerrit.asterisk.org/c/asterisk/+/14783 )

Change subject: scope_trace: Added debug messages and added additional macros
......................................................................

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
---
M apps/app_dial.c
M include/asterisk/logger.h
M main/stream.c
3 files changed, 100 insertions(+), 26 deletions(-)

Approvals:
  Joshua Colp: Looks good to me, but someone else must approve
  George Joseph: Looks good to me, approved
  Friendly Automation: Approved for Submit



diff --git a/apps/app_dial.c b/apps/app_dial.c
index 9e11487..e384b6d 100644
--- a/apps/app_dial.c
+++ b/apps/app_dial.c
@@ -1224,7 +1224,7 @@
 	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 @@
 				*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 @@
 			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 @@
 				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 @@
 							 * 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 @@
 				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 @@
 						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 @@
 					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 @@
 	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 @@
 	 */
 	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 @@
 		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 @@
 		 */
 		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 @@
 		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 5514d83..72c938d 100644
--- a/include/asterisk/logger.h
+++ b/include/asterisk/logger.h
@@ -662,6 +662,7 @@
  *
  */
 #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 @@
  *  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 @@
 #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 @@
 #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 @@
  * 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 @@
  * }
  */
 #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 @@
  * 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 @@
  * 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 @@
 	} \
 	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 c97ae48..859018d 100644
--- a/main/stream.c
+++ b/main/stream.c
@@ -542,6 +542,10 @@
 	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 @@
 			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 @@
 		}
 
 		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 @@
 	}
 
 	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)

-- 
To view, visit https://gerrit.asterisk.org/c/asterisk/+/14783
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings

Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Change-Id: I7fe55f7ec28069919a0fc0b11a82235ce904cc21
Gerrit-Change-Number: 14783
Gerrit-PatchSet: 4
Gerrit-Owner: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Benjamin Keith Ford <bford at digium.com>
Gerrit-Reviewer: Friendly Automation
Gerrit-Reviewer: George Joseph <gjoseph at digium.com>
Gerrit-Reviewer: Joshua Colp <jcolp at sangoma.com>
Gerrit-MessageType: merged
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-code-review/attachments/20200825/ca548fc6/attachment-0001.html>


More information about the asterisk-code-review mailing list