Preston_PLB
/
freeswitch
forked from Mirrors/freeswitch
1
0
Fork 0
Code Pull Requests Activity

[core] Add switch_log_meta_printf() and switch_log_meta_vprintf() to allow JSON metadata to tag along with the log message.

This commit is contained in:
Chris Rienzo 2021-01-29 22:03:56 +00:00 committed by Andrey Volk
parent 451900b353
commit a26d0c39b0
5 changed files with 289 additions and 7 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

35
src/include/switch_log.h
View File

@ -68,6 +68,8 @@ SWITCH_BEGIN_EXTERN_C
switch_event_t *tags;
/* Log sequence */
int64_t sequence;
/* Optional extra log metadata */
cJSON *meta;
} switch_log_node_t;
///\{
@ -157,7 +159,40 @@ SWITCH_DECLARE(void) switch_log_printf(_In_ switch_text_channel_t channel, _In_z
SWITCH_DECLARE(void) switch_log_vprintf(_In_ switch_text_channel_t channel, _In_z_ const char *file,
_In_z_ const char *func, _In_ int line,
_In_opt_z_ const char *userdata, _In_ switch_log_level_t level, const char *fmt, va_list ap);
/*!
\brief Write log data to the logging engine w/ optional JSON metadata
\param channel the log channel to write to
\param file the current file
\param func the current function
\param line the current line
\param userdata ununsed
\param level the current log level
\param meta log metadata - consumed by this function
\param fmt desired format
\param ... variable args
\note there are channel macros to supply the first 4 parameters (SWITCH_CHANNEL_LOG, SWITCH_CHANNEL_LOG_CLEAN, ...)
\see switch_types.h
*/
SWITCH_DECLARE(void) switch_log_meta_printf(switch_text_channel_t channel, const char *file, const char *func, int line,
const char *userdata, switch_log_level_t level, cJSON **meta, const char *fmt, ...) PRINTF_FUNCTION(8, 9);
/*!
\brief Write log data to the logging engine w/ optional JSON metadata
\param channel the log channel to write to
\param file the current file
\param func the current function
\param line the current line
\param userdata ununsed
\param level the current log level
\param meta log metadata - consumed by this function
\param fmt desired format
\param ap variable args
\note there are channel macros to supply the first 4 parameters (SWITCH_CHANNEL_LOG, SWITCH_CHANNEL_LOG_CLEAN, ...)
\see switch_types.h
*/
SWITCH_DECLARE(void) switch_log_meta_vprintf(_In_ switch_text_channel_t channel, _In_z_ const char *file,
_In_z_ const char *func, _In_ int line,
_In_opt_z_ const char *userdata, _In_ switch_log_level_t level, cJSON **meta, const char *fmt, va_list ap);
#endif
/*!
\brief Shut down the logging engine

61
src/switch_log.c
View File

@ -1,6 +1,6 @@
/*
* FreeSWITCH Modular Media Switching Software Library / Soft-Switch Application
* Copyright (C) 2005-2014, Anthony Minessale II <anthm@freeswitch.org>
* Copyright (C) 2005-2021, Anthony Minessale II <anthm@freeswitch.org>
*
* Version: MPL 1.1
*
@ -90,7 +90,7 @@ 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();
cJSON *json = NULL;
char *hostname;
char *full_message = node->content;
char *parsed_full_message = NULL;
@ -98,6 +98,24 @@ SWITCH_DECLARE(cJSON *) switch_log_node_to_json(const switch_log_node_t *node, i
switch_event_t *log_fields = NULL;
switch_core_session_t *session = NULL;
if (node->meta && cJSON_IsObject(node->meta)) {
if (json_format->custom_field_prefix) {
cJSON *field = NULL;
json = cJSON_CreateObject();
for (field = node->meta->child; field; field = field->next) {
if (!zstr(field->string)) {
char *field_name = switch_mprintf("%s%s", json_format->custom_field_prefix, field->string);
cJSON_AddItemToObject(json, field_name, cJSON_Duplicate(field, cJSON_True));
free(field_name);
}
}
} else {
json = cJSON_Duplicate(node->meta, cJSON_True);
}
} else {
json = cJSON_CreateObject();
}
if (json_format->version.name && json_format->version.value) {
cJSON_AddItemToObject(json, json_format->version.name, cJSON_CreateString(json_format->version.value));
}
@ -272,6 +290,10 @@ SWITCH_DECLARE(switch_log_node_t *) switch_log_node_dup(const switch_log_node_t
switch_event_dup(&newnode->tags, node->tags);
}
if (node->meta) {
newnode->meta = cJSON_Duplicate(node->meta, cJSON_True);
}
return newnode;
}
@ -291,6 +313,10 @@ SWITCH_DECLARE(void) switch_log_node_free(switch_log_node_t **pnode)
if (node->tags) {
switch_event_destroy(&node->tags);
}
if (node->meta) {
cJSON_Delete(node->meta);
node->meta = NULL;
}
#ifdef SWITCH_LOG_RECYCLE
if (switch_queue_trypush(LOG_RECYCLE_QUEUE, node) != SWITCH_STATUS_SUCCESS) {
free(node);
@ -500,13 +526,22 @@ static void *SWITCH_THREAD_FUNC log_thread(switch_thread_t *t, void *obj)
return NULL;
}
SWITCH_DECLARE(void) switch_log_meta_printf(switch_text_channel_t channel, const char *file, const char *func, int line,
const char *userdata, switch_log_level_t level, cJSON **meta, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
switch_log_meta_vprintf(channel, file, func, line, userdata, level, meta, fmt, ap);
va_end(ap);
}
SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char *file, const char *func, int line,
const char *userdata, switch_log_level_t level, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
switch_log_vprintf(channel, file, func, line, userdata, level, fmt, ap);
switch_log_meta_vprintf(channel, file, func, line, userdata, level, NULL, fmt, ap);
va_end(ap);
}
@ -514,6 +549,12 @@ SWITCH_DECLARE(void) switch_log_printf(switch_text_channel_t channel, const char
SWITCH_DECLARE(void) switch_log_vprintf(switch_text_channel_t channel, const char *file, const char *func, int line,
const char *userdata, switch_log_level_t level, const char *fmt, va_list ap)
{
switch_log_meta_vprintf(channel, file, func, line, userdata, level, NULL, fmt, ap);
}
SWITCH_DECLARE(void) switch_log_meta_vprintf(switch_text_channel_t channel, const char *file, const char *func, int line,
const char *userdata, switch_log_level_t level, cJSON **meta, const char *fmt, va_list ap)
{
cJSON *log_meta = NULL;
char *data = NULL;
char *new_fmt = NULL;
int ret = 0;
@ -531,8 +572,13 @@ SWITCH_DECLARE(void) switch_log_vprintf(switch_text_channel_t channel, const cha
switch_log_level_t limit_level = runtime.hard_log_level;
switch_log_level_t special_level = SWITCH_LOG_UNINIT;
if (meta && *meta) {
log_meta = *meta;
*meta = NULL;
}
if (limit_level == SWITCH_LOG_DISABLE) {
return;
goto end;
}
if (channel == SWITCH_CHANNEL_ID_SESSION && userdata) {
@ -545,14 +591,14 @@ SWITCH_DECLARE(void) switch_log_vprintf(switch_text_channel_t channel, const cha
if (level > 100) {
if ((uint32_t) (level - 100) > runtime.debug_level) {
return;
goto end;
}
level = 1;
}
if (level > limit_level) {
return;
goto end;
}
switch_assert(level < SWITCH_LOG_INVALID);
@ -671,6 +717,8 @@ SWITCH_DECLARE(void) switch_log_vprintf(switch_text_channel_t channel, const cha
node->timestamp = now;
node->channel = channel;
node->tags = NULL;
node->meta = log_meta;
log_meta = NULL;
if (channel == SWITCH_CHANNEL_ID_SESSION) {
switch_core_session_t *session = (switch_core_session_t *) userdata;
node->userdata = userdata ? strdup(switch_core_session_get_uuid(session)) : NULL;
@ -688,6 +736,7 @@ SWITCH_DECLARE(void) switch_log_vprintf(switch_text_channel_t channel, const cha
end:
cJSON_Delete(log_meta);
switch_safe_free(data);
switch_safe_free(new_fmt);

1
tests/unit/.gitignore vendored
View File

@ -25,6 +25,7 @@ switch_hash
switch_ivr_async
switch_ivr_originate
switch_ivr_play_say
switch_log
switch_packetizer
switch_red
switch_rtp

2
tests/unit/Makefile.am
View File

@ -2,7 +2,7 @@ include $(top_srcdir)/build/modmake.rulesam
noinst_PROGRAMS = switch_event switch_hash switch_ivr_originate switch_utils switch_core switch_console switch_vpx switch_core_file \
switch_ivr_play_say switch_core_codec switch_rtp switch_xml
noinst_PROGRAMS += switch_core_video switch_core_db switch_vad switch_packetizer test_sofia switch_ivr_async switch_core_asr switch_core_session
noinst_PROGRAMS += switch_core_video switch_core_db switch_vad switch_packetizer switch_core_session test_sofia switch_ivr_async switch_core_asr switch_log
AM_LDFLAGS += -avoid-version -no-undefined $(SWITCH_AM_LDFLAGS) $(openssl_LIBS)
AM_LDFLAGS += $(FREESWITCH_LIBS) $(switch_builddir)/libfreeswitch.la $(CORE_LIBS) $(APR_LIBS)

197
tests/unit/switch_log.c Normal file
View File

@ -0,0 +1,197 @@
/*
* FreeSWITCH Modular Media Switching Software Library / Soft-Switch Application
* Copyright (C) 2021, Anthony Minessale II <anthm@freeswitch.org>
*
* Version: MPL 1.1
*
* The contents of this file are subject to the Mozilla Public License Version
* 1.1 (the "License"); you may not use this file except in compliance with
* the License. You may obtain a copy of the License at
* http://www.mozilla.org/MPL/
*
* Software distributed under the License is distributed on an "AS IS" basis,
* WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
* for the specific language governing rights and limitations under the
* License.
*
* The Original Code is FreeSWITCH Modular Media Switching Software Library / Soft-Switch Application
*
* The Initial Developer of the Original Code is
* Anthony Minessale II <anthm@freeswitch.org>
* Portions created by the Initial Developer are Copyright (C)
* the Initial Developer. All Rights Reserved.
*
* Contributor(s):
* Chris Rienzo <chris@signalwire.com>
*
*
* switch_log.c -- tests core logging
*
*/
#include <switch.h>
#include <stdlib.h>
#include <test/switch_test.h>
switch_memory_pool_t *pool = NULL;
static switch_mutex_t *mutex = NULL;
switch_thread_cond_t *cond = NULL;
static cJSON *last_alert_log = NULL;
static switch_log_json_format_t json_format = {
{ NULL, NULL }, // version
{ NULL, NULL }, // host
{ NULL, NULL }, // timestamp
{ "level", NULL }, // level
{ NULL, NULL }, // ident
{ NULL, NULL }, // pid
{ NULL, NULL }, // uuid
{ NULL, NULL }, // file
{ NULL, NULL }, // line
{ NULL, NULL }, // function
{ "message", NULL }, // full_message
{ NULL, NULL }, // short_message
NULL, // custom_field_prefix
0.0, // timestamp_divisor
{ NULL, NULL } // sequence
};
static switch_status_t test_logger(const switch_log_node_t *node, switch_log_level_t level)
{
switch_mutex_lock(mutex);
if (level == SWITCH_LOG_ALERT && !last_alert_log && node->content && strstr(node->content, "switch_log test: ")) {
last_alert_log = switch_log_node_to_json(node, level, &json_format, NULL);
switch_thread_cond_signal(cond);
}
switch_mutex_unlock(mutex);
return SWITCH_STATUS_SUCCESS;
}
static char *wait_for_log(switch_interval_time_t timeout_ms)
{
char *log_str = NULL;
cJSON *log = NULL;
switch_time_t now = switch_time_now();
switch_time_t expiration = now + (timeout_ms * 1000);
switch_mutex_lock(mutex);
while (!last_alert_log && (now = switch_time_now()) < expiration) {
switch_interval_time_t timeout = expiration - now;
switch_thread_cond_timedwait(cond, mutex, timeout);
}
log = last_alert_log;
last_alert_log = NULL;
switch_mutex_unlock(mutex);
if (log) {
log_str = cJSON_PrintUnformatted(log);
cJSON_Delete(log);
}
return log_str;
}
FST_CORE_BEGIN("./conf")
{
switch_core_new_memory_pool(&pool);
switch_mutex_init(&mutex, SWITCH_MUTEX_NESTED, pool);
switch_thread_cond_create(&cond, pool);
FST_SUITE_BEGIN(switch_log)
{
FST_SETUP_BEGIN()
{
json_format.custom_field_prefix = NULL;
}
FST_SETUP_END()
FST_TEARDOWN_BEGIN()
{
}
FST_TEARDOWN_END()
FST_SESSION_BEGIN(switch_log_meta_printf)
{
cJSON *item = NULL;
cJSON *meta = NULL;
char *log = NULL;
switch_log_bind_logger(test_logger, SWITCH_LOG_ALERT, SWITCH_FALSE);
switch_log_meta_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ALERT, NULL, "switch_log test: Plain channel log %d\n", 0);
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"level\":1,\"message\":\"switch_log test: Plain channel log 0\\n\"}");
switch_safe_free(log);
switch_log_meta_printf(SWITCH_CHANNEL_SESSION_LOG(fst_session), SWITCH_LOG_ALERT, NULL, "switch_log test: Plain session log %d\n", 1);
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"level\":1,\"message\":\"switch_log test: Plain session log 1\\n\"}");
switch_safe_free(log);
switch_log_meta_printf(SWITCH_CHANNEL_UUID_LOG(switch_core_session_get_uuid(fst_session)), SWITCH_LOG_ALERT, NULL, "switch_log test: Plain uuid log %d\n", 2);
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"level\":1,\"message\":\"switch_log test: Plain uuid log 2\\n\"}");
switch_safe_free(log);
meta = cJSON_CreateObject();
cJSON_AddStringToObject(meta, "foo", "bar");
cJSON_AddNumberToObject(meta, "measure", 3.14159);
switch_log_meta_printf(SWITCH_CHANNEL_LOG, SWITCH_LOG_ALERT, &meta, "switch_log test: channel log with metadata %d\n", 3);
fst_xcheck(meta == NULL, "Expect logging meta data to be consumed by switch_log_meta_printf()");
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"foo\":\"bar\",\"measure\":3.14159,\"level\":1,\"message\":\"switch_log test: channel log with metadata 3\\n\"}");
switch_safe_free(log);
meta = cJSON_CreateObject();
cJSON_AddStringToObject(meta, "foo", "bar");
cJSON_AddNumberToObject(meta, "measure", 3.14159);
switch_log_meta_printf(SWITCH_CHANNEL_SESSION_LOG(fst_session), SWITCH_LOG_ALERT, &meta, "switch_log test: Session log with metadata %d\n", 4);
fst_xcheck(meta == NULL, "Expect logging meta data to be consumed by switch_log_meta_printf()");
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"foo\":\"bar\",\"measure\":3.14159,\"level\":1,\"message\":\"switch_log test: Session log with metadata 4\\n\"}");
switch_safe_free(log);
meta = cJSON_CreateObject();
cJSON_AddStringToObject(meta, "foo", "bar");
cJSON_AddNumberToObject(meta, "measure", 3.14159);
switch_log_meta_printf(SWITCH_CHANNEL_UUID_LOG(switch_core_session_get_uuid(fst_session)), SWITCH_LOG_ALERT, &meta, "switch_log test: uuid log with metadata %d\n", 5);
fst_xcheck(meta == NULL, "Expect logging meta data to be consumed by switch_log_meta_printf()");
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"foo\":\"bar\",\"measure\":3.14159,\"level\":1,\"message\":\"switch_log test: uuid log with metadata 5\\n\"}");
switch_safe_free(log);
meta = cJSON_CreateObject();
item = cJSON_AddObjectToObject(meta, "nested");
cJSON_AddStringToObject(item, "stringval", "1234");
item = cJSON_AddArrayToObject(item, "array");
cJSON_AddItemToArray(item, cJSON_CreateString("12"));
item = cJSON_AddArrayToObject(meta, "array2");
cJSON_AddItemToArray(item, cJSON_CreateString("34"));
switch_log_meta_printf(SWITCH_CHANNEL_SESSION_LOG(fst_session), SWITCH_LOG_ALERT, &meta, "switch_log test: session log with complex metadata %d\n", 6);
fst_xcheck(meta == NULL, "Expect logging meta data to be consumed by switch_log_meta_printf()");
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"nested\":{\"stringval\":\"1234\",\"array\":[\"12\"]},\"array2\":[\"34\"],\"level\":1,\"message\":\"switch_log test: session log with complex metadata 6\\n\"}");
switch_safe_free(log);
meta = cJSON_CreateObject();
item = cJSON_AddObjectToObject(meta, "nested");
cJSON_AddStringToObject(item, "stringval", "1234");
item = cJSON_AddArrayToObject(item, "array");
cJSON_AddItemToArray(item, cJSON_CreateString("12"));
item = cJSON_AddArrayToObject(meta, "array2");
cJSON_AddItemToArray(item, cJSON_CreateString("34"));
json_format.custom_field_prefix = "prefix.";
switch_log_meta_printf(SWITCH_CHANNEL_SESSION_LOG(fst_session), SWITCH_LOG_ALERT, &meta, "switch_log test: session log with prefixed complex metadata %d\n", 7);
fst_xcheck(meta == NULL, "Expect logging meta data to be consumed by switch_log_meta_printf()");
log = wait_for_log(1000);
fst_check_string_equals(log, "{\"prefix.nested\":{\"stringval\":\"1234\",\"array\":[\"12\"]},\"prefix.array2\":[\"34\"],\"level\":1,\"message\":\"switch_log test: session log with prefixed complex metadata 7\\n\"}");
switch_safe_free(log);
cJSON_Delete(last_alert_log);
last_alert_log = NULL;
switch_log_unbind_logger(test_logger);
}
FST_SESSION_END()
}
FST_SUITE_END()
switch_core_destroy_memory_pool(&pool);
}
FST_CORE_END()