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 makes 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 itself. This allows the
console handlers to 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

diff --git a/include/asterisk/logger.h b/include/asterisk/logger.h
index bf8ce6acf2dbaf7fc19561380a046b9302228ea9..9f9f671c06f00586a01f6a4a6c1b39c3c17ce51e 100644 (file)
--- a/include/asterisk/logger.h
+++ b/include/asterisk/logger.h
@@ -195,11 +195,25 @@ int ast_unregister_verbose(void (*verboser)(const char *string)) attribute_warn_
 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 bf2206cd77e8e0187936fe643de567ec2fec45e5..6cfbc1b336bb44380bbe03579f6524647da1a57d 100644 (file)
--- a/main/asterisk.c
+++ b/main/asterisk.c
@@ -1257,14 +1257,15 @@ void ast_console_toggle_mute(int fd, int silent)
 /*!
  * \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);
@@ -1276,13 +1277,24 @@ static void ast_network_puts_mutable(const char *string, int level)
  * network console clients
  */
 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);
 }
 
 /*!
@@ -1314,24 +1326,6 @@ void ast_console_puts(const char *string)
        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;
 
 /*!
@@ -1594,9 +1588,6 @@ static int ast_makesocket(void)
                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(&lthread, NULL, listener, NULL)) {
                ast_log(LOG_WARNING, "Unable to create listener thread.\n");
@@ -2118,7 +2109,7 @@ static int console_state_init(void *ptr)
 
 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));
@@ -2189,18 +2180,6 @@ static int console_print(const char *s, int local)
        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)
 {
        while (*s) {
@@ -2713,7 +2692,7 @@ static int ast_el_read_char(EditLine *editline, char *cp)
                                }
                        }
 
-                       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 env_init(void)
 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 @@ static void asterisk_daemon(int isroot, const char *runuser, const char *rungrou
 
        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);
@@ -4466,11 +4446,6 @@ static void asterisk_daemon(int isroot, const char *runuser, const char *rungrou
        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();
 
        if (ast_rtp_engine_init()) {

diff --git a/main/logger.c b/main/logger.c
index 42a1c700049cd9946001f1c6c74519d344c4ab47..90d7cd6b1111e22eea7fd89ce9a90dd0df10c64e 100644 (file)
--- a/main/logger.c
+++ b/main/logger.c
@@ -158,6 +158,7 @@ enum logmsgtypes {
 struct logmsg {
        enum logmsgtypes type;
        int level;
+       int sublevel;
        int line;
        int lwp;
        ast_callid callid;
@@ -307,6 +308,52 @@ static struct logformatter logformatter_json = {
        .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];
@@ -334,6 +381,14 @@ static int format_log_default(struct logchannel *chan, struct logmsg *msg, char
                {
                        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 @@ static char *handle_logger_remove_channel(struct ast_cli_entry *e, int cmd, stru
        }
 }
 
-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,60 +1480,13 @@ static struct sigaction handle_SIGXFSZ = {
        .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)) {
                AST_RWLIST_TRAVERSE(&logchannels, chan, list) {
@@ -1522,13 +1523,8 @@ static void logger_print_normal(struct logmsg *logmsg)
                                }
                                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 @@ int init_logger(void)
 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 @@ void close_logger(void)
        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 @@ void ast_callid_threadstorage_auto_clean(ast_callid callid, int callid_created)
 /*!
  * \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 @@ static void __attribute__((format(printf, 6, 0))) ast_log_full(int level, const
 
        /* 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 @@ void ast_log(int level, const char *file, int line, const char *function, const
        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 @@ void ast_log_safe(int level, const char *file, int line, const char *function, c
        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 @@ void ast_log_callid(int level, const char *file, int line, const char *function,
 {
        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_log_backtrace(void)
 
 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, ...)
@@ -2270,40 +2215,6 @@ void ast_verb_console_set(int verb_level)
        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)
 {
        struct logchannel *cur;

diff --git a/utils/extconf.c b/utils/extconf.c
index 4eaea3c2d374afe15d4f24fa46a413a7336d211f..48053aed662d870ea252bdf51449fb615bcd3a2b 100644 (file)
--- a/utils/extconf.c
+++ b/utils/extconf.c
@@ -120,9 +120,6 @@ void ast_queue_log(const char *queuename, const char *callid, const char *agent,
 /* 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__