]> git.ipfire.org Git - thirdparty/freeswitch.git/commitdiff
[core] Add switch_log_meta_printf() and switch_log_meta_vprintf() to allow JSON metad...
authorChris Rienzo <chris@signalwire.com>
Fri, 29 Jan 2021 22:03:56 +0000 (22:03 +0000)
committerAndrey Volk <andywolk@gmail.com>
Sat, 23 Oct 2021 19:00:40 +0000 (22:00 +0300)
src/include/switch_log.h
src/switch_log.c
tests/unit/.gitignore
tests/unit/Makefile.am
tests/unit/switch_log.c [new file with mode: 0644]

index 40725a6cca0ee128001d8703c50a711019149b24..ee8f0d02ae4a853fdcb5238e73a76690c35ffc1a 100644 (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
index 054e728768c846f50ad362f3a85395988bc83b1a..c7a18c1a52fcfd0cc689b04ff27bba3e13483912 100644 (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);
 
index a9c5b8eb8f7d00515aeacbde7bbda52daf70d287..66ea66aa069aa10c4504217e601f8175371965e2 100644 (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
index 9d57dbe589fd9df50fa6dc489d7ec537f0fdde24..ee2e92b175e90177e8a06e651940fd9bf6bc4531 100644 (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)
diff --git a/tests/unit/switch_log.c b/tests/unit/switch_log.c
new file mode 100644 (file)
index 0000000..a56612f
--- /dev/null
@@ -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()