diff --git a/src/include/switch_log.h b/src/include/switch_log.h index 40725a6cca..ee8f0d02ae 100644 --- a/src/include/switch_log.h +++ b/src/include/switch_log.h @@ -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 diff --git a/src/switch_log.c b/src/switch_log.c index 054e728768..c7a18c1a52 100644 --- a/src/switch_log.c +++ b/src/switch_log.c @@ -1,6 +1,6 @@ /* * FreeSWITCH Modular Media Switching Software Library / Soft-Switch Application - * Copyright (C) 2005-2014, Anthony Minessale II + * Copyright (C) 2005-2021, Anthony Minessale II * * 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); diff --git a/tests/unit/.gitignore b/tests/unit/.gitignore index a9c5b8eb8f..66ea66aa06 100644 --- a/tests/unit/.gitignore +++ b/tests/unit/.gitignore @@ -25,6 +25,7 @@ switch_hash switch_ivr_async switch_ivr_originate switch_ivr_play_say +switch_log switch_packetizer switch_red switch_rtp diff --git a/tests/unit/Makefile.am b/tests/unit/Makefile.am index 9d57dbe589..ee2e92b175 100644 --- a/tests/unit/Makefile.am +++ b/tests/unit/Makefile.am @@ -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) diff --git a/tests/unit/switch_log.c b/tests/unit/switch_log.c new file mode 100644 index 0000000000..a56612fc28 --- /dev/null +++ b/tests/unit/switch_log.c @@ -0,0 +1,197 @@ +/* + * FreeSWITCH Modular Media Switching Software Library / Soft-Switch Application + * Copyright (C) 2021, Anthony Minessale II + * + * 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 + * Portions created by the Initial Developer are Copyright (C) + * the Initial Developer. All Rights Reserved. + * + * Contributor(s): + * Chris Rienzo + * + * + * switch_log.c -- tests core logging + * + */ +#include +#include + +#include + +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()