PJPROJECT logging: Made easier to get available logging levels.

Use of the new logging is as simple as issuing the new CLI command or
setting the new pjproject.conf option.

Other options that can affect the logging are how you have the pjproject
log levels mapped to Asterisk log types in pjproject.conf and if you have
configured Asterisk to log the DEBUG type messages.  Altering the
pjproject.conf level mapping shouldn't be necessary for most installations
as the default mapping is sensible.  Configuring Asterisk to log the DEBUG
message type is standard practice for collecting debug information.

* Added CLI "pjproject set log level" command to dynamically adjust the
maximum pjproject log message level.

* Added CLI "pjproject show log level" command to see the currently set
maximum pjproject log message level.

* Added pjproject.conf startup section "log_level" option to set the
initial maximum pjproject log message level so all messages could be
captured from initialization.

* Set PJ_LOG_MAX_LEVEL to 6 to compile in all defined logging levels into
bundled pjproject.  Pjproject will use the currently set run time log
level to determine if a log message is generated just like Asterisk
verbose and debug logging levels.

* In log_forwarder(), made always log enabled and mapped pjproject log
messages.  DEBUG mapped log messages are no longer gated by the current
Asterisk debug logging level.

* Removed RAII_VAR() from res_pjproject.c:get_log_level().

ASTERISK-26630 #close

Change-Id: I6dca12979f482ffb0450aaf58db0fe0f6d2e5389

8 files changed, 221 insertions, 19 deletions

diff --git a/CHANGES b/CHANGES
index adba9847e..e08d9cdc6 100644
--- a/CHANGES
+++ b/CHANGES
@@ -9,6 +9,23 @@
 ==============================================================================
 
 ------------------------------------------------------------------------------
+--- Functionality changes from Asterisk 13.13.0 to Asterisk 13.14.0 ----------
+------------------------------------------------------------------------------
+
+res_pjproject
+------------------
+ * Added new CLI command "pjproject set log level".  The new command allows
+   the maximum PJPROJECT log levels to be adjusted dynamically and
+   independently from the set debug logging level like many other similar
+   module debug logging commands.
+
+ * Added new companion CLI command "pjproject show log level" to allow the
+   user to see the current maximum pjproject logging level.
+
+ * Added new pjproject.conf startup section "log_level' option to set the
+   initial maximum PJPROJECT logging level.
+
+------------------------------------------------------------------------------
 --- Functionality changes from Asterisk 13.12.0 to Asterisk 13.13.0 ----------
 ------------------------------------------------------------------------------
 
diff --git a/configs/samples/pjproject.conf.sample b/configs/samples/pjproject.conf.sample
index 97af7345f..82c81a1f6 100644
--- a/configs/samples/pjproject.conf.sample
+++ b/configs/samples/pjproject.conf.sample
@@ -1,15 +1,36 @@
 ; Common pjproject options
 ;
 
+;[startup]
+;  NOTES: The name of this section in the pjproject.conf configuration file must
+;         remain startup or the configuration will not be applied.
+;
+;log_level=default   ; Initial maximum pjproject logging level to log
+                     ; Valid values are: 0-6, and default
+                     ;
+                     ; Note: This option is needed very early in the startup
+                     ; process so it can only be read from config files because
+                     ; the modules for other methods have not been loaded yet.
+;type=               ; Must be of type startup (default: "")
+
 ;========================LOG_MAPPINGS SECTION OPTIONS===============================
 ;[log_mappings]
 ;  SYNOPSIS: Provides pjproject to Asterisk log level mappings.
 ;  NOTES: The name of this section in the pjproject.conf configuration file must
 ;         remain log_mappings or the configuration will not be applied.
 ;         The defaults mentioned below only apply if this file or the 'log_mappings'
-;         object can'tbe found.  If the object is found, there are no defaults. If
+;         object can't be found.  If the object is found, there are no defaults. If
 ;         you don't specify an entry, nothing will be logged for that level.
 ;
