[Asterisk-code-review] Logging: Add debug logging categories (asterisk[master])
George Joseph
asteriskteam at digium.com
Fri Oct 2 12:58:20 CDT 2020
George Joseph has submitted this change. ( https://gerrit.asterisk.org/c/asterisk/+/14887 )
Change subject: Logging: Add debug logging categories
......................................................................
Logging: Add debug logging categories
Added debug logging categories that allow a user to output debug
information based on a specified category. This lets the user limit,
and filter debug output to data relevant to a particular context,
or topic. For instance the following categories are now available for
debug logging purposes:
dtls, dtls_packet, ice, rtcp, rtcp_packet, rtp, rtp_packet,
stun, stun_packet
These debug categories can be enable/disable via an Asterisk CLI command.
While this overrides, and outputs debug data, core system debugging is
not affected by this patch. Statements still output at their appropriate
debug level. As well backwards compatibility has been maintained with
past debug groups that could be enabled using the CLI (e.g. rtpdebug,
stundebug, etc.).
ASTERISK-29054 #close
Change-Id: I6e6cb247bb1f01dbf34750b2cd98e5b5b41a1849
---
A doc/CHANGES-staging/logger_category.txt
A include/asterisk/logger_category.h
M include/asterisk/rtp_engine.h
M include/asterisk/stun.h
M main/cli.c
M main/logger.c
A main/logger_category.c
M main/rtp_engine.c
M main/stun.c
M res/res_pjsip_sdp_rtp.c
M res/res_rtp_asterisk.c
11 files changed, 1,035 insertions(+), 200 deletions(-)
Approvals:
Joshua Colp: Looks good to me, but someone else must approve
George Joseph: Looks good to me, approved; Approved for Submit
diff --git a/doc/CHANGES-staging/logger_category.txt b/doc/CHANGES-staging/logger_category.txt
new file mode 100644
index 0000000..67cc3ec
--- /dev/null
+++ b/doc/CHANGES-staging/logger_category.txt
@@ -0,0 +1,18 @@
+Subject: Core
+
+Added debug logging categories that allow a user to output debug information
+based on a specified category. This lets the user limit, and filter debug
+output to data relevant to a particular context, or topic. For instance the
+following categories are now available for debug logging purposes:
+
+ dtls, dtls_packet, ice, rtcp, rtcp_packet, rtp, rtp_packet, stun, stun_packet
+
+These debug categories can be enable/disable via an Asterisk CLI command:
+
+ core set debug category <category>[:<sublevel>] [category[:<sublevel] ...]
+ core set debug category off [<category> [<category>] ...]
+
+If no sub-level is associated all debug statements for a given category are
+output. If a sub-level is given then only those statements assigned a value
+at or below the associated sub-level are output.
+
diff --git a/include/asterisk/logger_category.h b/include/asterisk/logger_category.h
new file mode 100644
index 0000000..ff994cc
--- /dev/null
+++ b/include/asterisk/logger_category.h
@@ -0,0 +1,178 @@
+/*
+ * Asterisk -- An open source telephony toolkit.
+ *
+ * Copyright (C) 2020, Sangoma Technologies Corporation
+ *
+ * Kevin Harwell <kharwell at sangoma.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.
+ */
+#ifndef ASTERISK_LOGGER_CATEGORY_H
+#define ASTERISK_LOGGER_CATEGORY_H
+
+#include "asterisk/logger.h"
+
+/*!
+ * Logger category is enabled
+ */
+#define AST_LOG_CATEGORY_ENABLED -1
+
+/*!
+ * Logger category is disabled
+ */
+#define AST_LOG_CATEGORY_DISABLED 0
+
+/*!
+ * \brief Load/Initialize system wide logger category functionality
+ *
+ * \retval 0 Success, -1 Failure
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+int ast_logger_category_load(void);
+
+/*!
+ * \brief Unload system wide logger category functionality
+ *
+ * \retval 0 Success, -1 Failure
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+int ast_logger_category_unload(void);
+
+/*!
+ * \brief Register a debug level logger category
+ *
+ * \param name The name of the category
+ * \param id The unique id of the category
+ *
+ * \retval 0 if failed to register/retrieve an id. Otherwise it returns the id
+ * for the registered category.
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+uintmax_t ast_debug_category_register(const char *name);
+
+/*!
+ * \brief Un-register a debug level logger category
+ *
+ * \retval 0 Success, -1 Failure
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+int ast_debug_category_unregister(const char *name);
+
+/*!
+ * \brief Set the debug category's sublevel
+ *
+ * Statements are output at a specified sublevel. Typically any number greater
+ * than or equal to 0. Other acceptable values include AST_LOG_CATEGORY_ENABLED
+ * and AST_LOG_CATEGORY_DISABLED.
+ *
+ * \param name The name of the category
+ * \param sublevel The debug sublevel output number
+ *
+ * \retval 0 Success, -1 Failure
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+int ast_debug_category_set_sublevel(const char *name, int sublevel);
+
+/*!
+ * \brief Set one or more debug category's sublevel.
+ *
+ * Accepts an array of category names, and optional associated sublevels. Sublevels can
+ * be associated with a name by using a ':' as a separator. For example:
+ *
+ * <category name>:<category sublevel>
+ *
+ * The given default sublevel is used if no sublevel is associated with a name.
+ *
+ * \param names An array of category names
+ * \param size The size of the array (number of elements)
+ * \param default_sublevel The sublevel value to use if one is not associated with a name
+ *
+ * \retval 0 Success, -1 Failure
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+int ast_debug_category_set_sublevels(const char * const *names, size_t size, int default_sublevel);
+
+/*!
+ * \brief Add a unique (no duplicates) result to a request for completion for debug categories.
+ *
+ * \param argv A list of already completed options
+ * \param argc The number of already completed options
+ * \param word The word to complete
+ * \param state The state
+ *
+ * \retval 0 Success, -1 Failure
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+char *ast_debug_category_complete(const char * const *argv, int argc, const char *word, int state);
+
+/*!
+ * \brief Check if a debug category is enabled, and allowed to output
+ *
+ * \note If more than one id is specified then if even one is allowed "true"
+ * is returned.
+ *
+ * \param sublevel Current set sublevel must be this sublevel or less
+ * \param ids One or more unique category ids to check
+ *
+ * \retval 1 if allowed, 0 if not allowed
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+*/
+int ast_debug_category_is_allowed(int sublevel, uintmax_t ids);
+
+/*!
+ * \brief Log for a debug category.
+ *
+ * This will output log data for debug under the following conditions:
+ *
+ * 1. The specified sublevel is at, or below the current system debug level
+ * 2. At least one of the given category ids is enabled AND
+ * a. The category sublevel is enabled OR the given sublevel is at, or
+ * below a category's specified sublevel.
+ *
+ * \param sublevel The minimum level to output at
+ * \param ids One or more unique category ids to output for
+ *
+ * \since 16.14
+ * \since 17.8
+ * \since 18.0
+ */
+#define ast_debug_category(sublevel, ids, ...) \
+ do { \
+ if (DEBUG_ATLEAST(sublevel) || ast_debug_category_is_allowed(sublevel, ids)) { \
+ ast_log(AST_LOG_DEBUG, __VA_ARGS__); \
+ } \
+ } while (0)
+
+#endif /* ASTERISK_LOGGER_CATEGORY_H */
diff --git a/include/asterisk/rtp_engine.h b/include/asterisk/rtp_engine.h
index 758fad7..0584f2c 100644
--- a/include/asterisk/rtp_engine.h
+++ b/include/asterisk/rtp_engine.h
@@ -77,6 +77,7 @@
#include "asterisk/res_srtp.h"
#include "asterisk/stasis.h"
#include "asterisk/vector.h"
+#include "asterisk/logger_category.h"
/*! Maximum number of payload types RTP can support. */
#define AST_RTP_MAX_PT 128
@@ -2819,6 +2820,84 @@
*/
struct stasis_topic *ast_rtp_topic(void);
+/* RTP debug logging category name */
+#define AST_LOG_CATEGORY_RTP "rtp"
+/* RTP packet debug logging category name */
+#define AST_LOG_CATEGORY_RTP_PACKET "rtp_packet"
+/* RTCP debug logging category name */
+#define AST_LOG_CATEGORY_RTCP "rtcp"
+/* RTCP packet debug logging category name */
+#define AST_LOG_CATEGORY_RTCP_PACKET "rtcp_packet"
+/* DTLS debug logging category name */
+#define AST_LOG_CATEGORY_DTLS "dtls"
+/* DTLS packet debug logging category name */
+#define AST_LOG_CATEGORY_DTLS_PACKET "dtls_packet"
+/* ICE debug logging category name */
+#define AST_LOG_CATEGORY_ICE "ice"
+
+uintmax_t ast_debug_category_rtp_id(void);
+uintmax_t ast_debug_category_rtp_packet_id(void);
+uintmax_t ast_debug_category_rtcp_id(void);
+uintmax_t ast_debug_category_rtcp_packet_id(void);
+uintmax_t ast_debug_category_dtls_id(void);
+uintmax_t ast_debug_category_dtls_packet_id(void);
+uintmax_t ast_debug_category_ice_id(void);
+
+#define AST_DEBUG_CATEGORY_RTP ast_debug_category_rtp_id() /* RTP debug logging category id */
+#define AST_DEBUG_CATEGORY_RTP_PACKET ast_debug_category_rtp_packet_id() /* RTP packet debug logging category id */
+#define AST_DEBUG_CATEGORY_RTCP ast_debug_category_rtcp_id() /* RTCP debug logging category id */
+#define AST_DEBUG_CATEGORY_RTCP_PACKET ast_debug_category_rtcp_packet_id() /* RTCP packet debug logging category id */
+#define AST_DEBUG_CATEGORY_DTLS ast_debug_category_dtls_id() /* DTLS debug logging category id */
+#define AST_DEBUG_CATEGORY_DTLS_PACKET ast_debug_category_dtls_packet_id() /* DTLS packet debug logging category id */
+#define AST_DEBUG_CATEGORY_ICE ast_debug_category_ice_id() /* ICE debug logging category id */
+
+/*!
+ * \brief Log debug level RTP information
+ *
+ * \param sublevel Debug output sublevel (>= 0)
+ * \param ... String format and any associated arguments
+ */
+#define ast_debug_rtp(sublevel, ...) \
+ ast_debug_category(sublevel, AST_DEBUG_CATEGORY_RTP, __VA_ARGS__)
+
+/* Allow logging of RTP packets? */
+#define ast_debug_rtp_packet_is_allowed \
+ ast_debug_category_is_allowed(AST_LOG_CATEGORY_ENABLED, AST_DEBUG_CATEGORY_RTP_PACKET)
+
+/*!
+ * \brief Log debug level RTCP information
+ *
+ * \param sublevel Debug output sublevel (>= 0)
+ * \param ... String format and any associated arguments
+ */
+#define ast_debug_rtcp(sublevel, ...) \
+ ast_debug_category(sublevel, AST_DEBUG_CATEGORY_RTCP, __VA_ARGS__)
+
+/* Allow logging of RTCP packets? */
+#define ast_debug_rtcp_packet_is_allowed \
+ ast_debug_category_is_allowed(AST_LOG_CATEGORY_ENABLED, AST_DEBUG_CATEGORY_RTCP_PACKET)
+
+/*!
+ * \brief Log debug level DTLS information
+ *
+ * \param sublevel Debug output sublevel (>= 0)
+ * \param ... String format and any associated arguments
+ */
+#define ast_debug_dtls(sublevel, ...) \
+ ast_debug_category(sublevel, AST_DEBUG_CATEGORY_DTLS, __VA_ARGS__)
+
+/* Allow logging of DTLS packets? */
+#define ast_debug_dtls_packet_is_allowed \
+ ast_debug_category_is_allowed(AST_LOG_CATEGORY_ENABLED, AST_DEBUG_CATEGORY_DTLS_PACKET)
+/*!
+ * \brief Log debug level ICE information
+ *
+ * \param sublevel Debug output sublevel (>= 0)
+ * \param ... String format and any associated arguments
+ */
+#define ast_debug_ice(sublevel, ...) \
+ ast_debug_category(sublevel, AST_DEBUG_CATEGORY_ICE, __VA_ARGS__)
+
/* @} */
#if defined(__cplusplus) || defined(c_plusplus)
diff --git a/include/asterisk/stun.h b/include/asterisk/stun.h
index f0f9d0e..90c6ecc 100644
--- a/include/asterisk/stun.h
+++ b/include/asterisk/stun.h
@@ -27,11 +27,36 @@
#define _ASTERISK_STUN_H
#include "asterisk/network.h"
+#include "asterisk/logger_category.h"
#if defined(__cplusplus) || defined(c_plusplus)
extern "C" {
#endif
+/* STUN debug logging category name */
+#define AST_LOG_CATEGORY_STUN "stun"
+/* STUN packet debug logging category name */
+#define AST_LOG_CATEGORY_STUN_PACKET "stun_packet"
+
+uintmax_t ast_debug_category_stun_id(void);
+uintmax_t ast_debug_category_stun_packet_id(void);
+
+#define AST_DEBUG_CATEGORY_STUN ast_debug_category_stun_id() /* STUN debug logging category id */
+#define AST_DEBUG_CATEGORY_STUN_PACKET ast_debug_category_stun_packet_id() /* STUN packet debug logging category id */
+
+/*!
+ * \brief Log debug level STUN information
+ *
+ * \param sublevel Debug output sublevel (>= 0)
+ * \param ... String format and any associated arguments
+ */
+#define ast_debug_stun(sublevel, ...) \
+ ast_debug_category(sublevel, AST_DEBUG_CATEGORY_STUN, __VA_ARGS__)
+
+/* Is logging of stun packets allowed? */
+#define ast_debug_stun_packet_is_allowed \
+ ast_debug_category_is_allowed(AST_LOG_CATEGORY_ENABLED, AST_DEBUG_CATEGORY_STUN_PACKET)
+
static const int STANDARD_STUN_PORT = 3478;
enum ast_stun_result {
diff --git a/main/cli.c b/main/cli.c
index 3cb42f2..dc13019 100644
--- a/main/cli.c
+++ b/main/cli.c
@@ -55,6 +55,7 @@
#include "asterisk/app.h"
#include "asterisk/lock.h"
#include "asterisk/threadstorage.h"
+#include "asterisk/logger_category.h"
#include "asterisk/translate.h"
#include "asterisk/bridge.h"
#include "asterisk/stasis_channels.h"
@@ -478,9 +479,11 @@
if (!strcasecmp(a->argv[e->args], "atleast")) {
atleast = 1;
}
+
if (a->argc != e->args + atleast + 1 && a->argc != e->args + atleast + 2) {
return CLI_SHOWUSAGE;
}
+
if (sscanf(a->argv[e->args + atleast], "%30d", &newlevel) != 1) {
return CLI_SHOWUSAGE;
}
@@ -585,6 +588,10 @@
return NULL;
case CLI_GENERATE:
+ if (!strcasecmp(argv3, "category")) {
+ return NULL;
+ }
+
if (!strcasecmp(argv3, "atleast")) {
atleast = 1;
}
@@ -618,7 +625,6 @@
*/
return handle_debug_or_trace(DEBUG_HANDLER, e, cmd, a);
-
}
static char *handle_trace(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
@@ -1533,6 +1539,47 @@
return CLI_SUCCESS;
}
+static char *handle_debug_category(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
+{
+ const char *argv4 = a->argv ? S_OR(a->argv[4], "") : "";
+ int offset = strncasecmp(argv4, "off", strlen(argv4)) ? 0 : 1;
+
+ switch (cmd) {
+ case CLI_INIT:
+ e->command = "core set debug category";
+ e->usage =
+ "Usage: core set debug category <category>[:<sublevel>] [category[:<sublevel] ...]\n"
+ " core set debug category off [<category> [<category>] ...]\n\n"
+ " Allows enabling and disabling debug logging categories.\n"
+ " When a category is enabled all relevant debug messages are logged\n"
+ " for a given category. However, if a sublevel is specified only\n"
+ " those categorized messages at or below the coded debug sublevel\n"
+ " are logged.\n";
+ return NULL;
+
+ case CLI_GENERATE:
+ if (a->pos < e->args) {
+ return NULL;
+ }
+
+ if (a->pos == 4 && offset) {
+ ast_cli_completion_add(ast_strdup("off"));
+ }
+
+ return ast_debug_category_complete(a->argv + 4,
+ a->pos - e->args, a->word, a->n - 1);
+ }
+
+ if (a->argc <= e->args) {
+ return CLI_SHOWUSAGE;
+ }
+
+ ast_debug_category_set_sublevels(a->argv + e->args + offset, a->argc - e->args - offset,
+ offset ? AST_LOG_CATEGORY_DISABLED : AST_LOG_CATEGORY_ENABLED);
+
+ return CLI_SUCCESS;
+}
+
static char *handle_nodebugchan_deprecated(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
char *res;
@@ -1947,6 +1994,8 @@
AST_CLI_DEFINE(handle_core_set_debug_channel, "Enable/disable debugging on a channel"),
+ AST_CLI_DEFINE(handle_debug_category, "Enable/disable debugging categories"),
+
AST_CLI_DEFINE(handle_debug, "Set level of debug chattiness"),
AST_CLI_DEFINE(handle_trace, "Set level of trace chattiness"),
AST_CLI_DEFINE(handle_verbose, "Set level of verbose chattiness"),
diff --git a/main/logger.c b/main/logger.c
index d7d1807..067f9a9 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -52,6 +52,7 @@
#include "asterisk/module.h"
#include "asterisk/paths.h" /* use ast_config_AST_LOG_DIR */
#include "asterisk/logger.h"
+#include "asterisk/logger_category.h"
#include "asterisk/lock.h"
#include "asterisk/channel.h"
#include "asterisk/config.h"
@@ -1868,6 +1869,8 @@
ast_log(LOG_ERROR, "Errors detected in logger.conf. Default console logging is being used.\n");
}
+ ast_logger_category_load();
+
return 0;
}
@@ -1875,6 +1878,8 @@
{
struct logchannel *f = NULL;
+ ast_logger_category_unload();
+
ast_cli_unregister_multiple(cli_logger, ARRAY_LEN(cli_logger));
logger_initialized = 0;
diff --git a/main/logger_category.c b/main/logger_category.c
new file mode 100644
index 0000000..7d9242c
--- /dev/null
+++ b/main/logger_category.c
@@ -0,0 +1,324 @@
+/*
+ * Asterisk -- An open source telephony toolkit.
+ *
+ * Copyright (C) 2020, Sangoma Technologies Corporation
+ *
+ * Kevin Harwell <kharwell at sangoma.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.
+ */
+
+#include "asterisk.h"
+
+#include "asterisk/cli.h"
+#include "asterisk/conversions.h"
+#include "asterisk/logger_category.h"
+#include "asterisk/vector.h"
+
+struct category_t {
+ int sublevel;
+ uintmax_t id;
+ char name[0];
+};
+
+AST_VECTOR_RW(categories_t, struct category_t *);
+
+struct categories_level_t {
+ int type;
+ int sublevel;
+ uintmax_t id_pool;
+ uintmax_t state;
+ struct categories_t categories;
+};
+
+/*! \brief Retrieve the next available id.
+ *
+ * Ids must be a power of 2. This allows for fast lookup, and "or'ing" of ids
+ * in order to permit multiple categories in a log statement.
+ */
+static uintmax_t get_next_id(struct categories_level_t *level)
+{
+ if (level->id_pool == 0) {
+ level->id_pool = 1;
+ } else if (level->id_pool >= (UINTMAX_MAX / 2)) {
+ /* No more ids left*/
+ return 0;
+ } else {
+ level->id_pool <<= 1;
+ }
+
+ return level->id_pool;
+}
+
+static int cmp_by_name(const struct category_t *category, const char *name)
+{
+ return !strcmp(category->name, name);
+}
+
+static uintmax_t category_register(struct categories_level_t *level, const char *name)
+{
+ int i;
+ struct category_t *category;
+
+ AST_VECTOR_RW_WRLOCK(&level->categories);
+
+ i = AST_VECTOR_GET_INDEX(&level->categories, name, cmp_by_name);
+ if (i >= 0) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ ast_log(LOG_ERROR, "Cannot register logger category '%s'. "
+ "Name already used for type.\n", name);
+ return 0;
+ }
+
+ category = ast_calloc(1, sizeof(*category) + strlen(name) + 1);
+ if (!category) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return 0;
+ }
+
+ category->id = get_next_id(level);
+ category->sublevel = AST_LOG_CATEGORY_DISABLED;
+ strcpy(category->name, name); /* Safe */
+
+ if (AST_VECTOR_APPEND(&level->categories, category)) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ ast_log(LOG_ERROR, "Cannot register logger category '%s'. "
+ "Unable to append.\n", name);
+ return 0;
+ }
+
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return category->id;
+}
+
+static int category_unregister(struct categories_level_t *level, const char *name)
+{
+ int res;
+
+ AST_VECTOR_RW_WRLOCK(&level->categories);
+ res = AST_VECTOR_REMOVE_CMP_UNORDERED(&level->categories, name, cmp_by_name, ast_free);
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+
+ return res;
+}
+
+static int casecmp_by_name(const struct category_t *category, const char *name)
+{
+ return !strcasecmp(category->name, name);
+}
+
+static int category_set_sublevel(struct category_t *category, struct categories_level_t *level,
+ const char *name, int sublevel)
+{
+ int locked = 0;
+
+ if (!category) {
+ struct category_t **obj;
+
+ if (!name) {
+ return -1;
+ }
+
+ locked = !AST_VECTOR_RW_WRLOCK(&level->categories);
+ if (!locked) {
+ return -1;
+ }
+
+ obj = AST_VECTOR_GET_CMP(&level->categories, name, casecmp_by_name);
+ if (!obj) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return -1;
+ }
+
+ category = *obj;
+ }
+
+ category->sublevel = sublevel;
+
+ if (category->sublevel == AST_LOG_CATEGORY_DISABLED) {
+ level->state &= ~category->id;
+ } else {
+ level->state |= category->id;
+ }
+
+ if (locked) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ }
+
+ return 0;
+}
+
+static int category_set_sublevels(struct categories_level_t *level,
+ const char * const *names, size_t size, int default_sublevel)
+{
+ int i;
+
+ if (!names || !size) {
+ level->state = default_sublevel;
+ AST_VECTOR_RW_WRLOCK(&level->categories);
+ AST_VECTOR_CALLBACK_VOID(&level->categories, category_set_sublevel,
+ level, NULL, default_sublevel);
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return 0;
+ }
+
+ for (i = 0; i < size; ++i) {
+ const char *sublevel;
+ int num = default_sublevel;
+
+ sublevel = strchr(names[i], ':');
+ if (sublevel) {
+ size_t len = ++sublevel - names[i];
+ char name[len];
+
+ if (*sublevel && ast_str_to_int(sublevel, &num)) {
+ continue;
+ }
+
+ ast_copy_string(name, names[i], len);
+ category_set_sublevel(NULL, level, name, num);
+ } else {
+ category_set_sublevel(NULL, level, names[i], num);
+ }
+ }
+
+ return 0;
+}
+
+static char *category_complete(struct categories_level_t *level, const char * const *argv,
+ int argc, const char *word, int state)
+{
+ int wordlen = strlen(word);
+ int which = 0;
+ int i, j;
+
+ AST_VECTOR_RW_RDLOCK(&level->categories);
+
+ if (argc == AST_VECTOR_SIZE(&level->categories)) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return NULL;
+ }
+
+ for (i = 0; i < AST_VECTOR_SIZE(&level->categories); ++i) {
+ struct category_t *category = AST_VECTOR_GET(&level->categories, i);
+
+ if (!strncasecmp(word, category->name, wordlen) && (++which > state)) {
+ /* Check to see if one is already been included */
+ for (j = 0; j < argc; ++j) {
+ if (!strncasecmp(category->name, argv[j], strlen(category->name))) {
+ break;
+ }
+ }
+
+ if (j != argc) {
+ continue;
+ }
+
+ if (state != -1) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return ast_strdup(category->name);
+ }
+
+ if (ast_cli_completion_add(ast_strdup(category->name))) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return NULL;
+ }
+ }
+ }
+
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return NULL;
+}
+
+static int category_is_allowed(int sublevel, struct categories_level_t *level, uintmax_t ids)
+{
+ /* Check level, and potentially allow but only if there is a matching state enabled */
+ if (ids & level->state) {
+ int i;
+
+ if (sublevel == AST_LOG_CATEGORY_ENABLED || sublevel == 0) {
+ /* If at least one id is enabled then always allow these sublevels */
+ return 1;
+ }
+
+ AST_VECTOR_RW_RDLOCK(&level->categories);
+ for (i = 0; i < AST_VECTOR_SIZE(&level->categories); ++i) {
+ struct category_t *category = AST_VECTOR_GET(&level->categories, i);
+
+ /*
+ * If there is at least one matching category, and that category is enabled
+ * or its sub-level is at or above the given sub-level then allow.
+ */
+ if ((category->id & ids) && category->sublevel != AST_LOG_CATEGORY_DISABLED &&
+ (category->sublevel == AST_LOG_CATEGORY_ENABLED || category->sublevel >= sublevel)) {
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ return 1;
+ }
+ }
+ AST_VECTOR_RW_UNLOCK(&level->categories);
+ }
+
+ return 0;
+}
+
+static struct categories_level_t debug_categories = {
+ .type = __LOG_DEBUG,
+ .sublevel = 0,
+ .id_pool = 0,
+ .state = 0,
+};
+
+uintmax_t ast_debug_category_register(const char *name)
+{
+ return category_register(&debug_categories, name);
+}
+
+int ast_debug_category_unregister(const char *name)
+{
+ return category_unregister(&debug_categories, name);
+}
+
+int ast_debug_category_set_sublevel(const char *name, int sublevel)
+{
+ return category_set_sublevel(NULL, &debug_categories, name, sublevel);
+}
+
+int ast_debug_category_set_sublevels(const char * const *names,
+ size_t size, int default_sublevel)
+{
+ return category_set_sublevels(&debug_categories, names, size, default_sublevel);
+}
+
+char *ast_debug_category_complete(const char * const *argv, int argc,
+ const char *word, int state)
+{
+ return category_complete(&debug_categories, argv, argc, word, state);
+}
+
+int ast_debug_category_is_allowed(int sublevel, uintmax_t ids)
+{
+ return category_is_allowed(sublevel, &debug_categories, ids);
+}
+
+int ast_logger_category_unload(void)
+{
+ AST_VECTOR_RW_FREE(&debug_categories.categories);
+ return 0;
+}
+
+int ast_logger_category_load(void)
+{
+ if (AST_VECTOR_RW_INIT(&debug_categories.categories, 10)) {
+ return -1;
+ }
+
+ return 0;
+}
diff --git a/main/rtp_engine.c b/main/rtp_engine.c
index 95510d8..f88b877 100644
--- a/main/rtp_engine.c
+++ b/main/rtp_engine.c
@@ -3533,6 +3533,55 @@
return rtp_topic;
}
+static uintmax_t debug_category_rtp_id;
+
+uintmax_t ast_debug_category_rtp_id(void)
+{
+ return debug_category_rtp_id;
+}
+
+static uintmax_t debug_category_rtp_packet_id;
+
+uintmax_t ast_debug_category_rtp_packet_id(void)
+{
+ return debug_category_rtp_packet_id;
+}
+
+static uintmax_t debug_category_rtcp_id;
+
+uintmax_t ast_debug_category_rtcp_id(void)
+{
+ return debug_category_rtcp_id;
+}
+
+static uintmax_t debug_category_rtcp_packet_id;
+
+uintmax_t ast_debug_category_rtcp_packet_id(void)
+{
+ return debug_category_rtcp_packet_id;
+}
+
+static uintmax_t debug_category_dtls_id;
+
+uintmax_t ast_debug_category_dtls_id(void)
+{
+ return debug_category_dtls_id;
+}
+
+static uintmax_t debug_category_dtls_packet_id;
+
+uintmax_t ast_debug_category_dtls_packet_id(void)
+{
+ return debug_category_dtls_packet_id;
+}
+
+static uintmax_t debug_category_ice_id;
+
+uintmax_t ast_debug_category_ice_id(void)
+{
+ return debug_category_ice_id;
+}
+
static void rtp_engine_shutdown(void)
{
int x;
@@ -3557,6 +3606,17 @@
}
mime_types_len = 0;
ast_rwlock_unlock(&mime_types_lock);
+
+ ast_debug_category_unregister(AST_LOG_CATEGORY_ICE);
+
+ ast_debug_category_unregister(AST_LOG_CATEGORY_DTLS_PACKET);
+ ast_debug_category_unregister(AST_LOG_CATEGORY_DTLS);
+
+ ast_debug_category_unregister(AST_LOG_CATEGORY_RTCP_PACKET);
+ ast_debug_category_unregister(AST_LOG_CATEGORY_RTCP);
+
+ ast_debug_category_unregister(AST_LOG_CATEGORY_RTP_PACKET);
+ ast_debug_category_unregister(AST_LOG_CATEGORY_RTP);
}
int ast_rtp_engine_init(void)
@@ -3684,6 +3744,14 @@
add_static_payload(127, ast_format_slin96, 0);
/* payload types above 127 are not valid */
+ debug_category_rtp_id = ast_debug_category_register(AST_LOG_CATEGORY_RTP);
+ debug_category_rtp_packet_id = ast_debug_category_register(AST_LOG_CATEGORY_RTP_PACKET);
+ debug_category_rtcp_id = ast_debug_category_register(AST_LOG_CATEGORY_RTCP);
+ debug_category_rtcp_packet_id = ast_debug_category_register(AST_LOG_CATEGORY_RTCP_PACKET);
+ debug_category_dtls_id = ast_debug_category_register(AST_LOG_CATEGORY_DTLS);
+ debug_category_dtls_packet_id = ast_debug_category_register(AST_LOG_CATEGORY_DTLS_PACKET);
+ debug_category_ice_id = ast_debug_category_register(AST_LOG_CATEGORY_ICE);
+
return 0;
}
diff --git a/main/stun.c b/main/stun.c
index c103ab8..e917944 100644
--- a/main/stun.c
+++ b/main/stun.c
@@ -32,14 +32,14 @@
#include "asterisk.h"
+#include "asterisk/logger.h"
+#include "asterisk/logger_category.h"
#include "asterisk/_private.h"
#include "asterisk/stun.h"
#include "asterisk/cli.h"
#include "asterisk/utils.h"
#include "asterisk/channel.h"
-static int stundebug; /*!< Are we debugging stun? */
-
/*!
* \brief STUN support code
*
@@ -178,9 +178,10 @@
static int stun_process_attr(struct stun_state *state, struct stun_attr *attr)
{
- if (stundebug)
+ if (ast_debug_stun_packet_is_allowed) {
ast_verbose("Found STUN Attribute %s (%04x), length %d\n",
- stun_attr2str(ntohs(attr->attr)), (unsigned)ntohs(attr->attr), ntohs(attr->len));
+ stun_attr2str(ntohs(attr->attr)), (unsigned)ntohs(attr->attr), ntohs(attr->len));
+ }
switch (ntohs(attr->attr)) {
case STUN_USERNAME:
state->username = (const char *) (attr->value);
@@ -189,10 +190,12 @@
state->password = (const char *) (attr->value);
break;
default:
- if (stundebug)
+ if (ast_debug_stun_packet_is_allowed) {
ast_verbose("Ignoring STUN attribute %s (%04x), length %d\n",
- stun_attr2str(ntohs(attr->attr)), (unsigned)ntohs(attr->attr), ntohs(attr->len));
+ stun_attr2str(ntohs(attr->attr)), (unsigned)ntohs(attr->attr), ntohs(attr->len));
+ }
}
+
return 0;
}
@@ -275,35 +278,35 @@
* while 'data' is advanced accordingly.
*/
if (len < sizeof(struct stun_header)) {
- ast_debug(1, "Runt STUN packet (only %d, wanting at least %d)\n", (int) len, (int) sizeof(struct stun_header));
+ ast_debug_stun(1, "Runt STUN packet (only %d, wanting at least %d)\n", (int) len, (int) sizeof(struct stun_header));
return -1;
}
len -= sizeof(struct stun_header);
data += sizeof(struct stun_header);
x = ntohs(hdr->msglen); /* len as advertised in the message */
- if (stundebug)
+ if (ast_debug_stun_packet_is_allowed)
ast_verbose("STUN Packet, msg %s (%04x), length: %d\n", stun_msg2str(ntohs(hdr->msgtype)), (unsigned)ntohs(hdr->msgtype), x);
if (x > len) {
- ast_debug(1, "Scrambled STUN packet length (got %d, expecting %d)\n", x, (int)len);
+ ast_debug_stun(1, "Scrambled STUN packet length (got %d, expecting %d)\n", x, (int)len);
} else
len = x;
memset(&st, 0, sizeof(st));
while (len) {
if (len < sizeof(struct stun_attr)) {
- ast_debug(1, "Runt Attribute (got %d, expecting %d)\n", (int)len, (int) sizeof(struct stun_attr));
+ ast_debug_stun(1, "Runt Attribute (got %d, expecting %d)\n", (int)len, (int) sizeof(struct stun_attr));
break;
}
attr = (struct stun_attr *)data;
/* compute total attribute length */
x = ntohs(attr->len) + sizeof(struct stun_attr);
if (x > len) {
- ast_debug(1, "Inconsistent Attribute (length %d exceeds remaining msg len %d)\n", x, (int)len);
+ ast_debug_stun(1, "Inconsistent Attribute (length %d exceeds remaining msg len %d)\n", x, (int)len);
break;
}
if (stun_cb)
stun_cb(attr, arg);
if (stun_process_attr(&st, attr)) {
- ast_debug(1, "Failed to handle attribute %s (%04x)\n", stun_attr2str(ntohs(attr->attr)), (unsigned)ntohs(attr->attr));
+ ast_debug_stun(1, "Failed to handle attribute %s (%04x)\n", stun_attr2str(ntohs(attr->attr)), (unsigned)ntohs(attr->attr));
break;
}
/* Clear attribute id: in case previous entry was a string,
@@ -337,7 +340,7 @@
attr = (struct stun_attr *)resp->ies;
switch (ntohs(hdr->msgtype)) {
case STUN_BINDREQ:
- if (stundebug)
+ if (ast_debug_stun_packet_is_allowed)
ast_verbose("STUN Bind Request, username: %s\n",
st.username ? st.username : "<none>");
if (st.username) {
@@ -355,7 +358,7 @@
ret = AST_STUN_ACCEPT;
break;
default:
- if (stundebug)
+ if (ast_debug_stun_packet_is_allowed)
ast_verbose("Dunno what to do with STUN message %04x (%s)\n", (unsigned)ntohs(hdr->msgtype), stun_msg2str(ntohs(hdr->msgtype)));
}
}
@@ -416,7 +419,7 @@
/* Send STUN message. */
res = stun_send(s, dst, req);
if (res < 0) {
- ast_debug(1, "stun_send try %d failed: %s\n", retry, strerror(errno));
+ ast_debug_stun(1, "stun_send try %d failed: %s\n", retry, strerror(errno));
break;
}
if (!answer) {
@@ -459,7 +462,7 @@
res = recvfrom(s, rsp_buf, sizeof(rsp_buf) - 1,
0, (struct sockaddr *) &src, &srclen);
if (res < 0) {
- ast_debug(1, "recvfrom try %d failed: %s\n", retry, strerror(errno));
+ ast_debug_stun(1, "recvfrom try %d failed: %s\n", retry, strerror(errno));
break;
}
@@ -500,13 +503,13 @@
return CLI_SHOWUSAGE;
if (!strncasecmp(a->argv[e->args-1], "on", 2))
- stundebug = 1;
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_STUN_PACKET, AST_LOG_CATEGORY_ENABLED);
else if (!strncasecmp(a->argv[e->args-1], "off", 3))
- stundebug = 0;
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_STUN_PACKET, AST_LOG_CATEGORY_DISABLED);
else
return CLI_SHOWUSAGE;
- ast_cli(a->fd, "STUN Debugging %s\n", stundebug ? "Enabled" : "Disabled");
+ ast_cli(a->fd, "STUN Debugging %s\n", ast_debug_stun_packet_is_allowed ? "Enabled" : "Disabled");
return CLI_SUCCESS;
}
@@ -514,9 +517,26 @@
AST_CLI_DEFINE(handle_cli_stun_set_debug, "Enable/Disable STUN debugging"),
};
+static uintmax_t debug_category_stun_id;
+
+uintmax_t ast_debug_category_stun_id(void)
+{
+ return debug_category_stun_id;
+}
+
+static uintmax_t debug_category_stun_packet_id;
+
+uintmax_t ast_debug_category_stun_packet_id(void)
+{
+ return debug_category_stun_packet_id;
+}
+
static void stun_shutdown(void)
{
ast_cli_unregister_multiple(cli_stun, sizeof(cli_stun) / sizeof(struct ast_cli_entry));
+
+ ast_debug_category_unregister(AST_LOG_CATEGORY_STUN_PACKET);
+ ast_debug_category_unregister(AST_LOG_CATEGORY_STUN);
}
/*! \brief Initialize the STUN system in Asterisk */
@@ -524,4 +544,7 @@
{
ast_cli_register_multiple(cli_stun, sizeof(cli_stun) / sizeof(struct ast_cli_entry));
ast_register_cleanup(stun_shutdown);
+
+ debug_category_stun_id = ast_debug_category_register(AST_LOG_CATEGORY_STUN);
+ debug_category_stun_packet_id = ast_debug_category_register(AST_LOG_CATEGORY_STUN_PACKET);
}
diff --git a/res/res_pjsip_sdp_rtp.c b/res/res_pjsip_sdp_rtp.c
index 1bccc50..a807c23 100644
--- a/res/res_pjsip_sdp_rtp.c
+++ b/res/res_pjsip_sdp_rtp.c
@@ -52,6 +52,7 @@
#include "asterisk/dsp.h"
#include "asterisk/linkedlists.h" /* for AST_LIST_NEXT */
#include "asterisk/stream.h"
+#include "asterisk/logger_category.h"
#include "asterisk/format_cache.h"
#include "asterisk/res_pjsip.h"
@@ -82,15 +83,15 @@
keepalive = ast_rtp_instance_get_keepalive(rtp);
if (!ast_sockaddr_isnull(&session_media->direct_media_addr)) {
- ast_debug(3, "Not sending RTP keepalive on RTP instance %p since direct media is in use\n", rtp);
+ ast_debug_rtp(3, "(%p) RTP not sending keepalive since direct media is in use\n", rtp);
return keepalive * 1000;
}
interval = time(NULL) - ast_rtp_instance_get_last_tx(rtp);
send_keepalive = interval >= keepalive;
- ast_debug(3, "It has been %d seconds since RTP was last sent on instance %p. %sending keepalive\n",
- (int) interval, rtp, send_keepalive ? "S" : "Not s");
+ ast_debug_rtp(3, "(%p) RTP it has been %d seconds since RTP was last sent. %sending keepalive\n",
+ rtp, (int) interval, send_keepalive ? "S" : "Not s");
if (send_keepalive) {
ast_rtp_instance_sendcng(rtp, 0);
@@ -138,8 +139,8 @@
* - disconnect channel unless direct media is in use.
*/
if (!ast_sockaddr_isnull(&session_media->direct_media_addr)) {
- ast_debug(3, "Not disconnecting channel '%s' for lack of %s RTP activity in %d seconds "
- "since direct media is in use\n", ast_channel_name(chan),
+ ast_debug_rtp(3, "(%p) RTP not disconnecting channel '%s' for lack of %s RTP activity in %d seconds "
+ "since direct media is in use\n", rtp, ast_channel_name(chan),
ast_codec_media_type2str(session_media->type), elapsed);
ast_channel_unlock(chan);
ast_channel_unref(chan);
@@ -233,12 +234,12 @@
if (session->endpoint->media.bind_rtp_to_media_address && !ast_strlen_zero(session->endpoint->media.address)) {
if (ast_sockaddr_parse(&temp_media_address, session->endpoint->media.address, 0)) {
- ast_debug(1, "Endpoint %s: Binding RTP media to %s\n",
+ ast_debug_rtp(1, "Endpoint %s: Binding RTP media to %s\n",
ast_sorcery_object_get_id(session->endpoint),
session->endpoint->media.address);
media_address = &temp_media_address;
} else {
- ast_debug(1, "Endpoint %s: RTP media address invalid: %s\n",
+ ast_debug_rtp(1, "Endpoint %s: RTP media address invalid: %s\n",
ast_sorcery_object_get_id(session->endpoint),
session->endpoint->media.address);
}
@@ -256,11 +257,11 @@
pj_sockaddr_print(&trans_state->host, hoststr, sizeof(hoststr), 0);
if (ast_sockaddr_parse(&temp_media_address, hoststr, 0)) {
- ast_debug(1, "Transport %s bound to %s: Using it for RTP media.\n",
+ ast_debug_rtp(1, "Transport %s bound to %s: Using it for RTP media.\n",
session->endpoint->transport, hoststr);
media_address = &temp_media_address;
} else {
- ast_debug(1, "Transport %s bound to %s: Invalid for RTP media.\n",
+ ast_debug_rtp(1, "Transport %s bound to %s: Invalid for RTP media.\n",
session->endpoint->transport, hoststr);
}
ao2_ref(trans_state, -1);
@@ -786,6 +787,8 @@
return;
}
+ ast_debug_ice(2, "(%p) ICE process attributes\n", session_media->rtp);
+
attr = pjmedia_sdp_media_find_attr2(remote_stream, "ice-ufrag", NULL);
if (!attr) {
attr = pjmedia_sdp_attr_find2(remote->attr_count, remote->attr, "ice-ufrag", NULL);
@@ -794,6 +797,7 @@
ast_copy_pj_str(attr_value, (pj_str_t*)&attr->value, sizeof(attr_value));
ice->set_authentication(session_media->rtp, attr_value, NULL);
} else {
+ ast_debug_ice(2, "(%p) ICE no, or invalid ice-ufrag\n", session_media->rtp);
return;
}
@@ -805,6 +809,7 @@
ast_copy_pj_str(attr_value, (pj_str_t*)&attr->value, sizeof(attr_value));
ice->set_authentication(session_media->rtp, NULL, attr_value);
} else {
+ ast_debug_ice(2, "(%p) ICE no, or invalid ice-pwd\n", session_media->rtp);
return;
}
diff --git a/res/res_rtp_asterisk.c b/res/res_rtp_asterisk.c
index 1820ab1..dfec8f5 100644
--- a/res/res_rtp_asterisk.c
+++ b/res/res_rtp_asterisk.c
@@ -64,6 +64,7 @@
#endif
#include "asterisk/options.h"
+#include "asterisk/logger_category.h"
#include "asterisk/stun.h"
#include "asterisk/pbx.h"
#include "asterisk/frame.h"
@@ -110,6 +111,7 @@
#define MAXIMUM_RTP_RECV_BUFFER_SIZE (DEFAULT_RTP_RECV_BUFFER_SIZE + 20) /*!< Maximum RTP receive buffer size */
#define OLD_PACKET_COUNT 1000 /*!< The number of previous packets that are considered old */
#define MISSING_SEQNOS_ADDED_TRIGGER 2 /*!< The number of immediate missing packets that will trigger an immediate NACK */
+
#define SEQNO_CYCLE_OVER 65536 /*!< The number after the maximum allowed sequence number */
/*! Full INTRA-frame Request / Fast Update Request (From RFC2032) */
@@ -189,8 +191,6 @@
static int rtpstart = DEFAULT_RTP_START; /*!< First port for RTP sessions (set in rtp.conf) */
static int rtpend = DEFAULT_RTP_END; /*!< Last port for RTP sessions (set in rtp.conf) */
-static int rtpdebug; /*!< Are we debugging? */
-static int rtcpdebug; /*!< Are we debugging RTCP? */
static int rtcpstats; /*!< Are we debugging RTCP? */
static int rtcpinterval = RTCP_DEFAULT_INTERVALMS; /*!< Time between rtcp reports in millisecs */
static struct ast_sockaddr rtpdebugaddr; /*!< Debug packets to/from this host */
@@ -669,6 +669,7 @@
int rtcp = 0;
struct ast_sockaddr remote_address = { {0, } };
int ice;
+ int bytes_sent;
/* OpenSSL can't tolerate a packet not being sent, so we always state that
* we sent the packet. If it isn't then retransmission will occur.
@@ -685,7 +686,13 @@
return len;
}
- __rtp_sendto(instance, (char *)buf, len, 0, &remote_address, rtcp, &ice, 0);
+ bytes_sent = __rtp_sendto(instance, (char *)buf, len, 0, &remote_address, rtcp, &ice, 0);
+
+ if (bytes_sent > 0 && ast_debug_dtls_packet_is_allowed) {
+ ast_debug(0, "(%p) DTLS - sent %s packet to %s%s (len %-6.6d)\n",
+ instance, rtcp ? "RTCP" : "RTP", ast_sockaddr_stringify(&remote_address),
+ ice ? " (via ICE)" : "", bytes_sent);
+ }
return len;
}
@@ -817,6 +824,8 @@
ast_sockaddr_copy(&remote_candidate->relay_address, &candidate->relay_address);
remote_candidate->type = candidate->type;
+ ast_debug_ice(2, "(%p) ICE add remote candidate\n", instance);
+
ao2_link(rtp->ice_proposed_remote_candidates, remote_candidate);
ao2_ref(remote_candidate, -1);
}
@@ -862,6 +871,7 @@
ao2_unlock(instance);
ao2_ref(ice, -1);
ao2_lock(instance);
+ ast_debug_ice(2, "(%p) ICE stopped\n", instance);
}
}
@@ -922,13 +932,14 @@
struct ast_rtp *rtp = ast_rtp_instance_get_data(instance);
int res;
- ast_debug(3, "Resetting ICE for RTP instance '%p'\n", instance);
+ ast_debug_ice(3, "(%p) ICE resetting\n", instance);
if (!rtp->ice->real_ice->is_nominating && !rtp->ice->real_ice->is_complete) {
- ast_debug(3, "Nevermind. ICE isn't ready for a reset\n");
+ ast_debug_ice(3, " (%p) ICE nevermind, not ready for a reset\n", instance);
return 0;
}
- ast_debug(3, "Recreating ICE session %s (%d) for RTP instance '%p'\n", ast_sockaddr_stringify(&rtp->ice_original_rtp_addr), rtp->ice_port, instance);
+ ast_debug_ice(3, "(%p) ICE recreating ICE session %s (%d)\n",
+ instance, ast_sockaddr_stringify(&rtp->ice_original_rtp_addr), rtp->ice_port);
res = ice_create(instance, &rtp->ice_original_rtp_addr, rtp->ice_port, 1);
if (!res) {
/* Use the current expected role for the ICE session */
@@ -1004,7 +1015,7 @@
/* Check for equivalence in the lists */
if (rtp->ice_active_remote_candidates &&
!ice_candidates_compare(rtp->ice_proposed_remote_candidates, rtp->ice_active_remote_candidates)) {
- ast_debug(3, "Proposed == active candidates for RTP instance '%p'\n", instance);
+ ast_debug_ice(2, "(%p) ICE proposed equals active candidates\n", instance);
ao2_cleanup(rtp->ice_proposed_remote_candidates);
rtp->ice_proposed_remote_candidates = NULL;
/* If this ICE session is being preserved then go back to the role it currently is */
@@ -1017,9 +1028,11 @@
rtp->ice_active_remote_candidates = rtp->ice_proposed_remote_candidates;
rtp->ice_proposed_remote_candidates = NULL;
+ ast_debug_ice(2, "(%p) ICE start\n", instance);
+
/* Reset the ICE session. Is this going to work? */
if (ice_reset_session(instance)) {
- ast_log(LOG_NOTICE, "Failed to create replacement ICE session\n");
+ ast_log(LOG_NOTICE, "(%p) ICE failed to create replacement session\n", instance);
return;
}
@@ -1054,13 +1067,13 @@
}
if (candidate->id == AST_RTP_ICE_COMPONENT_RTP && rtp->turn_rtp) {
- ast_debug(3, "RTP candidate %s (%p)\n", ast_sockaddr_stringify(&candidate->address), instance);
+ ast_debug_ice(2, "(%p) ICE RTP candidate %s\n", instance, ast_sockaddr_stringify(&candidate->address));
/* Release the instance lock to avoid deadlock with PJPROJECT group lock */
ao2_unlock(instance);
pj_turn_sock_set_perm(rtp->turn_rtp, 1, &candidates[cand_cnt].addr, 1);
ao2_lock(instance);
} else if (candidate->id == AST_RTP_ICE_COMPONENT_RTCP && rtp->turn_rtcp) {
- ast_debug(3, "RTCP candidate %s (%p)\n", ast_sockaddr_stringify(&candidate->address), instance);
+ ast_debug_ice(2, "(%p) ICE RTCP candidate %s\n", instance, ast_sockaddr_stringify(&candidate->address));
/* Release the instance lock to avoid deadlock with PJPROJECT group lock */
ao2_unlock(instance);
pj_turn_sock_set_perm(rtp->turn_rtcp, 1, &candidates[cand_cnt].addr, 1);
@@ -1074,17 +1087,17 @@
ao2_iterator_destroy(&i);
if (cand_cnt < ao2_container_count(rtp->ice_active_remote_candidates)) {
- ast_log(LOG_WARNING, "Lost %d ICE candidates. Consider increasing PJ_ICE_MAX_CAND in PJSIP (%p)\n",
- ao2_container_count(rtp->ice_active_remote_candidates) - cand_cnt, instance);
+ ast_log(LOG_WARNING, "(%p) ICE lost %d candidates. Consider increasing PJ_ICE_MAX_CAND in PJSIP\n",
+ instance, ao2_container_count(rtp->ice_active_remote_candidates) - cand_cnt);
}
if (!has_rtp) {
- ast_log(LOG_WARNING, "No RTP candidates; skipping ICE checklist (%p)\n", instance);
+ ast_log(LOG_WARNING, "(%p) ICE no RTP candidates; skipping checklist\n", instance);
}
/* If we're only dealing with one ICE component, then we don't care about the lack of RTCP candidates */
if (!has_rtcp && rtp->ice_num_components > 1) {
- ast_log(LOG_WARNING, "No RTCP candidates; skipping ICE checklist (%p)\n", instance);
+ ast_log(LOG_WARNING, "(%p) ICE no RTCP candidates; skipping checklist\n", instance);
}
if (rtp->ice && has_rtp && (has_rtcp || rtp->ice_num_components == 1)) {
@@ -1098,7 +1111,7 @@
ao2_unlock(instance);
res = pj_ice_sess_create_check_list(ice->real_ice, &ufrag, &passwd, cand_cnt, &candidates[0]);
if (res == PJ_SUCCESS) {
- ast_debug(3, "Successfully created ICE checklist (%p)\n", instance);
+ ast_debug_ice(2, "(%p) ICE successfully created checklist\n", instance);
ast_test_suite_event_notify("ICECHECKLISTCREATE", "Result: SUCCESS");
pj_ice_sess_start_check(ice->real_ice);
pj_timer_heap_poll(timer_heap, NULL);
@@ -1111,7 +1124,7 @@
ao2_lock(instance);
pj_strerror(res, reason, sizeof(reason));
- ast_log(LOG_WARNING, "Failed to create ICE session check list: %s (%p)\n", reason, instance);
+ ast_log(LOG_WARNING, "(%p) ICE failed to create session check list: %s\n", instance, reason);
}
ast_test_suite_event_notify("ICECHECKLISTCREATE", "Result: FAILURE");
@@ -1174,11 +1187,8 @@
{
struct ast_rtp *rtp = ast_rtp_instance_get_data(instance);
- ast_debug(3, "Set role to %s (%p)\n",
- role == AST_RTP_ICE_ROLE_CONTROLLED ? "CONTROLLED" : "CONTROLLING", instance);
-
if (!rtp->ice) {
- ast_debug(3, "Set role failed; no ice instance (%p)\n", instance);
+ ast_debug_ice(3, "(%p) ICE set role failed; no ice instance\n", instance);
return;
}
@@ -1186,11 +1196,13 @@
if (!rtp->ice->real_ice->is_nominating && !rtp->ice->real_ice->is_complete) {
pj_thread_register_check();
-
+ ast_debug_ice(2, "(%p) ICE set role to %s\n",
+ instance, role == AST_RTP_ICE_ROLE_CONTROLLED ? "CONTROLLED" : "CONTROLLING");
pj_ice_sess_change_role(rtp->ice->real_ice, role == AST_RTP_ICE_ROLE_CONTROLLED ?
PJ_ICE_SESS_ROLE_CONTROLLED : PJ_ICE_SESS_ROLE_CONTROLLING);
} else {
- ast_debug(3, "Not setting ICE role because state is %s\n", rtp->ice->real_ice->is_nominating ? "nominating" : "complete" );
+ ast_debug_ice(2, "(%p) ICE not setting role because state is %s\n",
+ instance, rtp->ice->real_ice->is_nominating ? "nominating" : "complete");
}
}
@@ -1261,6 +1273,8 @@
ao2_ref(ice, -1);
ao2_lock(instance);
if (!rtp->ice || status != PJ_SUCCESS) {
+ ast_debug_ice(2, "(%p) ICE unable to add candidate: %s, %d\n", instance, ast_sockaddr_stringify(
+ &candidate->address), candidate->priority);
ao2_ref(candidate, -1);
return;
}
@@ -1268,6 +1282,9 @@
/* By placing the candidate into the ICE session it will have produced the priority, so update the local candidate with it */
candidate->priority = rtp->ice->real_ice->lcand[rtp->ice->real_ice->lcand_cnt - 1].prio;
+ ast_debug_ice(2, "(%p) ICE add candidate: %s, %d\n", instance, ast_sockaddr_stringify(
+ &candidate->address), candidate->priority);
+
ao2_link(rtp->ice_local_candidates, candidate);
ao2_ref(candidate, -1);
}
@@ -1292,8 +1309,8 @@
char buf[100];
pj_strerror(status, buf, sizeof(buf));
- ast_log(LOG_WARNING, "PJ ICE Rx error status code: %d '%s'.\n",
- (int)status, buf);
+ ast_log(LOG_WARNING, "(%p) ICE PJ Rx error status code: %d '%s'.\n",
+ instance, (int)status, buf);
return;
}
if (!rtp->rtp_passthrough) {
@@ -1624,7 +1641,7 @@
turn_cb, &turn_sock_cfg, instance, turn_sock);
ao2_cleanup(ice);
if (status != PJ_SUCCESS) {
- ast_log(LOG_WARNING, "Could not create a TURN client socket\n");
+ ast_log(LOG_WARNING, "(%p) Could not create a TURN client socket\n", instance);
ao2_lock(instance);
return;
}
@@ -1635,6 +1652,11 @@
pj_strset2(&cred.data.static_cred.data, (char*)password);
pj_turn_sock_alloc(*turn_sock, pj_cstr(&turn_addr, server), port, NULL, &cred, NULL);
+
+ ast_debug_ice(2, "(%p) ICE request TURN %s %s candidate\n", instance,
+ transport == AST_TRANSPORT_UDP ? "UDP" : "TCP",
+ component == AST_RTP_ICE_COMPONENT_RTP ? "RTP" : "RTCP");
+
ao2_lock(instance);
/*
@@ -1688,6 +1710,9 @@
return;
}
+ ast_debug_ice(2, "(%p) ICE change number of components %u -> %u\n", instance,
+ rtp->ice_num_components, num_components);
+
rtp->ice_num_components = num_components;
ice_reset_session(instance);
}
@@ -1782,6 +1807,7 @@
return 0;
}
+ ast_debug_dtls(3, "(%p) DTLS RTCP setup\n", instance);
return dtls_details_initialize(&rtp->rtcp->dtls, rtp->ssl_ctx, rtp->dtls.dtls_setup, instance);
}
@@ -2075,6 +2101,8 @@
return 0;
}
+ ast_debug_dtls(3, "(%p) DTLS RTP setup\n", instance);
+
if (!ast_rtp_engine_srtp_is_registered()) {
ast_log(LOG_ERROR, "SRTP support module is not loaded or available. Try loading res_srtp.so.\n");
return -1;
@@ -2197,6 +2225,7 @@
struct ast_rtp *rtp = ast_rtp_instance_get_data(instance);
SSL *ssl = rtp->dtls.ssl;
+ ast_debug_dtls(3, "(%p) DTLS stop\n", instance);
ao2_unlock(instance);
dtls_srtp_stop_timeout_timer(instance, rtp, 0);
ao2_lock(instance);
@@ -2469,7 +2498,7 @@
{
struct ast_rtp *rtp = ast_rtp_instance_get_data(instance);
- ast_debug(3, "dtls_perform_handshake (%p) - ssl = %p, setup = %d\n",
+ ast_debug_dtls(3, "(%p) DTLS perform handshake - ssl = %p, setup = %d\n",
rtp, dtls->ssl, dtls->dtls_setup);
/* If we are not acting as a client connecting to the remote side then
@@ -2509,7 +2538,7 @@
}
dtls->connection = AST_RTP_DTLS_CONNECTION_NEW;
- ast_debug(3, "dtls_perform_setup - connection reset'\n");
+ ast_debug_dtls(3, "DTLS perform setup - connection reset\n");
}
#endif
@@ -2548,7 +2577,8 @@
return;
}
- ast_debug(3, "ast_rtp_on_ice_complete (%p) - perform DTLS\n", rtp);
+ ast_debug_category(2, AST_DEBUG_CATEGORY_ICE | AST_DEBUG_CATEGORY_DTLS,
+ "(%p) ICE starting media - perform DTLS - (%p)\n", instance, rtp);
/*
* Seemingly no reason to call dtls_perform_setup here. Currently we'll do a full
@@ -2585,6 +2615,7 @@
/* PJPROJECT ICE optional callback */
static void ast_rtp_on_valid_pair(pj_ice_sess *ice)
{
+ ast_debug_ice(2, "(%p) ICE valid pair, start media\n", ice->user_data);
ast_rtp_ice_start_media(ice, PJ_SUCCESS);
}
#endif
@@ -2592,6 +2623,7 @@
/* PJPROJECT ICE callback */
static void ast_rtp_on_ice_complete(pj_ice_sess *ice, pj_status_t status)
{
+ ast_debug_ice(2, "(%p) ICE complete, start media\n", ice->user_data);
ast_rtp_ice_start_media(ice, status);
}
@@ -2681,7 +2713,7 @@
static inline int rtp_debug_test_addr(struct ast_sockaddr *addr)
{
- if (!rtpdebug) {
+ if (!ast_debug_rtp_packet_is_allowed) {
return 0;
}
if (!ast_sockaddr_isnull(&rtpdebugaddr)) {
@@ -2697,7 +2729,7 @@
static inline int rtcp_debug_test_addr(struct ast_sockaddr *addr)
{
- if (!rtcpdebug) {
+ if (!ast_debug_rtcp_packet_is_allowed) {
return 0;
}
if (!ast_sockaddr_isnull(&rtcpdebugaddr)) {
@@ -2719,6 +2751,7 @@
struct dtls_details *dtls = !rtcp ? &rtp->dtls : &rtp->rtcp->dtls;
struct timeval dtls_timeout;
+ ast_debug_dtls(3, "(%p) DTLS srtp - handle timeout - rtcp=%d\n", instance, rtcp);
DTLSv1_handle_timeout(dtls->ssl);
/* If a timeout can't be retrieved then this recurring scheduled item must stop */
@@ -2778,6 +2811,8 @@
ao2_ref(instance, -1);
ast_log(LOG_WARNING, "Scheduling '%s' DTLS retransmission for RTP instance [%p] failed.\n",
!rtcp ? "RTP" : "RTCP", instance);
+ } else {
+ ast_debug_dtls(3, "(%p) DTLS srtp - scheduled timeout timer for '%d'\n", instance, timeout);
}
}
}
@@ -2788,6 +2823,7 @@
struct dtls_details *dtls = !rtcp ? &rtp->dtls : &rtp->rtcp->dtls;
AST_SCHED_DEL_UNREF(rtp->sched, dtls->timeout_timer, ao2_ref(instance, -1));
+ ast_debug_dtls(3, "(%p) DTLS srtp - stopped timeout timer'\n", instance);
}
/* Scheduler callback */
@@ -2798,6 +2834,7 @@
ao2_lock(instance);
+ ast_debug_dtls(3, "(%p) DTLS srtp - renegotiate'\n", instance);
SSL_renegotiate(rtp->dtls.ssl);
SSL_do_handshake(rtp->dtls.ssl);
@@ -2822,6 +2859,9 @@
int res = -1;
struct dtls_details *dtls = !rtcp ? &rtp->dtls : &rtp->rtcp->dtls;
+ ast_debug_dtls(3, "(%p) DTLS srtp - add local ssrc - rtcp=%d, set_remote_policy=%d'\n",
+ instance, rtcp, set_remote_policy);
+
/* Produce key information and set up SRTP */
if (!SSL_export_keying_material(dtls->ssl, material, SRTP_MASTER_LEN * 2, "EXTRACTOR-dtls_srtp", 19, NULL, 0, 0)) {
ast_log(LOG_WARNING, "Unable to extract SRTP keying material from DTLS-SRTP negotiation on RTP instance '%p'\n",
@@ -2899,7 +2939,7 @@
struct dtls_details *dtls = !rtcp ? &rtp->dtls : &rtp->rtcp->dtls;
int index;
- ast_debug(3, "Setup DTLS SRTP (%p)'\n", rtp);
+ ast_debug_dtls(3, "(%p) DTLS setup SRTP rtp=%p'\n", instance, rtp);
/* If a fingerprint is present in the SDP make sure that the peer certificate matches it */
if (rtp->dtls_verify & AST_RTP_DTLS_VERIFY_FINGERPRINT) {
@@ -3048,7 +3088,7 @@
return -1;
}
- ast_debug(3, "__rtp_recvfrom (%p) - Got SSL packet '%d'\n", rtp, *in);
+ ast_debug_dtls(3, "(%p) DTLS - __rtp_recvfrom rtp=%p - Got SSL packet '%d'\n", instance, rtp, *in);
/*
* A race condition is prevented between dtls_perform_handshake()
@@ -3090,7 +3130,7 @@
/* Notify that dtls has been established */
res = RTP_DTLS_ESTABLISHED;
- ast_debug(3, "__rtp_recvfrom (%p) - DTLS established'\n", rtp);
+ ast_debug_dtls(3, "(%p) DTLS - __rtp_recvfrom rtp=%p - established'\n", instance, rtp);
} else {
/* Since we've sent additional traffic start the timeout timer for retransmission */
dtls_srtp_start_timeout_timer(instance, rtp, rtcp);
@@ -3484,9 +3524,10 @@
if (getifaddrs(&ifa) < 0) {
/* If we can't get addresses, we can't load ICE candidates */
- ast_log(LOG_ERROR, "Error obtaining list of local addresses: %s\n",
- strerror(errno));
+ ast_log(LOG_ERROR, "(%p) ICE Error obtaining list of local addresses: %s\n",
+ instance, strerror(errno));
} else {
+ ast_debug_ice(2, "(%p) ICE add system candidates\n", instance);
/* Iterate through the list of addresses obtained from the system,
* until we've iterated through all of them, or accepted
* PJ_ICE_MAX_CAND candidates */
@@ -3588,6 +3629,11 @@
struct sockaddr_in answer;
int rsp;
+ ast_debug_category(3, AST_DEBUG_CATEGORY_ICE | AST_DEBUG_CATEGORY_STUN,
+ "(%p) ICE request STUN %s %s candidate\n", instance,
+ transport == AST_TRANSPORT_UDP ? "UDP" : "TCP",
+ component == AST_RTP_ICE_COMPONENT_RTP ? "RTP" : "RTCP");
+
/*
* The instance should not be locked because we can block
* waiting for a STUN respone.
@@ -3699,6 +3745,8 @@
ao2_cleanup(rtp->ice_local_candidates);
rtp->ice_local_candidates = NULL;
+ ast_debug_ice(2, "(%p) ICE create%s\n", instance, replace ? " and replace" : "");
+
ice = ao2_alloc_options(sizeof(*ice), ice_wrap_dtor, AO2_ALLOC_OPT_LOCK_NOLOCK);
if (!ice) {
ast_rtp_ice_stop(instance);
@@ -3782,7 +3830,7 @@
ast_sockaddr_set_port(&rtp->bind_address, x);
/* Try to bind, this will tell us whether the port is available or not */
if (!ast_bind(rtp->s, &rtp->bind_address)) {
- ast_debug(1, "Allocated port %d for RTP instance '%p'\n", x, instance);
+ ast_debug_rtp(1, "(%p) RTP allocated port %d\n", instance, x);
ast_rtp_instance_set_local_address(instance, &rtp->bind_address);
ast_test_suite_event_notify("RTP_PORT_ALLOCATED", "Port: %d", x);
break;
@@ -3812,9 +3860,10 @@
/* Create an ICE session for ICE negotiation */
if (icesupport) {
rtp->ice_num_components = 2;
- ast_debug(3, "Creating ICE session %s (%d) for RTP instance '%p'\n", ast_sockaddr_stringify(&rtp->bind_address), x, instance);
+ ast_debug_ice(2, "(%p) ICE creating session %s (%d)\n", instance,
+ ast_sockaddr_stringify(&rtp->bind_address), x);
if (ice_create(instance, &rtp->bind_address, x, 0)) {
- ast_log(LOG_NOTICE, "Failed to create ICE session\n");
+ ast_log(LOG_NOTICE, "(%p) ICE failed to create session\n", instance);
} else {
rtp->ice_port = x;
ast_sockaddr_copy(&rtp->ice_original_rtp_addr, &rtp->bind_address);
@@ -3891,6 +3940,7 @@
rtp->turn_rtcp = NULL;
}
+ ast_debug_ice(2, "(%p) ICE RTP transport deallocating\n", instance);
/* Destroy any ICE session */
ast_rtp_ice_stop(instance);
@@ -4218,7 +4268,8 @@
rtp->dtmfmute = ast_tvadd(ast_tvnow(), ast_tv(0, 500000));
if (duration > 0 && (measured_samples = duration * ast_rtp_get_rate(rtp->f.subclass.format) / 1000) > rtp->send_duration) {
- ast_debug(2, "Adjusting final end duration from %d to %u\n", rtp->send_duration, measured_samples);
+ ast_debug_rtp(2, "(%p) RTP adjusting final end duration from %d to %u\n",
+ instance, rtp->send_duration, measured_samples);
rtp->send_duration = measured_samples;
}
@@ -4281,7 +4332,7 @@
/* We simply set this bit so that the next packet sent will have the marker bit turned on */
ast_set_flag(rtp, FLAG_NEED_MARKER_BIT);
- ast_debug(3, "Setting the marker bit due to a source update\n");
+ ast_debug_rtp(3, "(%p) RTP setting the marker bit due to a source update\n", instance);
return;
}
@@ -4299,10 +4350,12 @@
ast_set_flag(rtp, FLAG_NEED_MARKER_BIT);
}
- ast_debug(3, "Changing ssrc from %u to %u due to a source change\n", rtp->ssrc, ssrc);
+ ast_debug_rtp(3, "(%p) RTP changing ssrc from %u to %u due to a source change\n",
+ instance, rtp->ssrc, ssrc);
if (srtp) {
- ast_debug(3, "Changing ssrc for SRTP from %u to %u\n", rtp->ssrc, ssrc);
+ ast_debug_rtp(3, "(%p) RTP changing ssrc for SRTP from %u to %u\n",
+ instance, rtp->ssrc, ssrc);
res_srtp->change_source(srtp, rtp->ssrc, ssrc);
if (rtcp_srtp != srtp) {
res_srtp->change_source(rtcp_srtp, rtp->ssrc, ssrc);
@@ -4639,7 +4692,7 @@
res = ast_rtcp_generate_report(instance, rtcpheader, report, sr);
if (res == 0 || res == 1) {
- ast_debug(1, "Failed to generate %s report!\n", sr ? "SR" : "RR");
+ ast_debug_rtcp(1, "(%p) RTCP failed to generate %s report!\n", instance, sr ? "SR" : "RR");
return 0;
}
@@ -4648,7 +4701,7 @@
res = ast_rtcp_generate_sdes(instance, rtcpheader + packet_len, report);
if (res == 0 || res == 1) {
- ast_debug(1, "Failed to generate SDES!\n");
+ ast_debug_rtcp(1, "(%p) RTCP failed to generate SDES!\n", instance);
return 0;
}
@@ -4856,7 +4909,8 @@
if (abs((int)rtp->lastts - pred) < MAX_TIMESTAMP_SKEW) {
rtp->lastts = pred;
} else {
- ast_debug(3, "Difference is %d, ms is %u\n", abs((int)rtp->lastts - pred), ms);
+ ast_debug_rtp(3, "(%p) RTP audio difference is %d, ms is %u\n",
+ instance, abs((int)rtp->lastts - pred), ms);
mark = 1;
}
}
@@ -4871,7 +4925,8 @@
rtp->lastts = pred;
rtp->lastovidtimestamp += frame->samples;
} else {
- ast_debug(3, "Difference is %d, ms is %u (%u), pred/ts/samples %u/%d/%d\n", abs((int)rtp->lastts - pred), ms, ms * 90, rtp->lastts, pred, frame->samples);
+ ast_debug_rtp(3, "(%p) RTP video difference is %d, ms is %u (%u), pred/ts/samples %u/%d/%d\n",
+ instance, abs((int)rtp->lastts - pred), ms, ms * 90, rtp->lastts, pred, frame->samples);
rtp->lastovidtimestamp = rtp->lastts;
}
}
@@ -4885,7 +4940,8 @@
rtp->lastts = pred;
rtp->lastotexttimestamp += frame->samples;
} else {
- ast_debug(3, "Difference is %d, ms is %u, pred/ts/samples %u/%d/%d\n", abs((int)rtp->lastts - pred), ms, rtp->lastts, pred, frame->samples);
+ ast_debug_rtp(3, "(%p) RTP other difference is %d, ms is %u, pred/ts/samples %u/%d/%d\n",
+ instance, abs((int)rtp->lastts - pred), ms, rtp->lastts, pred, frame->samples);
rtp->lastotexttimestamp = rtp->lastts;
}
}
@@ -5001,20 +5057,20 @@
res = rtp_sendto(instance, (void *)rtpheader, packet_len, 0, &remote_address, &ice);
if (res < 0) {
if (!ast_rtp_instance_get_prop(instance, AST_RTP_PROPERTY_NAT) || (ast_rtp_instance_get_prop(instance, AST_RTP_PROPERTY_NAT) && (ast_test_flag(rtp, FLAG_NAT_ACTIVE) == FLAG_NAT_ACTIVE))) {
- ast_debug(1, "RTP Transmission error of packet %d to %s: %s\n",
- rtp->seqno,
+ ast_debug_rtp(1, "(%p) RTP transmission error of packet %d to %s: %s\n",
+ instance, rtp->seqno,
ast_sockaddr_stringify(&remote_address),
strerror(errno));
- } else if (((ast_test_flag(rtp, FLAG_NAT_ACTIVE) == FLAG_NAT_INACTIVE) || rtpdebug) && !ast_test_flag(rtp, FLAG_NAT_INACTIVE_NOWARN)) {
+ } else if (((ast_test_flag(rtp, FLAG_NAT_ACTIVE) == FLAG_NAT_INACTIVE) || ast_debug_rtp_packet_is_allowed) && !ast_test_flag(rtp, FLAG_NAT_INACTIVE_NOWARN)) {
/* Only give this error message once if we are not RTP debugging */
- if (rtpdebug)
- ast_debug(0, "RTP NAT: Can't write RTP to private address %s, waiting for other end to send audio...\n",
- ast_sockaddr_stringify(&remote_address));
+ if (ast_debug_rtp_packet_is_allowed)
+ ast_debug(0, "(%p) RTP NAT: Can't write RTP to private address %s, waiting for other end to send audio...\n",
+ instance, ast_sockaddr_stringify(&remote_address));
ast_set_flag(rtp, FLAG_NAT_INACTIVE_NOWARN);
}
} else {
if (rtp->rtcp && rtp->rtcp->schedid < 0) {
- ast_debug(1, "Starting RTCP transmission on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP starting transmission\n", instance);
ao2_ref(instance, +1);
rtp->rtcp->schedid = ast_sched_add(rtp->sched, ast_rtcp_calc_interval(rtp), ast_rtcp_write, instance);
if (rtp->rtcp->schedid < 0) {
@@ -5160,8 +5216,8 @@
ao2_cleanup);
if (feedback->fmt != AST_RTP_RTCP_FMT_REMB) {
- ast_debug(1, "Provided an RTCP feedback frame of format %d to write on RTP instance '%p' but only REMB is supported\n",
- feedback->fmt, instance);
+ ast_debug_rtcp(1, "(%p) RTCP provided feedback frame of format %d to write, but only REMB is supported\n",
+ instance, feedback->fmt);
return;
}
@@ -5171,7 +5227,7 @@
/* If REMB support is not enabled don't send this RTCP packet */
if (!ast_rtp_instance_get_prop(instance, AST_RTP_PROPERTY_REMB)) {
- ast_debug(1, "Provided an RTCP feedback REMB report to write on RTP instance '%p' but REMB support not enabled\n",
+ ast_debug_rtcp(1, "(%p) RTCP provided feedback REMB report to write, but REMB support not enabled\n",
instance);
return;
}
@@ -5223,7 +5279,7 @@
/* If we don't actually know the remote address don't even bother doing anything */
if (ast_sockaddr_isnull(&remote_address)) {
- ast_debug(1, "No remote address on RTP instance '%p' so dropping frame\n", instance);
+ ast_debug_rtp(1, "(%p) RTP no remote address on instance, so dropping frame\n", instance);
return 0;
}
@@ -5240,7 +5296,7 @@
/* If there is no data length we can't very well send the packet */
if (!frame->datalen) {
- ast_debug(1, "Received frame with no data for RTP instance '%p' so dropping frame\n", instance);
+ ast_debug_rtp(1, "(%p) RTP received frame with no data for instance, so dropping frame\n", instance);
return 0;
}
@@ -5272,8 +5328,8 @@
format = frame->subclass.format;
if (ast_format_cmp(rtp->lasttxformat, format) == AST_FORMAT_CMP_NOT_EQUAL) {
/* Oh dear, if the format changed we will have to set up a new smoother */
- ast_debug(1, "Ooh, format changed from %s to %s\n",
- ast_format_get_name(rtp->lasttxformat),
+ ast_debug_rtp(1, "(%p) RTP ooh, format changed from %s to %s\n",
+ instance, ast_format_get_name(rtp->lasttxformat),
ast_format_get_name(frame->subclass.format));
ao2_replace(rtp->lasttxformat, format);
if (rtp->smoother) {
@@ -5398,14 +5454,14 @@
ast_rtp_instance_get_remote_address(instance, &remote_address);
if (((compensate && type == AST_FRAME_DTMF_END) || (type == AST_FRAME_DTMF_BEGIN)) && ast_tvcmp(ast_tvnow(), rtp->dtmfmute) < 0) {
- ast_debug(1, "Ignore potential DTMF echo from '%s'\n",
- ast_sockaddr_stringify(&remote_address));
+ ast_debug_rtp(1, "(%p) RTP ignore potential DTMF echo from '%s'\n",
+ instance, ast_sockaddr_stringify(&remote_address));
rtp->resp = 0;
rtp->dtmfsamples = 0;
return &ast_null_frame;
}
- ast_debug(1, "Creating %s DTMF Frame: %d (%c), at %s\n",
- type == AST_FRAME_DTMF_END ? "END" : "BEGIN",
+ ast_debug_rtp(1, "(%p) RTP creating %s DTMF Frame: %d (%c), at %s\n",
+ instance, type == AST_FRAME_DTMF_END ? "END" : "BEGIN",
rtp->resp, rtp->resp,
ast_sockaddr_stringify(&remote_address));
if (rtp->resp == 'X') {
@@ -5450,7 +5506,7 @@
}
/* Print out debug if turned on */
- if (rtpdebug)
+ if (ast_debug_rtp_packet_is_allowed)
ast_debug(0, "- RTP 2833 Event: %08x (len = %d)\n", event, len);
/* Figure out what digit was pressed */
@@ -5466,7 +5522,7 @@
resp = 'X';
} else {
/* Not a supported event */
- ast_debug(1, "Ignoring RTP 2833 Event: %08x. Not a DTMF Digit.\n", event);
+ ast_debug_rtp(1, "(%p) RTP ignoring RTP 2833 Event: %08x. Not a DTMF Digit.\n", instance, event);
return;
}
@@ -5504,9 +5560,9 @@
rtp->resp = 0;
rtp->dtmf_duration = rtp->dtmf_timeout = 0;
AST_LIST_INSERT_TAIL(frames, f, frame_list);
- } else if (rtpdebug) {
- ast_debug(1, "Dropping duplicate or out of order DTMF END frame (seqno: %u, ts %u, digit %c)\n",
- seqno, timestamp, resp);
+ } else if (ast_debug_rtp_packet_is_allowed) {
+ ast_debug_rtp(1, "(%p) RTP dropping duplicate or out of order DTMF END frame (seqno: %u, ts %u, digit %c)\n",
+ instance, seqno, timestamp, resp);
}
} else {
/* Begin/continuation */
@@ -5521,8 +5577,8 @@
* improperly duplicate incoming DTMF, so just drop
* this.
*/
- if (rtpdebug) {
- ast_debug(1, "Dropping out of order DTMF frame (seqno %u, ts %u, digit %c)\n",
+ if (ast_debug_rtp_packet_is_allowed) {
+ ast_debug(0, "Dropping out of order DTMF frame (seqno %u, ts %u, digit %c)\n",
seqno, timestamp, resp);
}
return;
@@ -5606,7 +5662,7 @@
power = data[2];
event = data[3] & 0x1f;
- if (rtpdebug)
+ if (ast_debug_rtp_packet_is_allowed)
ast_debug(0, "Cisco DTMF Digit: %02x (len=%d, seq=%d, flags=%02x, power=%u, history count=%d)\n", event, len, seq, flags, power, (len - 4) / 2);
if (event < 10) {
resp = '0' + event;
@@ -5646,7 +5702,7 @@
/* Convert comfort noise into audio with various codecs. Unfortunately this doesn't
totally help us out becuase we don't have an engine to keep it going and we are not
guaranteed to have it every 20ms or anything */
- if (rtpdebug) {
+ if (ast_debug_rtp_packet_is_allowed) {
ast_debug(0, "- RTP 3389 Comfort noise event: Format %s (len = %d)\n",
ast_format_get_name(rtp->lastrxformat), len);
}
@@ -5888,7 +5944,8 @@
unsigned int packets_not_found = 0;
if (!rtp->send_buffer) {
- ast_debug(1, "Tried to handle NACK request, but we don't have a RTP packet storage!\n");
+ ast_debug_rtcp(1, "(%p) RTCP tried to handle NACK request, "
+ "but we don't have a RTP packet storage!\n", instance);
return res;
}
@@ -5917,7 +5974,8 @@
}
res += rtp_sendto(instance, payload->buf, payload->size, 0, &remote_address, &ice);
} else {
- ast_debug(1, "Received NACK request for RTP packet with seqno %d, but we don't have it\n", pid);
+ ast_debug_rtcp(1, "(%p) RTCP received NACK request for RTP packet with seqno %d, "
+ "but we don't have it\n", instance, pid);
packets_not_found++;
}
/*
@@ -5939,7 +5997,8 @@
}
res += rtp_sendto(instance, payload->buf, payload->size, 0, &remote_address, &ice);
} else {
- ast_debug(1, "Remote end also requested RTP packet with seqno %d, but we don't have it\n", seqno);
+ ast_debug_rtcp(1, "(%p) RTCP remote end also requested RTP packet with seqno %d, "
+ "but we don't have it\n", instance, seqno);
packets_not_found++;
}
}
@@ -5954,7 +6013,8 @@
*/
ast_data_buffer_resize(rtp->send_buffer, MIN(MAXIMUM_RTP_SEND_BUFFER_SIZE,
ast_data_buffer_max(rtp->send_buffer) + packets_not_found));
- ast_debug(2, "Send buffer on RTP instance '%p' is now at maximum of %zu\n", instance, ast_data_buffer_max(rtp->send_buffer));
+ ast_debug_rtcp(2, "(%p) RTCP send buffer on RTP instance is now at maximum of %zu\n",
+ instance, ast_data_buffer_max(rtp->send_buffer));
}
return res;
@@ -6028,23 +6088,23 @@
packetwords = len / 4;
- ast_debug(1, "Got RTCP report of %d bytes from %s\n",
- len, ast_sockaddr_stringify(addr));
+ ast_debug_rtcp(1, "(%p) RTCP got report of %d bytes from %s\n",
+ instance, len, ast_sockaddr_stringify(addr));
/*
* Validate the RTCP packet according to an adapted and slightly
* modified RFC3550 validation algorithm.
*/
if (packetwords < RTCP_HEADER_SSRC_LENGTH) {
- ast_debug(1, "%p -- RTCP from %s: Frame size (%u words) is too short\n",
- transport_rtp, ast_sockaddr_stringify(addr), packetwords);
+ ast_debug_rtcp(1, "(%p) RTCP %p -- from %s: Frame size (%u words) is too short\n",
+ instance, transport_rtp, ast_sockaddr_stringify(addr), packetwords);
return &ast_null_frame;
}
position = 0;
first_word = ntohl(rtcpheader[position]);
if ((first_word & RTCP_VALID_MASK) != RTCP_VALID_VALUE) {
- ast_debug(1, "%p -- RTCP from %s: Failed first packet validity check\n",
- transport_rtp, ast_sockaddr_stringify(addr));
+ ast_debug_rtcp(1, "(%p) RTCP %p -- from %s: Failed first packet validity check\n",
+ instance, transport_rtp, ast_sockaddr_stringify(addr));
return &ast_null_frame;
}
do {
@@ -6055,8 +6115,8 @@
first_word = ntohl(rtcpheader[position]);
} while ((first_word & RTCP_VERSION_MASK_SHIFTED) == RTCP_VERSION_SHIFTED);
if (position != packetwords) {
- ast_debug(1, "%p -- RTCP from %s: Failed packet version or length check\n",
- transport_rtp, ast_sockaddr_stringify(addr));
+ ast_debug_rtcp(1, "(%p) RTCP %p -- from %s: Failed packet version or length check\n",
+ instance, transport_rtp, ast_sockaddr_stringify(addr));
return &ast_null_frame;
}
@@ -6146,8 +6206,8 @@
min_length = length;
break;
default:
- ast_debug(1, "%p -- RTCP from %s: %u(%s) skipping record\n",
- transport_rtp, ast_sockaddr_stringify(addr), pt, rtcp_payload_type2str(pt));
+ ast_debug_rtcp(1, "(%p) RTCP %p -- from %s: %u(%s) skipping record\n",
+ instance, transport_rtp, ast_sockaddr_stringify(addr), pt, rtcp_payload_type2str(pt));
if (rtcp_debug_test_addr(addr)) {
ast_verbose("\n");
ast_verbose("RTCP from %s: %u(%s) skipping record\n",
@@ -6157,8 +6217,8 @@
continue;
}
if (length < min_length) {
- ast_debug(1, "%p -- RTCP from %s: %u(%s) length field less than expected minimum. Min:%u Got:%u\n",
- transport_rtp, ast_sockaddr_stringify(addr), pt, rtcp_payload_type2str(pt),
+ ast_debug_rtcp(1, "(%p) RTCP %p -- from %s: %u(%s) length field less than expected minimum. Min:%u Got:%u\n",
+ instance, transport_rtp, ast_sockaddr_stringify(addr), pt, rtcp_payload_type2str(pt),
min_length - 1, length - 1);
return &ast_null_frame;
}
@@ -6248,8 +6308,8 @@
* for a different stream.
*/
position += length;
- ast_debug(1, "%p -- RTCP from %s: Skipping record, received SSRC '%u' != expected '%u'\n",
- rtp, ast_sockaddr_stringify(addr), ssrc, rtp->themssrc);
+ ast_debug_rtcp(1, "(%p) RTCP %p -- from %s: Skipping record, received SSRC '%u' != expected '%u'\n",
+ instance, rtp, ast_sockaddr_stringify(addr), ssrc, rtp->themssrc);
if (child) {
ao2_unlock(child);
}
@@ -6262,9 +6322,9 @@
/* Send to whoever sent to us */
if (ast_sockaddr_cmp(&rtp->rtcp->them, addr)) {
ast_sockaddr_copy(&rtp->rtcp->them, addr);
- if (rtpdebug) {
- ast_debug(0, "RTCP NAT: Got RTCP from other end. Now sending to address %s\n",
- ast_sockaddr_stringify(addr));
+ if (ast_debug_rtp_packet_is_allowed) {
+ ast_debug(0, "(%p) RTCP NAT: Got RTCP from other end. Now sending to address %s\n",
+ instance, ast_sockaddr_stringify(addr));
}
}
}
@@ -6527,12 +6587,12 @@
if (ast_sockaddr_is_ipv4(&addr)) {
ast_sockaddr_to_sin(&addr, &addr_tmp);
} else if (ast_sockaddr_ipv4_mapped(&addr, &addr_v4)) {
- ast_debug(1, "Using IPv6 mapped address %s for STUN\n",
- ast_sockaddr_stringify(&addr));
+ ast_debug_stun(2, "(%p) STUN using IPv6 mapped address %s\n",
+ instance, ast_sockaddr_stringify(&addr));
ast_sockaddr_to_sin(&addr_v4, &addr_tmp);
} else {
- ast_debug(1, "Cannot do STUN for non IPv4 address %s\n",
- ast_sockaddr_stringify(&addr));
+ ast_debug_stun(2, "(%p) STUN cannot do for non IPv4 address %s\n",
+ instance, ast_sockaddr_stringify(&addr));
return &ast_null_frame;
}
if ((ast_stun_handle_packet(rtp->rtcp->s, &addr_tmp, read_area, res, NULL, NULL) == AST_STUN_ACCEPT)) {
@@ -6579,7 +6639,7 @@
/* If the payload coming in is not one of the negotiated ones then send it to the core, this will cause formats to change and the bridge to break */
if (ast_rtp_codecs_find_payload_code(ast_rtp_instance_get_codecs(instance1), bridged_payload) == -1) {
- ast_debug(1, "Unsupported payload type received \n");
+ ast_debug_rtp(1, "(%p, %p) RTP unsupported payload type received\n", instance, instance1);
return -1;
}
@@ -6589,7 +6649,7 @@
* core so they can be filtered accordingly.
*/
if (rtp->last_end_timestamp == timestamp) {
- ast_debug(1, "Feeding packet with duplicate timestamp to core\n");
+ ast_debug_rtp(1, "(%p, %p) RTP feeding packet with duplicate timestamp to core\n", instance, instance1);
return -1;
}
@@ -6621,7 +6681,7 @@
/* If bridged peer is in dtmf, feed all packets to core until it finishes to avoid infinite dtmf */
if (bridged->sending_digit) {
- ast_debug(1, "Feeding packet to core until DTMF finishes\n");
+ ast_debug_rtp(1, "(%p, %p) RTP Feeding packet to core until DTMF finishes\n", instance, instance1);
ao2_unlock(instance1);
ao2_lock(instance);
return -1;
@@ -6635,8 +6695,8 @@
if (!bridged->asymmetric_codec
&& bridged->lastrxformat != ast_format_none
&& ast_format_cmp(payload_type->format, bridged->lastrxformat) == AST_FORMAT_CMP_NOT_EQUAL) {
- ast_debug(1, "Asymmetric RTP codecs detected (TX: %s, RX: %s) sending frame to core\n",
- ast_format_get_name(payload_type->format),
+ ast_debug_rtp(1, "(%p, %p) RTP asymmetric RTP codecs detected (TX: %s, RX: %s) sending frame to core\n",
+ instance, instance1, ast_format_get_name(payload_type->format),
ast_format_get_name(bridged->lastrxformat));
ao2_unlock(instance1);
ao2_lock(instance);
@@ -6649,7 +6709,8 @@
ast_rtp_instance_get_remote_address(instance1, &remote_address);
if (ast_sockaddr_isnull(&remote_address)) {
- ast_debug(5, "Remote address is null, most likely RTP has been stopped\n");
+ ast_debug_rtp(5, "(%p, %p) RTP remote address is null, most likely RTP has been stopped\n",
+ instance, instance1);
ao2_unlock(instance1);
ao2_lock(instance);
return 0;
@@ -6686,8 +6747,8 @@
"RTP Transmission error of packet to %s: %s\n",
ast_sockaddr_stringify(&remote_address),
strerror(errno));
- } else if (((ast_test_flag(bridged, FLAG_NAT_ACTIVE) == FLAG_NAT_INACTIVE) || rtpdebug) && !ast_test_flag(bridged, FLAG_NAT_INACTIVE_NOWARN)) {
- if (rtpdebug || DEBUG_ATLEAST(1)) {
+ } else if (((ast_test_flag(bridged, FLAG_NAT_ACTIVE) == FLAG_NAT_INACTIVE) || ast_debug_rtp_packet_is_allowed) && !ast_test_flag(bridged, FLAG_NAT_INACTIVE_NOWARN)) {
+ if (ast_debug_rtp_packet_is_allowed || DEBUG_ATLEAST(1)) {
ast_log(LOG_WARNING,
"RTP NAT: Can't write RTP to private "
"address %s, waiting for other end to "
@@ -6965,8 +7026,8 @@
/* The packet is now fully constructed so send it out */
ast_sockaddr_copy(&remote_address, &rtp->rtcp->them);
- ast_debug(2, "Sending transport-cc feedback packet of size '%d' on '%s' with packet count of %d (small = %d, large = %d, lost = %d)\n",
- packet_len, ast_rtp_instance_get_channel_id(instance), packet_count, small_delta_count, large_delta_count, lost_count);
+ ast_debug_rtcp(2, "(%p) RTCP sending transport-cc feedback packet of size '%d' on '%s' with packet count of %d (small = %d, large = %d, lost = %d)\n",
+ instance, packet_len, ast_rtp_instance_get_channel_id(instance), packet_count, small_delta_count, large_delta_count, lost_count);
res = rtcp_sendto(instance, (unsigned int *)rtcpheader, packet_len, 0, &remote_address, &ice);
if (res < 0) {
@@ -7026,7 +7087,7 @@
/* If we have not yet scheduled the periodic sending of feedback for this transport then do so */
if (transport_rtp->transport_wide_cc.schedid < 0 && transport_rtp->rtcp) {
- ast_debug(1, "Starting RTCP transport-cc feedback transmission on RTP instance '%p'\n", transport);
+ ast_debug_rtcp(1, "(%p) RTCP starting transport-cc feedback transmission on RTP instance '%p'\n", instance, transport);
ao2_ref(transport, +1);
transport_rtp->transport_wide_cc.schedid = ast_sched_add(rtp->sched, 1000,
rtp_transport_wide_cc_feedback_produce, transport);
@@ -7460,12 +7521,12 @@
if (ast_sockaddr_is_ipv4(&addr)) {
ast_sockaddr_to_sin(&addr, &addr_tmp);
} else if (ast_sockaddr_ipv4_mapped(&addr, &addr_v4)) {
- ast_debug(1, "Using IPv6 mapped address %s for STUN\n",
- ast_sockaddr_stringify(&addr));
+ ast_debug_stun(1, "(%p) STUN using IPv6 mapped address %s\n",
+ instance, ast_sockaddr_stringify(&addr));
ast_sockaddr_to_sin(&addr_v4, &addr_tmp);
} else {
- ast_debug(1, "Cannot do STUN for non IPv4 address %s\n",
- ast_sockaddr_stringify(&addr));
+ ast_debug_stun(1, "(%p) STUN cannot do for non IPv4 address %s\n",
+ instance, ast_sockaddr_stringify(&addr));
return &ast_null_frame;
}
if ((ast_stun_handle_packet(rtp->s, &addr_tmp, read_area, res, NULL, NULL) == AST_STUN_ACCEPT) &&
@@ -7611,8 +7672,8 @@
break;
}
/* Not ready to accept the RTP stream candidate */
- ast_debug(1, "%p -- Received RTP packet from %s, dropping due to strict RTP protection. Will switch to it in %d packets.\n",
- rtp, ast_sockaddr_stringify(&addr), rtp->rtp_source_learn.packets);
+ ast_debug_rtp(1, "(%p) RTP %p -- Received packet from %s, dropping due to strict RTP protection. Will switch to it in %d packets.\n",
+ instance, rtp, ast_sockaddr_stringify(&addr), rtp->rtp_source_learn.packets);
} else {
/*
* This is either an attacking stream or
@@ -7620,8 +7681,8 @@
*/
ast_sockaddr_copy(&rtp->rtp_source_learn.proposed_address, &addr);
rtp_learning_seq_init(&rtp->rtp_source_learn, seqno);
- ast_debug(1, "%p -- Received RTP packet from %s, dropping due to strict RTP protection. Qualifying new stream.\n",
- rtp, ast_sockaddr_stringify(&addr));
+ ast_debug_rtp(1, "(%p) RTP %p -- Received packet from %s, dropping due to strict RTP protection. Qualifying new stream.\n",
+ instance, rtp, ast_sockaddr_stringify(&addr));
}
return &ast_null_frame;
}
@@ -7639,8 +7700,8 @@
if (!ast_sockaddr_cmp(&rtp->strict_rtp_address, &addr)) {
break;
}
- ast_debug(1, "%p -- Received RTP packet from %s, dropping due to strict RTP protection.\n",
- rtp, ast_sockaddr_stringify(&addr));
+ ast_debug_rtp(1, "(%p) RTP %p -- Received packet from %s, dropping due to strict RTP protection.\n",
+ instance, rtp, ast_sockaddr_stringify(&addr));
#ifdef TEST_FRAMEWORK
{
static int strict_rtp_test_event = 1;
@@ -7667,9 +7728,9 @@
ast_sockaddr_set_port(&rtp->rtcp->them, ast_sockaddr_port(&addr) + 1);
}
ast_set_flag(rtp, FLAG_NAT_ACTIVE);
- if (rtpdebug)
- ast_debug(0, "RTP NAT: Got audio from other end. Now sending to address %s\n",
- ast_sockaddr_stringify(&remote_address));
+ if (ast_debug_rtp_packet_is_allowed)
+ ast_debug(0, "(%p) RTP NAT: Got audio from other end. Now sending to address %s\n",
+ instance, ast_sockaddr_stringify(&remote_address));
}
}
@@ -7697,8 +7758,8 @@
};
if (!mark) {
- if (rtpdebug) {
- ast_debug(1, "Forcing Marker bit, because SSRC has changed\n");
+ if (ast_debug_rtp_packet_is_allowed) {
+ ast_debug(0, "(%p) RTP forcing Marker bit, because SSRC has changed\n", instance);
}
mark = 1;
}
@@ -7750,8 +7811,8 @@
if (!AST_VECTOR_REMOVE_CMP_ORDERED(&rtp->missing_seqno, seqno, find_by_value,
AST_VECTOR_ELEM_CLEANUP_NOOP)) {
- ast_debug(2, "Packet with sequence number '%d' on RTP instance '%p' is no longer missing\n",
- seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP Packet with sequence number '%d' on instance is no longer missing\n",
+ instance, seqno);
}
/* If we don't have the next packet after this we can directly return the frame, as there is no
@@ -7793,8 +7854,8 @@
return AST_LIST_FIRST(&frames);
}
- ast_debug(2, "Pulled buffered packet with sequence number '%d' to additionally return on RTP instance '%p'\n",
- frame->seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP pulled buffered packet with sequence number '%d' to additionally return\n",
+ instance, frame->seqno);
AST_LIST_INSERT_TAIL(&frames, frame, frame_list);
prev_seqno = rtp->expectedrxseqno;
rtp->expectedrxseqno++;
@@ -7815,7 +7876,7 @@
*/
if (rtp->rtp_source_learn.stream_type == AST_MEDIA_TYPE_VIDEO) {
- ast_debug(2, "Source on RTP instance '%p' has wild gap or packet loss, sending FIR\n",
+ ast_debug_rtp(2, "(%p) RTP source has wild gap or packet loss, sending FIR\n",
instance);
rtp_write_rtcp_fir(instance, rtp, &remote_address);
}
@@ -7833,8 +7894,8 @@
if (frame) {
AST_LIST_INSERT_TAIL(&frames, frame, frame_list);
prev_seqno = seqno;
- ast_debug(2, "Inserted just received packet with sequence number '%d' in correct order on RTP instance '%p'\n",
- seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP inserted just received packet with sequence number '%d' in correct order\n",
+ instance, seqno);
}
/* It is possible due to packet retransmission for this packet to also exist in the receive
* buffer so we explicitly remove it in case this occurs, otherwise the receive buffer will
@@ -7858,8 +7919,8 @@
if (frame) {
AST_LIST_INSERT_TAIL(&frames, frame, frame_list);
prev_seqno = rtp->expectedrxseqno;
- ast_debug(2, "Emptying queue and returning packet with sequence number '%d' from RTP instance '%p'\n",
- frame->seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP emptying queue and returning packet with sequence number '%d'\n",
+ instance, frame->seqno);
}
ast_free(payload);
}
@@ -7883,8 +7944,8 @@
rtp->expectedrxseqno = 0;
}
- ast_debug(2, "Adding just received packet with sequence number '%d' to end of dumped queue on RTP instance '%p'\n",
- seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP adding just received packet with sequence number '%d' to end of dumped queue\n",
+ instance, seqno);
}
/* When we flush increase our chance for next time by growing the receive buffer when possible
@@ -7892,7 +7953,7 @@
*/
ast_data_buffer_resize(rtp->recv_buffer, MIN(MAXIMUM_RTP_RECV_BUFFER_SIZE,
ast_data_buffer_max(rtp->recv_buffer) + AST_VECTOR_SIZE(&rtp->missing_seqno)));
- ast_debug(2, "Receive buffer on RTP instance '%p' is now at maximum of %zu\n", instance, ast_data_buffer_max(rtp->recv_buffer));
+ ast_debug_rtp(2, "(%p) RTP receive buffer is now at maximum of %zu\n", instance, ast_data_buffer_max(rtp->recv_buffer));
/* As there is such a large gap we don't want to flood the order side with missing packets, so we
* give up and start anew.
@@ -7918,13 +7979,13 @@
if ((seqno < rtp->expectedrxseqno && ((rtp->expectedrxseqno - seqno) <= OLD_PACKET_COUNT)) ||
(seqno > rtp->expectedrxseqno && (seqno >= (65535 - OLD_PACKET_COUNT + rtp->expectedrxseqno)))) {
/* If this is a packet from the past then we have received a duplicate packet, so just drop it */
- ast_debug(2, "Received an old packet with sequence number '%d' on RTP instance '%p', dropping it\n",
- seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP received an old packet with sequence number '%d', dropping it\n",
+ instance, seqno);
return &ast_null_frame;
} else if (ast_data_buffer_get(rtp->recv_buffer, seqno)) {
/* If this is a packet we already have buffered then it is a duplicate, so just drop it */
- ast_debug(2, "Received a duplicate transmission of packet with sequence number '%d' on RTP instance '%p', dropping it\n",
- seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP received a duplicate transmission of packet with sequence number '%d', dropping it\n",
+ instance, seqno);
return &ast_null_frame;
} else {
/* This is an out of order packet from the future */
@@ -7933,8 +7994,8 @@
int remove_failed;
unsigned int missing_seqnos_added = 0;
- ast_debug(2, "Received an out of order packet with sequence number '%d' while expecting '%d' from the future on RTP instance '%p'\n",
- seqno, rtp->expectedrxseqno, instance);
+ ast_debug_rtp(2, "(%p) RTP received an out of order packet with sequence number '%d' while expecting '%d' from the future\n",
+ instance, seqno, rtp->expectedrxseqno);
payload = ast_malloc(sizeof(*payload) + res);
if (!payload) {
@@ -7961,8 +8022,8 @@
remove_failed = AST_VECTOR_REMOVE_CMP_ORDERED(&rtp->missing_seqno, seqno, find_by_value,
AST_VECTOR_ELEM_CLEANUP_NOOP);
if (!remove_failed) {
- ast_debug(2, "Packet with sequence number '%d' on RTP instance '%p' is no longer missing\n",
- seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP packet with sequence number '%d' is no longer missing\n",
+ instance, seqno);
}
/* The missing sequence number code works by taking the sequence number of the
@@ -8008,8 +8069,8 @@
continue;
}
- ast_debug(2, "Added missing sequence number '%d' to RTP instance '%p'\n",
- missing_seqno, instance);
+ ast_debug_rtp(2, "(%p) RTP added missing sequence number '%d'\n",
+ instance, missing_seqno);
AST_VECTOR_ADD_SORTED(&rtp->missing_seqno, missing_seqno,
compare_by_value);
missing_seqnos_added++;
@@ -8039,7 +8100,7 @@
*/
rtcpheader = ast_malloc(sizeof(*rtcpheader) + data_size);
if (!rtcpheader) {
- ast_debug(1, "Failed to allocate memory for NACK\n");
+ ast_debug_rtcp(1, "(%p) RTCP failed to allocate memory for NACK\n", instance);
return &ast_null_frame;
}
@@ -8056,7 +8117,7 @@
res = ast_rtcp_generate_nack(instance, rtcpheader + packet_len);
if (res == 0) {
- ast_debug(1, "Failed to construct NACK, stopping here\n");
+ ast_debug_rtcp(1, "(%p) RTCP failed to construct NACK, stopping here\n", instance);
return &ast_null_frame;
}
@@ -8064,9 +8125,9 @@
res = rtcp_sendto(instance, rtcpheader, packet_len, 0, &remote_address, &ice);
if (res < 0) {
- ast_debug(1, "Failed to send NACK request out\n");
+ ast_debug_rtcp(1, "(%p) RTCP failed to send NACK request out\n", instance);
} else {
- ast_debug(2, "Sending a NACK request on RTP instance '%p' to get missing packets\n", instance);
+ ast_debug_rtcp(2, "(%p) RTCP sending a NACK request to get missing packets\n", instance);
/* Update RTCP SR/RR statistics */
ast_rtcp_calculate_sr_rr_statistics(instance, rtcp_report, remote_address, ice, sr);
}
@@ -8086,7 +8147,7 @@
struct ast_sockaddr local_addr;
if (rtp->rtcp && rtp->rtcp->type == value) {
- ast_debug(1, "Ignoring duplicate RTCP property on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP ignoring duplicate property\n", instance);
return;
}
@@ -8138,7 +8199,7 @@
AF_INET :
ast_sockaddr_is_ipv6(&rtp->rtcp->us) ?
AF_INET6 : -1)) < 0) {
- ast_debug(1, "Failed to create a new socket for RTCP on instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP failed to create a new socket\n", instance);
ast_free(rtp->rtcp->local_addr_str);
ast_free(rtp->rtcp);
rtp->rtcp = NULL;
@@ -8147,7 +8208,7 @@
/* Try to actually bind to the IP address and port we are going to use for RTCP, if this fails we have to bail out */
if (ast_bind(rtp->rtcp->s, &rtp->rtcp->us)) {
- ast_debug(1, "Failed to setup RTCP on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP failed to setup RTP instance\n", instance);
close(rtp->rtcp->s);
ast_free(rtp->rtcp->local_addr_str);
ast_free(rtp->rtcp);
@@ -8187,7 +8248,7 @@
#endif
}
- ast_debug(1, "Setup RTCP on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP setup on RTP instance\n", instance);
} else {
if (rtp->rtcp) {
if (rtp->rtcp->schedid > -1) {
@@ -8197,7 +8258,7 @@
ao2_ref(instance, -1);
} else {
/* Unable to cancel scheduler entry */
- ast_debug(1, "Failed to tear down RTCP on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP failed to tear down RTCP\n", instance);
ao2_lock(instance);
return;
}
@@ -8209,7 +8270,7 @@
if (!ast_sched_del(rtp->sched, rtp->transport_wide_cc.schedid)) {
ao2_ref(instance, -1);
} else {
- ast_debug(1, "Failed to tear down RTCP transport-cc feedback on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP failed to tear down transport-cc feedback\n", instance);
ao2_lock(instance);
return;
}
@@ -8289,7 +8350,7 @@
}
if (rtp->rtcp && !ast_sockaddr_isnull(addr)) {
- ast_debug(1, "Setting RTCP address on RTP instance '%p'\n", instance);
+ ast_debug_rtcp(1, "(%p) RTCP setting address on RTP instance\n", instance);
ast_sockaddr_copy(&rtp->rtcp->them, addr);
if (rtp->rtcp->type == AST_RTP_INSTANCE_RTCP_STANDARD) {
@@ -8785,7 +8846,7 @@
}
#endif
- ast_debug(3, "ast_rtp_activate (%p) - setup and perform DTLS'\n", rtp);
+ ast_debug_dtls(3, "(%p) DTLS - ast_rtp_activate rtp=%p - setup and perform DTLS'\n", instance, rtp);
dtls_perform_setup(&rtp->dtls);
dtls_perform_handshake(instance, &rtp->dtls, 0);
@@ -8810,9 +8871,9 @@
return CLI_FAILURE;
}
rtpdebugport = (!ast_strlen_zero(debugport) && debugport[0] != '0');
- ast_cli(a->fd, "RTP Debugging Enabled for address: %s\n",
+ ast_cli(a->fd, "RTP Packet Debugging Enabled for address: %s\n",
ast_sockaddr_stringify(&rtpdebugaddr));
- rtpdebug = 1;
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_RTP_PACKET, AST_LOG_CATEGORY_ENABLED);
return CLI_SUCCESS;
}
@@ -8827,9 +8888,9 @@
return CLI_FAILURE;
}
rtcpdebugport = (!ast_strlen_zero(debugport) && debugport[0] != '0');
- ast_cli(a->fd, "RTCP Debugging Enabled for address: %s\n",
+ ast_cli(a->fd, "RTCP Packet Debugging Enabled for address: %s\n",
ast_sockaddr_stringify(&rtcpdebugaddr));
- rtcpdebug = 1;
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_RTCP_PACKET, AST_LOG_CATEGORY_ENABLED);
return CLI_SUCCESS;
}
@@ -8850,13 +8911,13 @@
if (a->argc == e->args) { /* set on or off */
if (!strncasecmp(a->argv[e->args-1], "on", 2)) {
- rtpdebug = 1;
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_RTP_PACKET, AST_LOG_CATEGORY_ENABLED);
memset(&rtpdebugaddr, 0, sizeof(rtpdebugaddr));
- ast_cli(a->fd, "RTP Debugging Enabled\n");
+ ast_cli(a->fd, "RTP Packet Debugging Enabled\n");
return CLI_SUCCESS;
} else if (!strncasecmp(a->argv[e->args-1], "off", 3)) {
- rtpdebug = 0;
- ast_cli(a->fd, "RTP Debugging Disabled\n");
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_RTP_PACKET, AST_LOG_CATEGORY_DISABLED);
+ ast_cli(a->fd, "RTP Packet Debugging Disabled\n");
return CLI_SUCCESS;
}
} else if (a->argc == e->args +1) { /* ip */
@@ -8921,13 +8982,13 @@
if (a->argc == e->args) { /* set on or off */
if (!strncasecmp(a->argv[e->args-1], "on", 2)) {
- rtcpdebug = 1;
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_RTCP_PACKET, AST_LOG_CATEGORY_ENABLED);
memset(&rtcpdebugaddr, 0, sizeof(rtcpdebugaddr));
- ast_cli(a->fd, "RTCP Debugging Enabled\n");
+ ast_cli(a->fd, "RTCP Packet Debugging Enabled\n");
return CLI_SUCCESS;
} else if (!strncasecmp(a->argv[e->args-1], "off", 3)) {
- rtcpdebug = 0;
- ast_cli(a->fd, "RTCP Debugging Disabled\n");
+ ast_debug_category_set_sublevel(AST_LOG_CATEGORY_RTCP_PACKET, AST_LOG_CATEGORY_DISABLED);
+ ast_cli(a->fd, "RTCP Packet Debugging Disabled\n");
return CLI_SUCCESS;
}
} else if (a->argc == e->args +1) { /* ip */
--
To view, visit https://gerrit.asterisk.org/c/asterisk/+/14887
To unsubscribe, or for help writing mail filters, visit https://gerrit.asterisk.org/settings
Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Change-Id: I6e6cb247bb1f01dbf34750b2cd98e5b5b41a1849
Gerrit-Change-Number: 14887
Gerrit-PatchSet: 7
Gerrit-Owner: Kevin Harwell <kharwell 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/20201002/0b42931e/attachment-0001.html>
More information about the asterisk-code-review
mailing list