Remote console: more output discrepancies

The remote console continued to have issues with its output.  In this case CLI
command output would either not show up (if verbose level = 0) or would contain
verbose prefixes (if verbose level > 0) once log messages were sent to the
remote console.  The fix now now adds verbose prefix data to all new lines
contained in a verbose log string.

(closes issue ASTERISK-22450)
Reported by: David Brillert
(closes issue AST-1193)
Reported by: Guenther Kelleter
Review: https://reviewboard.asterisk.org/r/2825/
........

Merged revisions 399267 from http://svn.asterisk.org/svn/asterisk/branches/11
........

Merged revisions 399268 from http://svn.asterisk.org/svn/asterisk/branches/12


git-svn-id: https://origsvn.digium.com/svn/asterisk/trunk@399269 65c4cc65-6c06-0410-ace0-fbb531ad65f3

2 files changed, 55 insertions, 50 deletions

diff --git a/main/asterisk.c b/main/asterisk.c
index 9d051c847..7e581513c 100644
--- a/main/asterisk.c
+++ b/main/asterisk.c
@@ -2056,14 +2056,12 @@ static const char *fix_header(char *outbuf, int maxout, const char *s, char leve
 }
 
 struct console_state_data {
-	int newline;
 	char verbose_line_level;
 };
 
 static int console_state_init(void *ptr)
 {
 	struct console_state_data *state = ptr;
-	state->newline = 1;
 	state->verbose_line_level = 0;
 	return 0;
 }
@@ -2076,42 +2074,40 @@ AST_THREADSTORAGE_CUSTOM(console_state, console_state_init, ast_free_ptr);
 #define VERBOSE_MAGIC2LEVEL(x) (((char) -*(signed char *) (x)) - 1)
 #define VERBOSE_HASMAGIC(x)	(*(signed char *) (x) < 0)
 
