sysmocom
/
asterisk
11
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

main/logger: Add log formatters and JSON structured logs 

When Asterisk is part of a larger distributed system, log files are often
gathered using tools (such as logstash) that prefer to consume information
and have it rendered using other tools (such as Kibana) that prefer a
structured format, e.g., JSON. This patch adds support for JSON formatted
logs by adding support for an optional log format specifier in Asterisk's
logging subsystem. By adding a format specifier of '[json]':

full => [json]debug,verbose,notice,warning,error

Log messages will be output to the 'full' channel in the following
format:

{
  "hostname": Hostname or name specified in asterisk.conf
  "timestamp": Date/Time
  "identifiers": {
    "lwp": Thread ID,
    "callid": Call Identifier
  }
  "logmsg": {
    "location": {
      "filename": Name of the file that generated the log statement
      "function": Function that generated the log statement
      "line": Line number that called the logging function
    }
    "level": Log level, e.g., DEBUG, VERBOSE, etc.
    "message": Actual text of the log message
  }
}

ASTERISK-25425 #close

Change-Id: I8649bfedf3fb7bf3138008cc11565553209cc238
This commit is contained in:
Matt Jordan 2015-09-21 07:26:00 -05:00
parent 9db74be3c0
commit 2d7a4a3357
3 changed files with 261 additions and 100 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

7
CHANGES
View File

@ -115,6 +115,13 @@ Core
names. This way one X.509 certificate can be used for hosts that can be
reached under multiple DNS names or for multiple hosts.
* The Asterisk logging system now supports JSON structured logging. Log
channels specified in logger.conf or added dynamically via CLI commands now
support an optional specifier prior to their levels that determines their
formatting. To set a log channel to format its entries as JSON, a formatter
of '[json]' can be set, e.g.,
full => [json]debug,verbose,notice,warning,error
Functions
------------------

40
configs/samples/logger.conf.sample
View File

@ -80,7 +80,35 @@
;
[logfiles]
;
; Format is "filename" and then "levels" of debugging to be included:
; Format is:
;
; logger_name => [formatter]levels
;
; The name of the logger dictates not only the name of the logging
; channel, but also its type. Valid types are:
; - 'console' - The root console of Asterisk
; - 'syslog' - Linux syslog, with facilities specified afterwards with
; a period delimiter, e.g., 'syslog.local0'
; - 'filename' - The name of the log file to create. This is the default
; for log channels.
;
; Filenames can either be relative to the standard Asterisk log directory
; (see 'astlogdir' in asterisk.conf), or absolute paths that begin with
; '/'.
;
; An optional formatter can be specified prior to the log levels sent
; to the log channel. The formatter is defined immediately preceeding the
; levels, and is enclosed in square brackets. Valid formatters are:
; - [default] - The default formatter, this outputs log messages using a
; human readable format.
; - [json] - Log the output in JSON. Note that JSON formatted log entries,
; if specified for a logger type of 'console', will be formatted
; per the 'default' formatter for log messages of type VERBOSE.
; This is due to the remote consoles intepreting verbosity
; outside of the logging subsystem.
;
; Log levels include the following, and are specified in a comma delineated
; list:
; debug
; notice
; warning
@ -90,12 +118,6 @@
; fax
; security
;
; Special filename "console" represents the root console
;
; Filenames can either be relative to the standard Asterisk log directory
; (see 'astlogdir' in asterisk.conf), or absolute paths that begin with
; '/'.
;
; Verbose takes an optional argument, in the form of an integer level.
; Verbose messages with higher levels will not be logged to the file. If
; the verbose level is not specified, it will log verbose messages following
@ -127,7 +149,9 @@ console => notice,warning,error
;console => notice,warning,error,debug
messages => notice,warning,error
;full => notice,warning,error,debug,verbose,dtmf,fax
;
;full-json => [json]debug,verbose,notice,warning,error,dtmf,fax
;
;syslog keyword : This special keyword logs to syslog facility
;
;syslog.local0 => notice,warning,error