+; These logging level meanings are typically used by pjproject:
+;  - 0: fatal error
+;  - 1: error
+;  - 2: warning
+;  - 3: info
+;  - 4: debug
+;  - 5: trace
+;  - 6: more detailed trace
+;
 ;asterisk_error =    ; A comma separated list of pjproject log levels to map to
                      ; Asterisk errors.
                      ; (default: "0,1")
@@ -24,5 +45,5 @@
                      ; (default: "")
 ;asterisk_debug =    ; A comma separated list of pjproject log levels to map to
                      ; Asterisk debug
-                     ; (default: "3,4,5")
+                     ; (default: "3,4,5,6")
 ;type=               ; Must be of type log_mappings (default: "")
diff --git a/include/asterisk/options.h b/include/asterisk/options.h
index 21bd7a704..0f8c6f87e 100644
--- a/include/asterisk/options.h
+++ b/include/asterisk/options.h
@@ -132,6 +132,20 @@ enum ast_option_flags {
 #define ast_opt_lock_confdir		ast_test_flag(&ast_options, AST_OPT_FLAG_LOCK_CONFIG_DIR)
 #define ast_opt_generic_plc         ast_test_flag(&ast_options, AST_OPT_FLAG_GENERIC_PLC)
 
+/*! Maximum log level defined by PJPROJECT. */
+#define MAX_PJ_LOG_MAX_LEVEL		6
+/*!
+ * Normal PJPROJECT active log level used by Asterisk.
+ *
+ * These levels are usually mapped to Error and
+ * Warning Asterisk log levels which shouldn't
+ * normally be suppressed.
+ */
+#define DEFAULT_PJ_LOG_MAX_LEVEL	2
+
+/*! Current pjproject logging level */
+extern int ast_option_pjproject_log_level;
+
 extern struct ast_flags ast_options;
 
 extern int option_verbose;
diff --git a/main/asterisk.c b/main/asterisk.c
index 746823ef5..2236e8c69 100644
--- a/main/asterisk.c
+++ b/main/asterisk.c
@@ -325,6 +325,7 @@ int ast_verb_sys_level;
 
 int option_verbose;				/*!< Verbosity level */
 int option_debug;				/*!< Debug level */
+int ast_option_pjproject_log_level;
 double ast_option_maxload;			/*!< Max load avg on system */
 int ast_option_maxcalls;			/*!< Max number of active calls */
 int ast_option_maxfiles;			/*!< Max number of open file handles (files, sockets) */
@@ -3891,6 +3892,37 @@ static void ast_readconfig(void)
 	ast_config_destroy(cfg);
 }
 