-static int console_log_verbose(const char *s)
+static int console_print(const char *s, int local)
 {
-	/* verbose level of 0 evaluates to a magic of -1, 1 to -2, etc...
-	   search up to -7 (level = 6) as this is currently the largest
-	   level used */
-	static const char find_set[9] = { -1, -2, -3, -4, -5, -6, -7, '\n'};
-
 	struct console_state_data *state =
 		ast_threadstorage_get(&console_state, sizeof(*state));
 
 	char prefix[80];
-	const char *c = s;
+	const char *c;
 	int num, res = 0;
+	unsigned int newline;
 
 	do {
 		if (VERBOSE_HASMAGIC(s)) {
-			/* if it has one always use the given line's level,
-			   otherwise we'll use the last line's level */
+			/* always use the given line's level, otherwise
+			   we'll use the last line's level */
 			state->verbose_line_level = VERBOSE_MAGIC2LEVEL(s);
 			/* move past magic */
 			s++;
-		}
-
-		c = fix_header(prefix, sizeof(prefix), s,
-			       state->verbose_line_level);
 
-		if (!state->newline) {
-			/* don't use the prefix if line continuation */
+			if (local) {
+				s = fix_header(prefix, sizeof(prefix), s,
+					       state->verbose_line_level);
+			}
+		} else {
 			*prefix = '\0';
 		}
+		c = s;
 
-		/* for a given line separate on verbose magic and newlines */
-		if (!(s = strpbrk(c, find_set))) {
-			s = strchr(c, '\0');
-		} else if (*s == '\n') {
+		/* for a given line separate on verbose magic, newline, and eol */
+		if ((s = strchr(c, '\n'))) {
 			++s;
+			newline = 1;
+		} else {
+			s = strchr(c, '\0');
+			newline = 0;
 		}
 
 		/* check if we should write this line after calculating begin/end
@@ -2121,8 +2117,7 @@ static int console_log_verbose(const char *s)
 			continue;
 		}
 
-		state->newline = *(s - 1) == '\n';
-		if (!ast_strlen_zero(prefix)) {
+		if (local && !ast_strlen_zero(prefix)) {
 			fputs(prefix, stdout);
 		}
 
@@ -2136,9 +2131,14 @@ static int console_log_verbose(const char *s)
 			   we'll want to return true */
 			res = 1;
 		}
-		c = s;
 	} while (*s);
 
+	if (newline) {
+		/* if ending on a newline then reset last level to zero
+		    since what follows may be not be logging output */
+		state->verbose_line_level = 0;
+	}
+
 	if (res) {
 		fflush(stdout);
 	}
@@ -2148,7 +2148,7 @@ static int console_log_verbose(const char *s)
 
 static void console_verboser(const char *s)
 {
-	if (!console_log_verbose(s)) {
+	if (!console_print(s, 1)) {
 		return;
 	}
 
@@ -2635,7 +2635,7 @@ static int ast_el_read_char(EditLine *editline, char *cp)
 				}
 			}
 
-			console_log_verbose(buf);
+			console_print(buf, 0);
 
 			if ((res < EL_BUF_SIZE - 1) && ((buf[res-1] == '\n') || (buf[res-2] == '\n'))) {
 				*cp = CC_REFRESH;
diff --git a/main/logger.c b/main/logger.c
index 06f8d4584..112456816 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -1603,10 +1603,11 @@ void ast_log_backtrace(void)
 
 void __ast_verbose_ap(const char *file, int line, const char *func, int level, struct ast_callid *callid, const char *fmt, va_list ap)
 {
-	struct ast_str *buf = NULL;
+	const char *p;
+	struct ast_str *prefixed, *buf = NULL;
 	int res = 0;
 	const char *prefix = level >= 4 ? VERBOSE_PREFIX_4 : level == 3 ? VERBOSE_PREFIX_3 : level == 2 ? VERBOSE_PREFIX_2 : level == 1 ? VERBOSE_PREFIX_1 : "";
-	signed char magic = level > 127 ? -128 : -level - 1; /* 0 => -1, 1 => -2, etc.  Can't pass NUL, as it is EOS-delimiter */
+	signed char magic = level > 9 ? -10 : -level - 1; /* 0 => -1, 1 => -2, etc.  Can't pass NUL, as it is EOS-delimiter */
 
 	/* For compatibility with modules still calling ast_verbose() directly instead of using ast_verb() */
 	if (level < 0) {
@@ -1623,37 +1624,41 @@ void __ast_verbose_ap(const char *file, int line, const char *func, int level, s
 		}
 	}
 
-	if (!(buf = ast_str_thread_get(&verbose_buf, VERBOSE_BUF_INIT_SIZE))) {
+	if (!(prefixed = ast_str_thread_get(&verbose_buf, VERBOSE_BUF_INIT_SIZE)) ||
+	    !(buf = ast_str_create(VERBOSE_BUF_INIT_SIZE))) {
 		return;
 	}
 
-	if (ast_opt_timestamp) {
-		struct timeval now;
-		struct ast_tm tm;
-		char date[40];
-		char *datefmt;
-
-		now = ast_tvnow();
-		ast_localtime(&now, &tm, NULL);
-		ast_strftime(date, sizeof(date), dateformat, &tm);
-		datefmt = ast_alloca(strlen(date) + 3 + strlen(prefix) + strlen(fmt) + 1);
-		sprintf(datefmt, "%c[%s] %s%s", (char) magic, date, prefix, fmt);
-		fmt = datefmt;
-	} else {
-		char *tmp = ast_alloca(strlen(prefix) + strlen(fmt) + 2);
-		sprintf(tmp, "%c%s%s", (char) magic, prefix, fmt);
-		fmt = tmp;
-	}
-
-	/* Build string */
 	res = ast_str_set_va(&buf, 0, fmt, ap);
-
 	/* If the build failed then we can drop this allocated message */
 	if (res == AST_DYNSTR_BUILD_FAILED) {
 		return;
 	}
 
-	ast_log_callid(__LOG_VERBOSE, file, line, func, callid, "%s", ast_str_buffer(buf));
+	ast_str_reset(prefixed);
+	/* for every newline found in the buffer add verbose prefix data */
+	fmt = ast_str_buffer(buf);
+	do {
+		if (!(p = strchr(fmt, '\n'))) {
+			p = strchr(fmt, '\0') - 1;
+		}
+		++p;
+
+		if (ast_opt_timestamp) {
+			struct ast_tm tm;
+			char date[40];
+			struct timeval now = ast_tvnow();
+			ast_localtime(&now, &tm, NULL);
+			ast_strftime(date, sizeof(date), dateformat, &tm);
+			ast_str_append(&prefixed, 0, "%c[%s] %s", (char) magic, date, prefix);
+		} else {
+			ast_str_append(&prefixed, 0, "%c%s", (char) magic, prefix);
+		}
+		ast_str_append_substr(&prefixed, 0, fmt, p - fmt);
+		fmt = p;
+	} while (p && *p);
+
+	ast_log_callid(__LOG_VERBOSE, file, line, func, callid, "%s", ast_str_buffer(prefixed));
 }
 
 void __ast_verbose(const char *file, int line, const char *func, int level, const char *fmt, ...)