FS-11870 [core, mod_graylog2, mod_console] Added switch_log_node_to_json() and updated mod_graylog2 to use it. This is a unified log node to JSON conversion.

Added json log mode in mod_console
This commit is contained in:
Chris Rienzo 2019-05-30 12:37:04 -04:00 committed by Andrey Volk
parent 302b409815
commit b06c7b0831
4 changed files with 294 additions and 103 deletions

View File

@ -68,8 +68,44 @@ SWITCH_BEGIN_EXTERN_C
switch_event_t *tags;
} switch_log_node_t;
///\{
/*! \brief JSON Log formatting data item
*/
typedef struct {
const char *name;
const char *value;
} switch_log_json_format_item_t;
///\{
/*! \brief JSON Log formatting data
*/
typedef struct {
switch_log_json_format_item_t version;
switch_log_json_format_item_t host;
switch_log_json_format_item_t timestamp;
switch_log_json_format_item_t level;
switch_log_json_format_item_t ident;
switch_log_json_format_item_t pid;
switch_log_json_format_item_t uuid;
switch_log_json_format_item_t file;
switch_log_json_format_item_t line;
switch_log_json_format_item_t function;
switch_log_json_format_item_t full_message;
switch_log_json_format_item_t short_message;
const char *custom_field_prefix;
double timestamp_divisor;
} switch_log_json_format_t;
typedef switch_status_t (*switch_log_function_t) (const switch_log_node_t *node, switch_log_level_t level);
/*!
\brief Convert a log node to JSON object. Destroy JSON object when finished.
\param node the node
\param log_level the log level
\param json_format the output format definition
\param char_vars optional channel variables to add to logs
*/
SWITCH_DECLARE(cJSON *) switch_log_node_to_json(const switch_log_node_t *node, int log_level, switch_log_json_format_t *json_format, switch_event_t *chan_vars);
/*!
\brief Initilize the logging engine

View File

@ -62,6 +62,33 @@ static uint32_t all_level = 0;
static int32_t hard_log_level = SWITCH_LOG_DEBUG;
static switch_bool_t log_uuid = SWITCH_FALSE;
//static int32_t failed_write = 0;
static switch_bool_t json_log = SWITCH_FALSE;
static switch_log_json_format_t json_format = {
{ NULL, NULL }, // version
{ "host", NULL }, // host
{ "timestamp", NULL }, // timestamp
{ "level", NULL }, // level
{ "ident", NULL }, // ident
{ "pid", NULL }, // pid
{ "session", NULL }, // uuid
{ "file", NULL }, // file
{ "line", NULL }, // line
{ "function", NULL }, // function
{ "message", NULL }, // full_message
{ NULL, NULL }, // short_message
"", // custom_field_prefix
0.0 // timestamp_divisor
};
static char *to_json_string(const switch_log_node_t *node)
{
char *json_text = NULL;
cJSON *json = switch_log_node_to_json(node, node->level, &json_format, NULL);
json_text = cJSON_PrintUnformatted(json);
cJSON_Delete(json);
return json_text;
}
static void del_mapping(char *var)
{
switch_core_hash_insert(log_hash, var, NULL);
@ -122,6 +149,47 @@ static switch_status_t config_logger(void)
}
}
// Customize field names or remove fields
// To remove a field, set its name to empty string
if ((settings = switch_xml_child(cfg, "json-log-format"))) {
for (param = switch_xml_child(settings, "format"); param; param = param->next) {
char *var = (char *) switch_xml_attr_soft(param, "field");
char *val = (char *) switch_xml_attr_soft(param, "name");
if (!strcasecmp(var, "host")) {
json_format.host.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "timestamp")) {
json_format.timestamp.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "level")) {
json_format.level.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "ident")) {
json_format.ident.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "pid")) {
json_format.pid.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "uuid")) {
json_format.uuid.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "file")) {
json_format.file.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "line")) {
json_format.line.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "function")) {
json_format.function.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "message")) {
json_format.full_message.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "short-message")) {
json_format.short_message.name = zstr(val) ? NULL : switch_core_strdup(module_pool, val);
}
}
for (param = switch_xml_child(settings, "config"); param; param = param->next) {
char *var = (char *) switch_xml_attr_soft(param, "name");
char *val = (char *) switch_xml_attr_soft(param, "value");
if (!strcasecmp(var, "custom-field-prefix")) {
json_format.custom_field_prefix = switch_core_strdup(module_pool, val);
} else if (!strcasecmp(var, "timestamp-divisor") && switch_is_number(val)) {
json_format.timestamp_divisor = strtod(val, NULL);
}
}
}
if ((settings = switch_xml_child(cfg, "settings"))) {
for (param = switch_xml_child(settings, "param"); param; param = param->next) {
char *var = (char *) switch_xml_attr_soft(param, "name");
@ -141,6 +209,8 @@ static switch_status_t config_logger(void)
hard_log_level = switch_log_str2level(val);
} else if (!strcasecmp(var, "uuid") && switch_true(val)) {
log_uuid = SWITCH_TRUE;
} else if (!strcasecmp(var, "json") && switch_true(val)) {
json_log = SWITCH_TRUE;
}
}
}
@ -242,7 +312,13 @@ static switch_status_t switch_console_logger(const switch_log_node_t *node, swit
}
#endif
if (COLORIZE) {
if (json_log) {
char *json_log_str = to_json_string(node);
if (json_log_str) {
fprintf(handle, "%s\n", json_log_str);
switch_safe_free(json_log_str);
}
} else if (COLORIZE) {
#ifdef WIN32
DWORD len = (DWORD) strlen(node->data);
DWORD outbytes = 0;
@ -281,6 +357,7 @@ SWITCH_STANDARD_API(console_api_function)
"console help\n"
"console loglevel [[0-7] | <loglevel_string>]\n"
"console uuid [on|off|toggle]\n"
"console json [on|off|toggle]\n"
"console colorize [on|off|toggle]\n" "--------------------------------------------------------------------------------\n";
const char *loglevel_usage_string = "USAGE:\n"
"--------------------------------------------------------------------------------\n"
@ -363,7 +440,19 @@ SWITCH_STANDARD_API(console_api_function)
}
}
stream->write_function(stream, "+OK console uuid %s\n", log_uuid ? "enabled" : "disabled");
} else if (!strcasecmp(argv[0], "json")) {
if (argc > 1) {
if (!strcasecmp(argv[1], "toggle")) {
if (json_log) {
json_log = SWITCH_FALSE;
} else {
json_log = SWITCH_TRUE;
}
} else {
json_log = switch_true(argv[1]);
}
}
stream->write_function(stream, "+OK console json %s\n", json_log ? "enabled" : "disabled");
} else { /* if (!strcasecmp(argv[0], "help")) { */
stream->write_function(stream, "%s", usage_string);
}
@ -383,7 +472,7 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_console_load)
/* connect my internal structure to the blank pointer passed to me */
*module_interface = switch_loadable_module_create_module_interface(pool, modname);
SWITCH_ADD_API(api_interface, "console", "Console", console_api_function, "loglevel [level]|colorize [on|toggle|off]");
SWITCH_ADD_API(api_interface, "console", "Console", console_api_function, "loglevel [level]|colorize [on|toggle|off]|uuid [on|toggle|off]|json [on|toggle|off]");
switch_console_set_complete("add console help");
switch_console_set_complete("add console loglevel");
switch_console_set_complete("add console loglevel help");
@ -400,6 +489,12 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_console_load)
switch_console_set_complete("add console colorize on");
switch_console_set_complete("add console colorize off");
switch_console_set_complete("add console colorize toggle");
switch_console_set_complete("add console uuid on");
switch_console_set_complete("add console uuid off");
switch_console_set_complete("add console uuid toggle");
switch_console_set_complete("add console json on");
switch_console_set_complete("add console json off");
switch_console_set_complete("add console json toggle");
/* setup my logger function */
switch_log_bind_logger(switch_console_logger, SWITCH_LOG_DEBUG, SWITCH_TRUE);

