[Asterisk-code-review] logger: Support JSON logging with Verbose messages (asterisk[master])
Matt Jordan
asteriskteam at digium.com
Sat May 14 08:12:13 CDT 2016
Matt Jordan has uploaded a new change for review.
https://gerrit.asterisk.org/2831
Change subject: logger: Support JSON logging with Verbose messages
......................................................................
logger: Support JSON logging with Verbose messages
When 2d7a4a3357 was merged, it missed the fact that Verbose log messages
are formatted and handled by 'verbosers'. Verbosers are registered
functions that handle verbose messages only; they exist as a separate
class of callbacks. This was done to handle the 'magic' that must be
inserted into Verbose messages sent to remote consoles, so that the
consoles can format the messages correctly, i.e., the leading
tabs/characters.
In reality, verbosers are a weird appendage: they're a separate class of
formatters/message handlers outside of what handles all other log
messages in Asterisk. After some code inspection, it became clear that
simply passing a Verbose message along with its 'sublevel' importance
through the normal logging mechanisms removes the need for verbosers
altogether.
This patch removes the verbosers, and maakes the default log formatter
aware that, if the log channel is a console log, it should simply insert
the 'verbose magic' into the log messages, so that the console handlers can
interpret and format the verbose message themselves.
This simplifies the code quite a lot, and should improve the performance
of printing verbose messages by a reasonable factor:
(1) It removes a number of memory allocations that were done on each
verobse message
(2) It removes the need to strip the verbose magic out of the verbose
log messages before passing them to non-console log channels
(3) It now performs fewer iterations over lists when handling verbose
messages
Since verbose messages are now handled like other log messages (for the
most part), the JSON formatting of the messages works as well.
ASTERISK-25425
Change-Id: I21bf23f0a1e489b5102f8a035fe8871552ce4f96
Fixup
Change-Id: I4cade80462b4e4256403e7bc3b5aab50bd064434
---
M include/asterisk/logger.h
M main/asterisk.c
M main/logger.c
M utils/extconf.c
4 files changed, 103 insertions(+), 206 deletions(-)
git pull ssh://gerrit.asterisk.org:29418/asterisk refs/changes/31/2831/1
diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h
index bf8ce6a..9f9f671 100644
--- a/include/asterisk/logger.h
+++ b/include/asterisk/logger.h
@@ -195,11 +195,25 @@
void ast_console_puts(const char *string);
/*!
- * \brief log the string to the console, and all attached
- * console clients
+ * \brief log the string to the console, and all attached console clients
+ *
+ * \param string The message to write to the console
+ * \param level The log level of the message
+ *
* \version 1.6.1 added level parameter
*/
void ast_console_puts_mutable(const char *string, int level);
+
+/*!
+ * \brief log the string to the console, and all attached console clients
+ * \since 14.0.0
+ *
+ * \param message The message to write to the console
+ * \param sublevel If the log level supports it, the sub-level of the message
+ * \param level The log level of the message
+ */
+void ast_console_puts_mutable_full(const char *message, int level, int sublevel);
+
void ast_console_toggle_mute(int fd, int silent);
/*!
diff --git a/main/asterisk.c b/main/asterisk.c
index bf2206c..6cfbc1b 100644
--- a/main/asterisk.c
+++ b/main/asterisk.c
@@ -1257,14 +1257,15 @@
/*!
* \brief log the string to all attached network console clients
*/
-static void ast_network_puts_mutable(const char *string, int level)
+static void ast_network_puts_mutable(const char *string, int level, int sublevel)
{
int x;
for (x = 0; x < AST_MAX_CONNECTS; ++x) {
if (consoles[x].fd < 0
|| consoles[x].mute
- || consoles[x].levels[level]) {
+ || consoles[x].levels[level]
+ || (level == __LOG_VERBOSE && consoles[x].option_verbose < sublevel)) {
continue;
}
fdprint(consoles[x].p[1], string);
@@ -1277,12 +1278,23 @@
*/
void ast_console_puts_mutable(const char *string, int level)
{
+ ast_console_puts_mutable_full(string, level, 0);
+}
+
+static int console_print(const char *s);
+
+void ast_console_puts_mutable_full(const char *message, int level, int sublevel)
+{
/* Send to the root console */
- fputs(string, stdout);
- fflush(stdout);
+ console_print(message);
+
+ /* Wake up a poll()ing console */
+ if (ast_opt_console && consolethread != AST_PTHREADT_NULL) {
+ pthread_kill(consolethread, SIGURG);
+ }
/* Send to any network console clients */
- ast_network_puts_mutable(string, level);
+ ast_network_puts_mutable(message, level, sublevel);
}
/*!
@@ -1312,24 +1324,6 @@
/* Send to any network console clients */
ast_network_puts(string);
-}
-
-static void network_verboser(const char *string)
-{
- int x;
- int verb_level;
-
- /* Send to any network console clients if client verbocity allows. */
- verb_level = VERBOSE_MAGIC2LEVEL(string);
- for (x = 0; x < AST_MAX_CONNECTS; ++x) {
- if (consoles[x].fd < 0
- || consoles[x].mute
- || consoles[x].levels[__LOG_VERBOSE]
- || consoles[x].option_verbose < verb_level) {
- continue;
- }
- fdprint(consoles[x].p[1], string);
- }
}
static pthread_t lthread;
@@ -1593,9 +1587,6 @@
close(ast_socket);
ast_socket = -1;
return -1;
- }
- if (ast_register_verbose(network_verboser)) {
- ast_log(LOG_WARNING, "Unable to register network verboser?\n");
}
if (ast_pthread_create_background(<hread, NULL, listener, NULL)) {
@@ -2118,7 +2109,7 @@
AST_THREADSTORAGE_CUSTOM(console_state, console_state_init, ast_free_ptr);
-static int console_print(const char *s, int local)
+static int console_print(const char *s)
{
struct console_state_data *state =
ast_threadstorage_get(&console_state, sizeof(*state));
@@ -2187,18 +2178,6 @@
}
return res;
-}
-
-static void console_verboser(const char *s)
-{
- if (!console_print(s, 1)) {
- return;
- }
-
- /* Wake up a poll()ing console */
- if (ast_opt_console && consolethread != AST_PTHREADT_NULL) {
- pthread_kill(consolethread, SIGURG);
- }
}
static int ast_all_zeros(const char *s)
@@ -2713,7 +2692,7 @@
}
}
- console_print(buf, 0);
+ console_print(buf);
if ((res < EL_BUF_SIZE - 1) && ((buf[res-1] == '\n') || (res >= 2 && buf[res-2] == '\n'))) {
*cp = CC_REFRESH;
@@ -3786,10 +3765,6 @@
static void print_intro_message(const char *runuser, const char *rungroup)
{
if (ast_opt_console || option_verbose || (ast_opt_remote && !ast_opt_exec)) {
- if (ast_register_verbose(console_verboser)) {
- fprintf(stderr, "Unable to register console verboser?\n");
- return;
- }
WELCOME_MESSAGE;
if (runuser) {
ast_verbose("Running as user '%s'\n", runuser);
@@ -4424,6 +4399,11 @@
aco_init();
+ if (init_logger()) { /* Start logging subsystem */
+ printf("Failed: init_logger\n%s", term_quit());
+ exit(1);
+ }
+
if (ast_bucket_init()) {
printf("Failed: ast_bucket_init\n%s", term_quit());
exit(1);
@@ -4465,11 +4445,6 @@
*/
srand((unsigned int) getpid() + (unsigned int) time(NULL));
initstate((unsigned int) getpid() * 65536 + (unsigned int) time(NULL), randompool, sizeof(randompool));
-
- if (init_logger()) { /* Start logging subsystem */
- printf("Failed: init_logger\n%s", term_quit());
- exit(1);
- }
threadstorage_init();
diff --git a/main/logger.c b/main/logger.c
index 42a1c70..90d7cd6 100644
--- a/main/logger.c
+++ b/main/logger.c
@@ -158,6 +158,7 @@
struct logmsg {
enum logmsgtypes type;
int level;
+ int sublevel;
int line;
int lwp;
ast_callid callid;
@@ -307,6 +308,52 @@
.format_log = format_log_json
};
+static int logger_add_verbose_magic(struct logmsg *logmsg, char *buf, size_t size)
+{
+ const char *p;
+ const char *fmt;
+ struct ast_str *prefixed;
+ signed char magic = logmsg->sublevel > 9 ? -10 : -logmsg->sublevel - 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 (logmsg->sublevel < 0) {
+ if (!strncmp(logmsg->message, VERBOSE_PREFIX_4, strlen(VERBOSE_PREFIX_4))) {
+ magic = -5;
+ } else if (!strncmp(logmsg->message, VERBOSE_PREFIX_3, strlen(VERBOSE_PREFIX_3))) {
+ magic = -4;
+ } else if (!strncmp(logmsg->message, VERBOSE_PREFIX_2, strlen(VERBOSE_PREFIX_2))) {
+ magic = -3;
+ } else if (!strncmp(logmsg->message, VERBOSE_PREFIX_1, strlen(VERBOSE_PREFIX_1))) {
+ magic = -2;
+ } else {
+ magic = -1;
+ }
+ }
+
+ if (!(prefixed = ast_str_thread_get(&verbose_buf, VERBOSE_BUF_INIT_SIZE))) {
+ return -1;
+ }
+
+ ast_str_reset(prefixed);
+
+ /* for every newline found in the buffer add verbose prefix data */
+ fmt = logmsg->message;
+ do {
+ if (!(p = strchr(fmt, '\n'))) {
+ p = strchr(fmt, '\0') - 1;
+ }
+ ++p;
+
+ ast_str_append(&prefixed, 0, "%c", (char)magic);
+ ast_str_append_substr(&prefixed, 0, fmt, p - fmt);
+ fmt = p;
+ } while (p && *p);
+
+ snprintf(buf, size, "%s", ast_str_buffer(prefixed));
+
+ return 0;
+}
+
static int format_log_default(struct logchannel *chan, struct logmsg *msg, char *buf, size_t size)
{
char call_identifier_str[13];
@@ -333,6 +380,14 @@
case LOGTYPE_CONSOLE:
{
char linestr[32];
+
+ /*
+ * Verbose messages are interpreted by console channels in their own
+ * special way
+ */
+ if (msg->level == __LOG_VERBOSE) {
+ return logger_add_verbose_magic(msg, buf, size);
+ }
/* Turn the numeric line number into a string for colorization */
snprintf(linestr, sizeof(linestr), "%d", msg->line);
@@ -1405,13 +1460,6 @@
}
}
-struct verb {
- void (*verboser)(const char *string);
- AST_LIST_ENTRY(verb) list;
-};
-
-static AST_RWLIST_HEAD_STATIC(verbosers, verb);
-
static struct ast_cli_entry cli_logger[] = {
AST_CLI_DEFINE(handle_logger_show_channels, "List configured log channels"),
AST_CLI_DEFINE(handle_logger_reload, "Reopens the log files"),
@@ -1432,59 +1480,12 @@
.sa_flags = SA_RESTART,
};
-static char *logger_strip_verbose_magic(const char *message, int level)
-{
- const char *begin, *end;
- char *stripped_message, *dst;
- char magic = -(level + 1);
-
- if (!(stripped_message = ast_malloc(strlen(message) + 1))) {
- return NULL;
- }
-
- begin = message;
- dst = stripped_message;
- do {
- end = strchr(begin, magic);
- if (end) {
- size_t len = end - begin;
- memcpy(dst, begin, len);
- begin = end + 1;
- dst += len;
- } else {
- strcpy(dst, begin); /* safe */
- break;
- }
- } while (1);
-
- return stripped_message;
-}
-
/*! \brief Print a normal log message to the channels */
static void logger_print_normal(struct logmsg *logmsg)
{
struct logchannel *chan = NULL;
char buf[BUFSIZ];
- struct verb *v = NULL;
- char *tmpmsg;
int level = 0;
-
- if (logmsg->level == __LOG_VERBOSE) {
-
- /* Iterate through the list of verbosers and pass them the log message string */
- AST_RWLIST_RDLOCK(&verbosers);
- AST_RWLIST_TRAVERSE(&verbosers, v, list)
- v->verboser(logmsg->message);
- AST_RWLIST_UNLOCK(&verbosers);
-
- level = VERBOSE_MAGIC2LEVEL(logmsg->message);
-
- tmpmsg = logger_strip_verbose_magic(logmsg->message, level);
- if (tmpmsg) {
- ast_string_field_set(logmsg, message, tmpmsg);
- ast_free(tmpmsg);
- }
- }
AST_RWLIST_RDLOCK(&logchannels);
if (!AST_RWLIST_EMPTY(&logchannels)) {
@@ -1522,13 +1523,8 @@
}
break;
case LOGTYPE_CONSOLE:
- /* The Console already is a verboser as well */
- if (logmsg->level == __LOG_VERBOSE) {
- continue;
- }
-
if (!chan->formatter.format_log(chan, logmsg, buf, BUFSIZ)) {
- ast_console_puts_mutable(buf, logmsg->level);
+ ast_console_puts_mutable_full(buf, logmsg->level, logmsg->sublevel);
}
break;
case LOGTYPE_FILE:
@@ -1722,7 +1718,6 @@
void close_logger(void)
{
struct logchannel *f = NULL;
- struct verb *cur = NULL;
ast_cli_unregister_multiple(cli_logger, ARRAY_LEN(cli_logger));
@@ -1734,14 +1729,9 @@
ast_cond_signal(&logcond);
AST_LIST_UNLOCK(&logmsgs);
- if (logthread != AST_PTHREADT_NULL)
+ if (logthread != AST_PTHREADT_NULL) {
pthread_join(logthread, NULL);
-
- AST_RWLIST_WRLOCK(&verbosers);
- while ((cur = AST_LIST_REMOVE_HEAD(&verbosers, list))) {
- ast_free(cur);
}
- AST_RWLIST_UNLOCK(&verbosers);
AST_RWLIST_WRLOCK(&logchannels);
@@ -1893,7 +1883,7 @@
/*!
* \brief send log messages to syslog and/or the console
*/
-static void __attribute__((format(printf, 6, 0))) ast_log_full(int level, const char *file, int line, const char *function, ast_callid callid, const char *fmt, va_list ap)
+static void __attribute__((format(printf, 7, 0))) ast_log_full(int level, int sublevel, const char *file, int line, const char *function, ast_callid callid, const char *fmt, va_list ap)
{
struct logmsg *logmsg = NULL;
struct ast_str *buf = NULL;
@@ -1955,6 +1945,7 @@
/* Copy over data */
logmsg->level = level;
+ logmsg->sublevel = sublevel;
logmsg->line = line;
ast_string_field_set(logmsg, level_name, levels[level]);
ast_string_field_set(logmsg, file, file);
@@ -1989,7 +1980,7 @@
if (level == __LOG_VERBOSE) {
__ast_verbose_ap(file, line, function, 0, callid, fmt, ap);
} else {
- ast_log_full(level, file, line, function, callid, fmt, ap);
+ ast_log_full(level, -1, file, line, function, callid, fmt, ap);
}
va_end(ap);
}
@@ -2013,7 +2004,7 @@
callid = ast_read_threadstorage_callid();
va_start(ap, fmt);
- ast_log_full(level, file, line, function, callid, fmt, ap);
+ ast_log_full(level, -1, file, line, function, callid, fmt, ap);
va_end(ap);
/* Clear flag so the next allocation failure can be logged. */
@@ -2024,7 +2015,7 @@
{
va_list ap;
va_start(ap, fmt);
- ast_log_full(level, file, line, function, callid, fmt, ap);
+ ast_log_full(level, -1, file, line, function, callid, fmt, ap);
va_end(ap);
}
@@ -2059,53 +2050,7 @@
void __ast_verbose_ap(const char *file, int line, const char *func, int level, ast_callid callid, const char *fmt, va_list ap)
{
- const char *p;
- struct ast_str *prefixed, *buf;
- int res = 0;
- 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) {
- if (!strncmp(fmt, VERBOSE_PREFIX_4, strlen(VERBOSE_PREFIX_4))) {
- magic = -5;
- } else if (!strncmp(fmt, VERBOSE_PREFIX_3, strlen(VERBOSE_PREFIX_3))) {
- magic = -4;
- } else if (!strncmp(fmt, VERBOSE_PREFIX_2, strlen(VERBOSE_PREFIX_2))) {
- magic = -3;
- } else if (!strncmp(fmt, VERBOSE_PREFIX_1, strlen(VERBOSE_PREFIX_1))) {
- magic = -2;
- } else {
- magic = -1;
- }
- }
-
- if (!(prefixed = ast_str_thread_get(&verbose_buf, VERBOSE_BUF_INIT_SIZE)) ||
- !(buf = ast_str_thread_get(&verbose_build_buf, VERBOSE_BUF_INIT_SIZE))) {
- return;
- }
-
- 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_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;
-
- ast_str_append(&prefixed, 0, "%c", (char)magic);
- 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));
+ ast_log_full(__LOG_VERBOSE, level, file, line, func, callid, fmt, ap);
}
void __ast_verbose(const char *file, int line, const char *func, int level, const char *fmt, ...)
@@ -2268,40 +2213,6 @@
}
AST_RWLIST_UNLOCK(&verb_consoles);
ast_verb_update();
-}
-
-int ast_register_verbose(void (*v)(const char *string))
-{
- struct verb *verb;
-
- if (!(verb = ast_malloc(sizeof(*verb))))
- return -1;
-
- verb->verboser = v;
-
- AST_RWLIST_WRLOCK(&verbosers);
- AST_RWLIST_INSERT_HEAD(&verbosers, verb, list);
- AST_RWLIST_UNLOCK(&verbosers);
-
- return 0;
-}
-
-int ast_unregister_verbose(void (*v)(const char *string))
-{
- struct verb *cur;
-
- AST_RWLIST_WRLOCK(&verbosers);
- AST_RWLIST_TRAVERSE_SAFE_BEGIN(&verbosers, cur, list) {
- if (cur->verboser == v) {
- AST_RWLIST_REMOVE_CURRENT(list);
- ast_free(cur);
- break;
- }
- }
- AST_RWLIST_TRAVERSE_SAFE_END;
- AST_RWLIST_UNLOCK(&verbosers);
-
- return cur ? 0 : -1;
}
static void update_logchannels(void)
diff --git a/utils/extconf.c b/utils/extconf.c
index 4eaea3c..48053ae 100644
--- a/utils/extconf.c
+++ b/utils/extconf.c
@@ -120,9 +120,6 @@
/* IN CONFLICT: void ast_verbose(const char *fmt, ...)
__attribute__((format(printf, 1, 2))); */
-int ast_register_verbose(void (*verboser)(const char *string));
-int ast_unregister_verbose(void (*verboser)(const char *string));
-
void ast_console_puts(const char *string);
#define _A_ __FILE__, __LINE__, __PRETTY_FUNCTION__
--
To view, visit https://gerrit.asterisk.org/2831
To unsubscribe, visit https://gerrit.asterisk.org/settings
Gerrit-MessageType: newchange
Gerrit-Change-Id: I4cade80462b4e4256403e7bc3b5aab50bd064434
Gerrit-PatchSet: 1
Gerrit-Project: asterisk
Gerrit-Branch: master
Gerrit-Owner: Matt Jordan <mjordan at digium.com>
More information about the asterisk-code-review
mailing list