+static void read_pjproject_startup_options(void)
+{
+	struct ast_config *cfg;
+	struct ast_variable *v;
+	struct ast_flags config_flags = { CONFIG_FLAG_NOCACHE | CONFIG_FLAG_NOREALTIME };
+
+	ast_option_pjproject_log_level = DEFAULT_PJ_LOG_MAX_LEVEL;
+
+	cfg = ast_config_load2("pjproject.conf", "" /* core, can't reload */, config_flags);
+	if (!cfg
+		|| cfg == CONFIG_STATUS_FILEUNCHANGED
+		|| cfg == CONFIG_STATUS_FILEINVALID) {
+		/* We'll have to use defaults */
+		return;
+	}
+
+	for (v = ast_variable_browse(cfg, "startup"); v; v = v->next) {
+		if (!strcasecmp(v->name, "log_level")) {
+			if (sscanf(v->value, "%30d", &ast_option_pjproject_log_level) != 1) {
+				ast_option_pjproject_log_level = DEFAULT_PJ_LOG_MAX_LEVEL;
+			} else if (ast_option_pjproject_log_level < 0) {
+				ast_option_pjproject_log_level = 0;
+			} else if (MAX_PJ_LOG_MAX_LEVEL < ast_option_pjproject_log_level) {
+				ast_option_pjproject_log_level = MAX_PJ_LOG_MAX_LEVEL;
+			}
+		}
+	}
+
+	ast_config_destroy(cfg);
+}
+
 static void *monitor_sig_flags(void *unused)
 {
 	for (;;) {
@@ -4612,6 +4644,7 @@ static void asterisk_daemon(int isroot, const char *runuser, const char *rungrou
 
 	check_init(ast_timing_init(), "Timing");
 	check_init(ast_ssl_init(), "SSL");
+	read_pjproject_startup_options();
 	check_init(ast_pj_init(), "Embedded PJProject");
 	check_init(app_init(), "App Core");
 	check_init(devstate_init(), "Device State Core");
diff --git a/main/libasteriskpj.c b/main/libasteriskpj.c
index aed0ec8b1..2d92b599d 100644
--- a/main/libasteriskpj.c
+++ b/main/libasteriskpj.c
@@ -37,6 +37,7 @@ ASTERISK_REGISTER_FILE()
 #include <pjlib.h>
 #endif
 
+#include "asterisk/options.h"
 #include "asterisk/_private.h" /* ast_pj_init() */
 
 /*!
@@ -46,6 +47,7 @@ ASTERISK_REGISTER_FILE()
 int ast_pj_init(void)
 {
 #ifdef HAVE_PJPROJECT_BUNDLED
+	pj_log_set_level(ast_option_pjproject_log_level);
 	pj_init();
 #endif
 	return 0;
diff --git a/res/res_pjproject.c b/res/res_pjproject.c
index 08699f3ee..cd562663b 100644
--- a/res/res_pjproject.c
+++ b/res/res_pjproject.c
@@ -41,6 +41,27 @@
 	<configInfo name="res_pjproject" language="en_US">
 		<synopsis>pjproject common configuration</synopsis>
 		<configFile name="pjproject.conf">
+			<configObject name="startup">
+				<synopsis>Asterisk startup time options for PJPROJECT</synopsis>
+				<description>
+					<note><para>The id of this object, as well as its type, must be
+					'startup' or it won't be found.</para></note>
+				</description>
+				<configOption name="type">
+					<synopsis>Must be of type 'startup'.</synopsis>
+				</configOption>
+				<configOption name="log_level" default="2">
+					<synopsis>Initial maximum pjproject logging level to log.</synopsis>
+					<description>
+						<para>Valid values are: 0-6, and default</para>
+					<note><para>
+						This option is needed very early in the startup process
+						so it can only be read from config files because the
+						modules for other methods have not been loaded yet.
+					</para></note>
+					</description>
+				</configOption>
+			</configObject>
 			<configObject name="log_mappings">
 				<synopsis>PJPROJECT to Asterisk Log Level Mapping</synopsis>
 				<description><para>Warnings and errors in the pjproject libraries are generally handled
@@ -64,7 +85,7 @@
 				<configOption name="asterisk_notice" default="">
 					<synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_NOTICE.</synopsis>
 				</configOption>
-				<configOption name="asterisk_debug" default="3,4,5">
+				<configOption name="asterisk_debug" default="3,4,5,6">
 					<synopsis>A comma separated list of pjproject log levels to map to Asterisk LOG_DEBUG.</synopsis>
 				</configOption>
 				<configOption name="asterisk_verbose" default="">
@@ -84,6 +105,7 @@ ASTERISK_REGISTER_FILE()
 #include <pjsip.h>
 #include <pj/log.h>
 
+#include "asterisk/options.h"
 #include "asterisk/logger.h"
 #include "asterisk/module.h"
 #include "asterisk/cli.h"
@@ -146,9 +168,11 @@ static struct log_mappings *get_log_mappings(void)
 
 static int get_log_level(int pj_level)
 {
-	RAII_VAR(struct log_mappings *, mappings, get_log_mappings(), ao2_cleanup);
+	int mapped_level;
 	unsigned char l;
+	struct log_mappings *mappings;
 
+	mappings = get_log_mappings();
 	if (!mappings) {
 		return __LOG_ERROR;
 	}
@@ -156,18 +180,21 @@ static int get_log_level(int pj_level)
 	l = '0' + fmin(pj_level, 9);
 
 	if (strchr(mappings->asterisk_error, l)) {
-		return __LOG_ERROR;
+		mapped_level = __LOG_ERROR;
 	} else if (strchr(mappings->asterisk_warning, l)) {
-		return __LOG_WARNING;
+		mapped_level = __LOG_WARNING;
 	} else if (strchr(mappings->asterisk_notice, l)) {
-		return __LOG_NOTICE;
+		mapped_level = __LOG_NOTICE;
 	} else if (strchr(mappings->asterisk_verbose, l)) {
-		return __LOG_VERBOSE;
+		mapped_level = __LOG_VERBOSE;
 	} else if (strchr(mappings->asterisk_debug, l)) {
-		return __LOG_DEBUG;
+		mapped_level = __LOG_DEBUG;
+	} else {
+		mapped_level = __LOG_SUPPRESS;
 	}
 
-	return __LOG_SUPPRESS;
+	ao2_ref(mappings, -1);
+	return mapped_level;
 }
 
 static void log_forwarder(int level, const char *data, int len)
@@ -194,13 +221,6 @@ static void log_forwarder(int level, const char *data, int len)
 		return;
 	}
 
-	if (ast_level == __LOG_DEBUG) {
-		/* Obey the debug level for res_pjproject */
-		if (!DEBUG_ATLEAST(level)) {
-			return;
-		}
-	}
-
 	/* PJPROJECT uses indention to indicate function call depth. We'll prepend
 	 * log statements with a tab so they'll have a better shot at lining
 	 * up */
@@ -351,9 +371,95 @@ static char *handle_pjproject_show_log_mappings(struct ast_cli_entry *e, int cmd
 	return CLI_SUCCESS;
 }
 
+struct max_pjproject_log_level_check {
+	/*!
+	 * Compile time sanity check to determine if
+	 * MAX_PJ_LOG_MAX_LEVEL matches CLI syntax.
+	 */
+	char check[1 / (6 == MAX_PJ_LOG_MAX_LEVEL)];
+};
+
+static char *handle_pjproject_set_log_level(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
+{
+	int level_new;
+	int level_old;
+
+	switch (cmd) {
+	case CLI_INIT:
+		e->command = "pjproject set log level {default|0|1|2|3|4|5|6}";
+		e->usage =
+			"Usage: pjproject set log level {default|<level>}\n"
+			"\n"
+			"       Set the maximum active pjproject logging level.\n"
+			"       See pjproject.conf.sample for additional information\n"
+			"       about the various levels pjproject uses.\n";
+		return NULL;
+	case CLI_GENERATE:
+		return NULL;
+	}
+
+	if (a->argc != 5) {
+		return CLI_SHOWUSAGE;
+	}
+
+	if (!strcasecmp(a->argv[4], "default")) {
+		level_new = DEFAULT_PJ_LOG_MAX_LEVEL;
+	} else {
+		if (sscanf(a->argv[4], "%30d", &level_new) != 1
+			|| level_new < 0 || MAX_PJ_LOG_MAX_LEVEL < level_new) {
+			return CLI_SHOWUSAGE;
+		}
+	}
+
+	/* Update pjproject logging level */
+	level_old = ast_option_pjproject_log_level;
+	if (level_old == level_new) {
+		ast_cli(a->fd, "pjproject log level is still %d.\n", level_old);
+	} else {
+		ast_cli(a->fd, "pjproject log level was %d and is now %d.\n",
+			level_old, level_new);
+		pj_log_set_level(level_new);
+	}
+	ast_option_pjproject_log_level = pj_log_get_level();
+	if (ast_option_pjproject_log_level != level_new) {
+		ast_log(LOG_WARNING, "Asterisk built with pjproject PJ_LOG_MAX_LEVEL set too low.\n");
+	}
+
+	return CLI_SUCCESS;
+}
+
+static char *handle_pjproject_show_log_level(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
+{
+	switch (cmd) {
+	case CLI_INIT:
+		e->command = "pjproject show log level";
+		e->usage =
+			"Usage: pjproject show log level\n"
+			"\n"
+			"       Show the current maximum active pjproject logging level.\n"
+			"       See pjproject.conf.sample for additional information\n"
+			"       about the various levels pjproject uses.\n";
+		return NULL;
+	case CLI_GENERATE:
+		return NULL;
+	}
+
+	if (a->argc != 4) {
+		return CLI_SHOWUSAGE;
+	}
+
+	ast_cli(a->fd, "pjproject log level is %d.%s\n",
+		ast_option_pjproject_log_level,
+		ast_option_pjproject_log_level == DEFAULT_PJ_LOG_MAX_LEVEL ? " (default)" : "");
+
+	return CLI_SUCCESS;
+}
+
 static struct ast_cli_entry pjproject_cli[] = {
+	AST_CLI_DEFINE(handle_pjproject_set_log_level, "Set the maximum active pjproject logging level"),
 	AST_CLI_DEFINE(handle_pjproject_show_buildopts, "Show the compiled config of the pjproject in use"),
 	AST_CLI_DEFINE(handle_pjproject_show_log_mappings, "Show pjproject to Asterisk log mappings"),
+	AST_CLI_DEFINE(handle_pjproject_show_log_level, "Show the maximum active pjproject logging level"),
 };
 
 static int load_module(void)
@@ -387,10 +493,11 @@ static int load_module(void)
 	}
 	ast_string_field_set(default_log_mappings, asterisk_error, "0,1");
 	ast_string_field_set(default_log_mappings, asterisk_warning, "2");
-	ast_string_field_set(default_log_mappings, asterisk_debug, "3,4,5");
+	ast_string_field_set(default_log_mappings, asterisk_debug, "3,4,5,6");
 
 	ast_sorcery_load(pjproject_sorcery);
 
+	pj_log_set_level(ast_option_pjproject_log_level);
 	pj_init();
 
 	decor_orig = pj_log_get_decor();
@@ -405,9 +512,15 @@ static int load_module(void)
 	 */
 	pj_log_set_log_func(capture_buildopts_cb);
 	pj_log_set_decor(0);
+	pj_log_set_level(MAX_PJ_LOG_MAX_LEVEL);/* Set level to guarantee the dump output. */
 	pj_dump_config();
+	pj_log_set_level(ast_option_pjproject_log_level);
 	pj_log_set_decor(PJ_LOG_HAS_SENDER | PJ_LOG_HAS_INDENT);
 	pj_log_set_log_func(log_forwarder);
+	if (!AST_VECTOR_SIZE(&buildopts)
+		|| ast_option_pjproject_log_level != pj_log_get_level()) {
+		ast_log(LOG_WARNING, "Asterisk built or linked with pjproject PJ_LOG_MAX_LEVEL set too low.\n");
+	}
 
 	ast_cli_register_multiple(pjproject_cli, ARRAY_LEN(pjproject_cli));
 
diff --git a/res/res_rtp_asterisk.c b/res/res_rtp_asterisk.c
index b8cb10b30..64b13722f 100644
--- a/res/res_rtp_asterisk.c
+++ b/res/res_rtp_asterisk.c
@@ -54,6 +54,7 @@ ASTERISK_FILE_VERSION(__FILE__, "$Revision$")
 #include <ifaddrs.h>
 #endif
 
+#include "asterisk/options.h"
 #include "asterisk/stun.h"
 #include "asterisk/pbx.h"
 #include "asterisk/frame.h"
@@ -5668,6 +5669,7 @@ static int load_module(void)
 #ifdef HAVE_PJPROJECT
 	pj_lock_t *lock;
 
+	pj_log_set_level(ast_option_pjproject_log_level);
 	if (pj_init() != PJ_SUCCESS) {
 		return AST_MODULE_LOAD_DECLINE;
 	}
diff --git a/third-party/pjproject/patches/config_site.h b/third-party/pjproject/patches/config_site.h
index 1a48695bf..66e8e84d3 100644
--- a/third-party/pjproject/patches/config_site.h
+++ b/third-party/pjproject/patches/config_site.h
@@ -34,7 +34,7 @@
 
 #define PJ_SCANNER_USE_BITWISE	0
 #define PJ_OS_HAS_CHECK_STACK	0
-#define PJ_LOG_MAX_LEVEL		3
+#define PJ_LOG_MAX_LEVEL		6
 #define PJ_ENABLE_EXTRA_CHECK	1
 #define PJSIP_MAX_TSX_COUNT		((64*1024)-1)
 #define PJSIP_MAX_DIALOG_COUNT	((64*1024)-1)