View File

@ -59,6 +59,8 @@ static struct {
switch_event_t *session_fields;
/** If true, byte header for uncompressed GELF is sent. Might be required if using logstash */
int send_uncompressed_header;
/** GELF JSON Format */
switch_log_json_format_t gelf_format;
} globals;
/**
@ -84,109 +86,10 @@ static int to_graylog2_level(switch_log_level_t level)
static char *to_gelf(const switch_log_node_t *node, switch_log_level_t log_level)
{
char *gelf_text = NULL;
cJSON *gelf = cJSON_CreateObject();
char *hostname;
char timestamp[32];
char *full_message = node->content;
char short_message[151];
char *short_message_end = NULL;
char *parsed_full_message = NULL;
char *field_name = NULL;
switch_event_t *log_fields = NULL;
switch_core_session_t *session = NULL;
cJSON_AddItemToObject(gelf, "version", cJSON_CreateString("1.1"));
if ((hostname = switch_core_get_variable("hostname")) && !zstr(hostname)) {
cJSON_AddItemToObject(gelf, "host", cJSON_CreateString(hostname));
} else if ((hostname = switch_core_get_variable("local_ip_v4")) && !zstr(hostname)) {
cJSON_AddItemToObject(gelf, "host", cJSON_CreateString(hostname));
}
switch_snprintf(timestamp, 32, "%"SWITCH_UINT64_T_FMT".%d", (uint64_t)(node->timestamp / 1000000), (node->timestamp % 1000000) / 1000);
cJSON_AddItemToObject(gelf, "timestamp", cJSON_CreateString(timestamp));
cJSON *gelf = switch_log_node_to_json(node, to_graylog2_level(log_level), &globals.gelf_format, globals.session_fields);
cJSON_AddItemToObject(gelf, "_microtimestamp", cJSON_CreateNumber(node->timestamp));
cJSON_AddItemToObject(gelf, "level", cJSON_CreateNumber(to_graylog2_level(log_level)));
cJSON_AddItemToObject(gelf, "_ident", cJSON_CreateString("freeswitch"));
cJSON_AddItemToObject(gelf, "_pid", cJSON_CreateNumber((int)getpid()));
if (!zstr(node->userdata)) {
cJSON_AddItemToObject(gelf, "_uuid", cJSON_CreateString(node->userdata));
}
if (!zstr_buf(node->file)) {
cJSON_AddItemToObject(gelf, "_file", cJSON_CreateString(node->file));
cJSON_AddItemToObject(gelf, "_line", cJSON_CreateNumber(node->line));
}
if (!zstr_buf(node->func)) {
cJSON_AddItemToObject(gelf, "_function", cJSON_CreateString(node->func));
}
/* skip initial space and new line */
if (*full_message == ' ') {
full_message++;
}
if (*full_message == '\n') {
full_message++;
}
/* get fields from log tags */
if (node->tags) {
switch_event_dup(&log_fields, node->tags);
}
/* get fields from channel data, if configured */
if (!zstr(node->userdata) && globals.session_fields->headers && (session = switch_core_session_locate(node->userdata))) {
switch_channel_t *channel = switch_core_session_get_channel(session);
switch_event_header_t *hp;
/* session_fields name mapped to variable name */
for (hp = globals.session_fields->headers; hp; hp = hp->next) {
if (!zstr(hp->name) && !zstr(hp->value)) {
const char *val = switch_channel_get_variable(channel, hp->value);
if (!zstr(val)) {
if (!log_fields) {
switch_event_create_plain(&log_fields, SWITCH_EVENT_CHANNEL_DATA);
}
switch_event_add_header_string(log_fields, SWITCH_STACK_BOTTOM, hp->name, val);
}
}
}
switch_core_session_rwunlock(session);
}
/* parse list of fields from message text, if any */
if (strncmp(full_message, "LOG_FIELDS", 10) == 0) {
switch_event_create_brackets(full_message+10, '[', ']', ',', &log_fields, &parsed_full_message, SWITCH_TRUE);
full_message = parsed_full_message;
}
/* add additional fields */
if (log_fields) {
switch_event_header_t *hp;
for (hp = log_fields->headers; hp; hp = hp->next) {
if (!zstr(hp->name) && !zstr(hp->value)) {
if (strncmp(hp->name, "@#", 2) == 0) {
field_name = switch_mprintf("_%s", hp->name + 2);
cJSON_AddItemToObject(gelf, field_name, cJSON_CreateNumber(strtod(hp->value, NULL)));
} else {
field_name = switch_mprintf("_%s", hp->name);
cJSON_AddItemToObject(gelf, field_name, cJSON_CreateString(hp->value));
}
free(field_name);
}
}
switch_event_destroy(&log_fields);
}
cJSON_AddItemToObject(gelf, "full_message", cJSON_CreateString(full_message));
switch_snprintf(short_message, sizeof(short_message) - 1, "%s", full_message);
if ((short_message_end = strchr(short_message, '\n'))) {
*short_message_end = '\0';
}
cJSON_AddItemToObject(gelf, "short_message", cJSON_CreateString(short_message));
gelf_text = cJSON_PrintUnformatted(gelf);
cJSON_Delete(gelf);
switch_safe_free(parsed_full_message);
return gelf_text;
}
@ -412,6 +315,25 @@ SWITCH_MODULE_LOAD_FUNCTION(mod_graylog2_load)
memset(&globals, 0, sizeof(globals));
globals.pool = pool;
// define GELF JSON format mappings
globals.gelf_format.version.name = "version";
globals.gelf_format.version.value = "1.1";
globals.gelf_format.host.name = "host";
globals.gelf_format.timestamp.name = "timestamp";
globals.gelf_format.timestamp_divisor = 1000000; // convert microseconds to seconds
globals.gelf_format.level.name = "level";
globals.gelf_format.ident.name = "_ident";
globals.gelf_format.ident.value = "freeswitch";
globals.gelf_format.pid.name = "_pid";
globals.gelf_format.pid.value = switch_core_sprintf(pool, "%d", (int)getpid());
globals.gelf_format.uuid.name = "_uuid";
globals.gelf_format.file.name = "_file";
globals.gelf_format.line.name = "_line";
globals.gelf_format.function.name = "_function";
globals.gelf_format.full_message.name = "full_message";
globals.gelf_format.short_message.name = "short_message";
globals.gelf_format.custom_field_prefix = "_";
switch_event_create_plain(&globals.session_fields, SWITCH_EVENT_CHANNEL_DATA);
if (do_config() != SWITCH_STATUS_SUCCESS) {

View File

@ -85,6 +85,144 @@ static const char *
SWITCH_SEQ_FYELLOW };
SWITCH_DECLARE(cJSON *) switch_log_node_to_json(const switch_log_node_t *node, int log_level, switch_log_json_format_t *json_format, switch_event_t *chan_vars)
{
cJSON *json = cJSON_CreateObject();
char *hostname;
char *full_message = node->content;
char *parsed_full_message = NULL;
char *field_name = NULL;
switch_event_t *log_fields = NULL;
switch_core_session_t *session = NULL;
if (json_format->version.name && json_format->version.value) {
cJSON_AddItemToObject(json, json_format->version.name, cJSON_CreateString(json_format->version.value));
}
if (json_format->host.name) {
if (json_format->host.value) {
cJSON_AddItemToObject(json, json_format->host.name, cJSON_CreateString(json_format->host.value));
} else if ((hostname = switch_core_get_variable("hostname")) && !zstr(hostname)) {
cJSON_AddItemToObject(json, json_format->host.name, cJSON_CreateString(hostname));
} else if ((hostname = switch_core_get_variable("local_ip_v4")) && !zstr(hostname)) {
cJSON_AddItemToObject(json, json_format->host.name, cJSON_CreateString(hostname));
}
}
if (json_format->timestamp.name) {
double timestamp = node->timestamp;
double divisor = 0.0;
if (json_format->timestamp_divisor > 1.0) {
timestamp = timestamp / divisor;
}
cJSON_AddItemToObject(json, json_format->timestamp.name, cJSON_CreateNumber(timestamp));
}
if (json_format->level.name) {
cJSON_AddItemToObject(json, json_format->level.name, cJSON_CreateNumber(log_level));
}
if (json_format->ident.name) {
if (json_format->ident.value) {
cJSON_AddItemToObject(json, json_format->ident.name, cJSON_CreateString(json_format->ident.value));
} else {
cJSON_AddItemToObject(json, json_format->ident.name, cJSON_CreateString("freeswitch"));
}
}
if (json_format->pid.name) {
if (json_format->pid.value) {
cJSON_AddItemToObject(json, json_format->pid.name, cJSON_CreateNumber(atoi(json_format->pid.value)));
} else {
cJSON_AddItemToObject(json, json_format->pid.name, cJSON_CreateNumber((int)getpid()));
}
}
if (json_format->uuid.name && !zstr(node->userdata)) {
cJSON_AddItemToObject(json, json_format->uuid.name, cJSON_CreateString(node->userdata));
}
if (json_format->file.name && !zstr_buf(node->file)) {
cJSON_AddItemToObject(json, json_format->file.name, cJSON_CreateString(node->file));
if (json_format->line.name) {
cJSON_AddItemToObject(json, json_format->line.name, cJSON_CreateNumber(node->line));
}
}
if (json_format->function.name && !zstr_buf(node->func)) {
cJSON_AddItemToObject(json, json_format->function.name, cJSON_CreateString(node->func));
}
/* skip initial space and new line */
if (*full_message == ' ') {
full_message++;
}
if (*full_message == '\n') {
full_message++;
}
/* get fields from log tags */
if (node->tags) {
switch_event_dup(&log_fields, node->tags);
}
/* get fields from channel data, if configured */
if (!zstr(node->userdata) && chan_vars && chan_vars->headers && (session = switch_core_session_locate(node->userdata))) {
switch_channel_t *channel = switch_core_session_get_channel(session);
switch_event_header_t *hp;
/* session_fields name mapped to variable name */
for (hp = chan_vars->headers; hp; hp = hp->next) {
if (!zstr(hp->name) && !zstr(hp->value)) {
const char *val = switch_channel_get_variable(channel, hp->value);
if (!zstr(val)) {
if (!log_fields) {
switch_event_create_plain(&log_fields, SWITCH_EVENT_CHANNEL_DATA);
}
switch_event_add_header_string(log_fields, SWITCH_STACK_BOTTOM, hp->name, val);
}
}
}
switch_core_session_rwunlock(session);
}
/* parse list of fields from message text, if any */
if (strncmp(full_message, "LOG_FIELDS", 10) == 0) {
switch_event_create_brackets(full_message+10, '[', ']', ',', &log_fields, &parsed_full_message, SWITCH_TRUE);
full_message = parsed_full_message;
}
/* add additional fields */
if (log_fields) {
switch_event_header_t *hp;
const char *prefix = json_format->custom_field_prefix ? json_format->custom_field_prefix : "";
for (hp = log_fields->headers; hp; hp = hp->next) {
if (!zstr(hp->name) && !zstr(hp->value)) {
if (strncmp(hp->name, "@#", 2) == 0) {
field_name = switch_mprintf("%s%s", prefix, hp->name + 2);
cJSON_AddItemToObject(json, field_name, cJSON_CreateNumber(strtod(hp->value, NULL)));
} else {
field_name = switch_mprintf("%s%s", prefix, hp->name);
cJSON_AddItemToObject(json, field_name, cJSON_CreateString(hp->value));
}
free(field_name);
}
}
switch_event_destroy(&log_fields);
}
if (json_format->full_message.name) {
cJSON_AddItemToObject(json, json_format->full_message.name, cJSON_CreateString(full_message));
} else {
cJSON_AddItemToObject(json, "message", cJSON_CreateString(full_message));
}
if (json_format->short_message.name) {
char short_message[151];
char *short_message_end = NULL;
switch_snprintf(short_message, sizeof(short_message) - 1, "%s", full_message);
if ((short_message_end = strchr(short_message, '\n'))) {
*short_message_end = '\0';
}
cJSON_AddItemToObject(json, json_format->short_message.name, cJSON_CreateString(short_message));
}
switch_safe_free(parsed_full_message);
return json;
}
static switch_log_node_t *switch_log_node_alloc()
{
switch_log_node_t *node = NULL;