314
main/logger.c
View File

@ -69,6 +69,7 @@ ASTERISK_REGISTER_FILE()
#include "asterisk/buildinfo.h"
#include "asterisk/ast_version.h"
#include "asterisk/backtrace.h"
#include "asterisk/json.h"
/*** DOCUMENTATION
***/
@ -104,6 +105,16 @@ static struct {
static char hostname[MAXHOSTNAMELEN];
AST_THREADSTORAGE_RAW(in_safe_log);
struct logchannel;
struct logmsg;
struct logformatter {
/* The name of the log formatter */
const char *name;
/* Pointer to the function that will format the log */
int (* const format_log)(struct logchannel *channel, struct logmsg *msg, char *buf, size_t size);
};
enum logtypes {
LOGTYPE_SYSLOG,
LOGTYPE_FILE,
@ -111,6 +122,8 @@ enum logtypes {
};
struct logchannel {
/*! How the logs sent to this channel will be formatted */
struct logformatter formatter;
/*! What to log to this channel */
unsigned int logmask;
/*! If this channel is disabled or not */
@ -234,6 +247,117 @@ AST_THREADSTORAGE(verbose_build_buf);
AST_THREADSTORAGE(log_buf);
#define LOG_BUF_INIT_SIZE 256
static int format_log_json(struct logchannel *channel, struct logmsg *msg, char *buf, size_t size)
{
struct ast_json *json;
char *str;
char call_identifier_str[13];
size_t json_str_len;
if (msg->callid) {
snprintf(call_identifier_str, sizeof(call_identifier_str), "[C-%08x]", msg->callid);
} else {
call_identifier_str[0] = '\0';
}
json = ast_json_pack("{s: s, s: s, "
"s: {s: i, s: s} "
"s: {s: {s: s, s: s, s: i}, "
"s: s, s: s} }",
"hostname", ast_config_AST_SYSTEM_NAME,
"timestamp", msg->date,
"identifiers",
"lwp", msg->lwp,
"callid", S_OR(call_identifier_str, ""),
"logmsg",
"location",
"filename", msg->file,
"function", msg->function,
"line", msg->line,
"level", msg->level_name,
"message", msg->message);
if (!json) {
return -1;
}
str = ast_json_dump_string(json);
if (!str) {
ast_json_unref(json);
return -1;
}
ast_copy_string(buf, str, size);
json_str_len = strlen(str);
if (json_str_len > size - 1) {
json_str_len = size - 1;
}
buf[json_str_len] = '\n';
buf[json_str_len + 1] = '\0';
term_strip(buf, buf, size);
ast_json_free(str);
ast_json_unref(json);
return 0;
}
static struct logformatter logformatter_json = {
.name = "json",
.format_log = format_log_json
};
static int format_log_default(struct logchannel *chan, struct logmsg *msg, char *buf, size_t size)
{
char call_identifier_str[13];
if (msg->callid) {
snprintf(call_identifier_str, sizeof(call_identifier_str), "[C-%08x]", msg->callid);
} else {
call_identifier_str[0] = '\0';
}
switch (chan->type) {
case LOGTYPE_SYSLOG:
snprintf(buf, size, "%s[%d]%s: %s:%d in %s: %s",
levels[msg->level], msg->lwp, call_identifier_str, msg->file,
msg->line, msg->function, msg->message);
term_strip(buf, buf, size);
break;
case LOGTYPE_FILE:
snprintf(buf, size, "[%s] %s[%d]%s %s: %s",
msg->date, msg->level_name, msg->lwp, call_identifier_str,
msg->file, msg->message);
term_strip(buf, buf, size);
break;
case LOGTYPE_CONSOLE:
{
char linestr[32];
/* Turn the numeric line number into a string for colorization */
snprintf(linestr, sizeof(linestr), "%d", msg->line);
snprintf(buf, size, "[%s] " COLORIZE_FMT "[%d]%s: " COLORIZE_FMT ":" COLORIZE_FMT " " COLORIZE_FMT ": %s",
msg->date,
COLORIZE(colors[msg->level], 0, msg->level_name),
msg->lwp,
call_identifier_str,
COLORIZE(COLOR_BRWHITE, 0, msg->file),
COLORIZE(COLOR_BRWHITE, 0, linestr),
COLORIZE(COLOR_BRWHITE, 0, msg->function),
msg->message);
}
break;
}
return 0;
}
static struct logformatter logformatter_default = {
.name = "default",
.format_log = format_log_default,
};
static void make_components(struct logchannel *chan)
{
char *w;
@ -245,6 +369,33 @@ static void make_components(struct logchannel *chan)
/* Default to using option_verbose as the verbosity level of the logging channel. */
verb_level = -1;
w = strchr(stringp, '[');
if (w) {
char *end = strchr(w + 1, ']');
if (!end) {
fprintf(stderr, "Logger Warning: bad formatter definition for %s in logger.conf\n", chan->filename);
} else {
char *formatter_name = w + 1;
*end = '\0';
stringp = end + 1;
if (!strcasecmp(formatter_name, "json")) {
memcpy(&chan->formatter, &logformatter_json, sizeof(chan->formatter));
} else if (!strcasecmp(formatter_name, "default")) {
memcpy(&chan->formatter, &logformatter_default, sizeof(chan->formatter));
} else {
fprintf(stderr, "Logger Warning: Unknown formatter definition %s for %s in logger.conf; using 'default'\n",
formatter_name, chan->filename);
memcpy(&chan->formatter, &logformatter_default, sizeof(chan->formatter));
}
}
}
if (!chan->formatter.name) {
memcpy(&chan->formatter, &logformatter_default, sizeof(chan->formatter));
}
while ((w = strsep(&stringp, ","))) {
w = ast_strip(w);
if (ast_strlen_zero(w)) {
@ -462,6 +613,7 @@ static int init_logger_chain(int locked, const char *altconf)
}
chan->type = LOGTYPE_CONSOLE;
chan->logmask = __LOG_WARNING | __LOG_NOTICE | __LOG_ERROR;
memcpy(&chan->formatter, &logformatter_default, sizeof(chan->formatter));
if (!locked) {
AST_RWLIST_WRLOCK(&logchannels);
@ -1095,7 +1247,7 @@ int ast_logger_get_channels(int (*logentry)(const char *channel, const char *typ
/*! \brief CLI command to show logging system configuration */
static char *handle_logger_show_channels(struct ast_cli_entry *e, int cmd, struct ast_cli_args *a)
{
#define FORMATL "%-35.35s %-8.8s %-9.9s "
#define FORMATL "%-35.35s %-8.8s %-10.10s %-9.9s "
struct logchannel *chan;
switch (cmd) {
case CLI_INIT:
@ -1107,15 +1259,16 @@ static char *handle_logger_show_channels(struct ast_cli_entry *e, int cmd, struc
case CLI_GENERATE:
return NULL;
}
ast_cli(a->fd, FORMATL, "Channel", "Type", "Status");
ast_cli(a->fd, FORMATL, "Channel", "Type", "Formatter", "Status");
ast_cli(a->fd, "Configuration\n");
ast_cli(a->fd, FORMATL, "-------", "----", "------");
ast_cli(a->fd, FORMATL, "-------", "----", "---------", "------");
ast_cli(a->fd, "-------------\n");
AST_RWLIST_RDLOCK(&logchannels);
AST_RWLIST_TRAVERSE(&logchannels, chan, list) {
unsigned int level;
ast_cli(a->fd, FORMATL, chan->filename, chan->type == LOGTYPE_CONSOLE ? "Console" : (chan->type == LOGTYPE_SYSLOG ? "Syslog" : "File"),
chan->formatter.name,
chan->disabled ? "Disabled" : "Enabled");
ast_cli(a->fd, " - ");
for (level = 0; level < ARRAY_LEN(levels); level++) {
@ -1171,7 +1324,9 @@ static char *handle_logger_add_channel(struct ast_cli_entry *e, int cmd, struct
" Adds a temporary logger channel. This logger channel\n"
" will exist until removed or until Asterisk is restarted.\n"
" <levels> is a comma-separated list of desired logger\n"
" levels such as: verbose,warning,error\n";
" levels such as: verbose,warning,error\n"
" An optional formatter may be specified with the levels;\n"
" valid values are '[json]' and '[default]'.\n";
return NULL;
case CLI_GENERATE:
return NULL;
@ -1296,33 +1451,6 @@ static struct sigaction handle_SIGXFSZ = {
.sa_flags = SA_RESTART,
};
static void ast_log_vsyslog(struct logmsg *msg, int facility)
{
char buf[BUFSIZ];
int syslog_level = ast_syslog_priority_from_loglevel(msg->level);
char call_identifier_str[13];
if (msg->callid) {
snprintf(call_identifier_str, sizeof(call_identifier_str), "[C-%08x]", msg->callid);
} else {
call_identifier_str[0] = '\0';
}
if (syslog_level < 0) {
/* we are locked here, so cannot ast_log() */
fprintf(stderr, "ast_log_vsyslog called with bogus level: %d\n", msg->level);
return;
}
syslog_level = LOG_MAKEPRI(facility, syslog_level);
snprintf(buf, sizeof(buf), "%s[%d]%s: %s:%d in %s: %s",
levels[msg->level], msg->lwp, call_identifier_str, msg->file, msg->line, msg->function, msg->message);
term_strip(buf, buf, strlen(buf) + 1);
syslog(syslog_level, "%s", buf);
}
static char *logger_strip_verbose_magic(const char *message, int level)
{
const char *begin, *end;
@ -1378,17 +1506,8 @@ static void logger_print_normal(struct logmsg *logmsg)
}
AST_RWLIST_RDLOCK(&logchannels);
if (!AST_RWLIST_EMPTY(&logchannels)) {
AST_RWLIST_TRAVERSE(&logchannels, chan, list) {
char call_identifier_str[13];
if (logmsg->callid) {
snprintf(call_identifier_str, sizeof(call_identifier_str), "[C-%08x]", logmsg->callid);
} else {
call_identifier_str[0] = '\0';
}
/* If the channel is disabled, then move on to the next one */
if (chan->disabled) {
@ -1399,65 +1518,76 @@ static void logger_print_normal(struct logmsg *logmsg)
continue;
}
/* Check syslog channels */
if (chan->type == LOGTYPE_SYSLOG && (chan->logmask & (1 << logmsg->level))) {
ast_log_vsyslog(logmsg, chan->facility);
/* Console channels */
} else if (chan->type == LOGTYPE_CONSOLE && (chan->logmask & (1 << logmsg->level))) {
char linestr[128];
if (!(chan->logmask & (1 << logmsg->level))) {
continue;
}
/* If the level is verbose, then skip it */
if (logmsg->level == __LOG_VERBOSE)
continue;
switch (chan->type) {
case LOGTYPE_SYSLOG:
{
int syslog_level = ast_syslog_priority_from_loglevel(logmsg->level);
/* Turn the numerical line number into a string */
snprintf(linestr, sizeof(linestr), "%d", logmsg->line);
/* Build string to print out */
snprintf(buf, sizeof(buf), "[%s] " COLORIZE_FMT "[%d]%s: " COLORIZE_FMT ":" COLORIZE_FMT " " COLORIZE_FMT ": %s",
logmsg->date,
COLORIZE(colors[logmsg->level], 0, logmsg->level_name),
logmsg->lwp,
call_identifier_str,
COLORIZE(COLOR_BRWHITE, 0, logmsg->file),
COLORIZE(COLOR_BRWHITE, 0, linestr),
COLORIZE(COLOR_BRWHITE, 0, logmsg->function),
logmsg->message);
/* Print out */
ast_console_puts_mutable(buf, logmsg->level);
/* File channels */
} else if (chan->type == LOGTYPE_FILE && (chan->logmask & (1 << logmsg->level))) {
int res = 0;
if (syslog_level < 0) {
/* we are locked here, so cannot ast_log() */
fprintf(stderr, "ast_log_vsyslog called with bogus level: %d\n", logmsg->level);
continue;
}
/* If no file pointer exists, skip it */
if (!chan->fileptr) {
syslog_level = LOG_MAKEPRI(chan->facility, syslog_level);
if (!chan->formatter.format_log(chan, logmsg, buf, BUFSIZ)) {
syslog(syslog_level, "%s", buf);
}
}
break;
case LOGTYPE_CONSOLE:
/* The Console already is a verboser as well */
if (logmsg->level == __LOG_VERBOSE) {
continue;
}
/* Print out to the file */
res = fprintf(chan->fileptr, "[%s] %s[%d]%s %s: %s",
logmsg->date, logmsg->level_name, logmsg->lwp, call_identifier_str,
logmsg->file, term_strip(buf, logmsg->message, BUFSIZ));
if (res <= 0 && !ast_strlen_zero(logmsg->message)) {
fprintf(stderr, "**** Asterisk Logging Error: ***********\n");
if (errno == ENOMEM || errno == ENOSPC)
fprintf(stderr, "Asterisk logging error: Out of disk space, can't log to log file %s\n", chan->filename);
else
fprintf(stderr, "Logger Warning: Unable to write to log file '%s': %s (disabled)\n", chan->filename, strerror(errno));
/*** DOCUMENTATION
<managerEventInstance>
<synopsis>Raised when a logging channel is disabled.</synopsis>
<syntax>
<parameter name="Channel">
<para>The name of the logging channel.</para>
</parameter>
</syntax>
</managerEventInstance>
***/
manager_event(EVENT_FLAG_SYSTEM, "LogChannel", "Channel: %s\r\nEnabled: No\r\nReason: %d - %s\r\n", chan->filename, errno, strerror(errno));
chan->disabled = 1;
} else if (res > 0) {
fflush(chan->fileptr);
if (!chan->formatter.format_log(chan, logmsg, buf, BUFSIZ)) {
ast_console_puts_mutable(buf, logmsg->level);
}
break;
case LOGTYPE_FILE:
{
int res = 0;
if (!chan->fileptr) {
continue;
}
if (chan->formatter.format_log(chan, logmsg, buf, BUFSIZ)) {
continue;
}
/* Print out to the file */
res = fprintf(chan->fileptr, "%s", buf);
if (res > 0) {
fflush(chan->fileptr);
} else if (res <= 0 && !ast_strlen_zero(logmsg->message)) {
fprintf(stderr, "**** Asterisk Logging Error: ***********\n");
if (errno == ENOMEM || errno == ENOSPC) {
fprintf(stderr, "Asterisk logging error: Out of disk space, can't log to log file %s\n", chan->filename);
} else {
fprintf(stderr, "Logger Warning: Unable to write to log file '%s': %s (disabled)\n", chan->filename, strerror(errno));
}
/*** DOCUMENTATION
<managerEventInstance>
<synopsis>Raised when a logging channel is disabled.</synopsis>
<syntax>
<parameter name="Channel">
<para>The name of the logging channel.</para>
</parameter>
</syntax>
</managerEventInstance>
***/
manager_event(EVENT_FLAG_SYSTEM, "LogChannel", "Channel: %s\r\nEnabled: No\r\nReason: %d - %s\r\n", chan->filename, errno, strerror(errno));
chan->disabled = 1;
}
}
break;
}
}
} else if (logmsg->level != __LOG_VERBOSE) {