From fed72692bfbbfbd110ab4ddb5fcb6e82ca19c496 Mon Sep 17 00:00:00 2001 From: Philippe Proulx Date: Mon, 19 Jun 2017 15:58:27 -0400 Subject: [PATCH] plugins/utils/muxer/muxer.c: add logging MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Signed-off-by: Philippe Proulx Signed-off-by: Jérémie Galarneau --- cli/babeltrace.c | 1 + .../babeltrace/graph/connection-internal.h | 21 + plugins/utils/Makefile.am | 5 +- plugins/utils/muxer/Makefile.am | 2 +- plugins/utils/muxer/logging.c | 27 ++ plugins/utils/muxer/logging.h | 31 ++ plugins/utils/muxer/muxer.c | 374 +++++++++++++++++- plugins/utils/trimmer/Makefile.am | 9 - 8 files changed, 443 insertions(+), 27 deletions(-) create mode 100644 plugins/utils/muxer/logging.c create mode 100644 plugins/utils/muxer/logging.h diff --git a/cli/babeltrace.c b/cli/babeltrace.c index 2c978215..c804321a 100644 --- a/cli/babeltrace.c +++ b/cli/babeltrace.c @@ -73,6 +73,7 @@ static const char* log_level_env_var_names[] = { "BABELTRACE_PLUGIN_CTF_METADATA_LOG_LEVEL", "BABELTRACE_PLUGIN_CTF_NOTIF_ITER_LOG_LEVEL", "BABELTRACE_PLUGIN_LTTNG_UTILS_DEBUG_INFO_FLT_LOG_LEVEL", + "BABELTRACE_PLUGIN_UTILS_MUXER_FLT_LOG_LEVEL", "BABELTRACE_PLUGIN_UTILS_TRIMMER_FLT_LOG_LEVEL", "BABELTRACE_PYTHON_PLUGIN_PROVIDER_LOG_LEVEL", NULL, diff --git a/include/babeltrace/graph/connection-internal.h b/include/babeltrace/graph/connection-internal.h index 6044f0a5..7b4d26d2 100644 --- a/include/babeltrace/graph/connection-internal.h +++ b/include/babeltrace/graph/connection-internal.h @@ -122,4 +122,25 @@ bt_connection_status_from_notification_iterator_status( } } +static inline +const char *bt_connection_status_string(enum bt_connection_status status) +{ + switch (status) { + case BT_CONNECTION_STATUS_GRAPH_IS_CANCELED: + return "BT_CONNECTION_STATUS_GRAPH_IS_CANCELED"; + case BT_CONNECTION_STATUS_OK: + return "BT_CONNECTION_STATUS_OK"; + case BT_CONNECTION_STATUS_INVALID: + return "BT_CONNECTION_STATUS_INVALID"; + case BT_CONNECTION_STATUS_ERROR: + return "BT_CONNECTION_STATUS_ERROR"; + case BT_CONNECTION_STATUS_NOMEM: + return "BT_CONNECTION_STATUS_NOMEM"; + case BT_CONNECTION_STATUS_IS_ENDED: + return "BT_CONNECTION_STATUS_IS_ENDED"; + default: + return "(unknown)"; + } +} + #endif /* BABELTRACE_COMPONENT_CONNECTION_INTERNAL_H */ diff --git a/plugins/utils/Makefile.am b/plugins/utils/Makefile.am index 8784d046..decee2c5 100644 --- a/plugins/utils/Makefile.am +++ b/plugins/utils/Makefile.am @@ -16,5 +16,8 @@ babeltrace_plugin_utils_la_LIBADD = \ if !BUILT_IN_PLUGINS babeltrace_plugin_utils_la_LIBADD += \ - $(top_builddir)/lib/libbabeltrace.la + $(top_builddir)/lib/libbabeltrace.la \ + $(top_builddir)/plugins/libctfcopytrace/libctfcopytrace.la \ + $(top_builddir)/common/libbabeltrace-common.la \ + $(top_builddir)/logging/libbabeltrace-logging.la endif diff --git a/plugins/utils/muxer/Makefile.am b/plugins/utils/muxer/Makefile.am index f69d46a1..4c4f9d21 100644 --- a/plugins/utils/muxer/Makefile.am +++ b/plugins/utils/muxer/Makefile.am @@ -1,4 +1,4 @@ AM_CFLAGS = $(PACKAGE_CFLAGS) -I$(top_srcdir)/include -I$(top_srcdir)/plugins noinst_LTLIBRARIES = libbabeltrace-plugin-muxer.la -libbabeltrace_plugin_muxer_la_SOURCES = muxer.c muxer.h +libbabeltrace_plugin_muxer_la_SOURCES = muxer.c muxer.h logging.c logging.h diff --git a/plugins/utils/muxer/logging.c b/plugins/utils/muxer/logging.c new file mode 100644 index 00000000..814143fb --- /dev/null +++ b/plugins/utils/muxer/logging.c @@ -0,0 +1,27 @@ +/* + * Copyright (c) 2017 Philippe Proulx + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, + * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE + * SOFTWARE. + */ + +#define BT_LOG_OUTPUT_LEVEL bt_plugin_utils_muxer_log_level +#include + +BT_LOG_INIT_LOG_LEVEL(bt_plugin_utils_muxer_log_level, + "BABELTRACE_PLUGIN_UTILS_MUXER_FLT_LOG_LEVEL"); diff --git a/plugins/utils/muxer/logging.h b/plugins/utils/muxer/logging.h new file mode 100644 index 00000000..3c9dd65a --- /dev/null +++ b/plugins/utils/muxer/logging.h @@ -0,0 +1,31 @@ +#ifndef PLUGINS_UTILS_MUXER_LOGGING_H +#define PLUGINS_UTILS_MUXER_LOGGING_H + +/* + * Copyright (c) 2017 Philippe Proulx + * + * Permission is hereby granted, free of charge, to any person obtaining a copy + * of this software and associated documentation files (the "Software"), to deal + * in the Software without restriction, including without limitation the rights + * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell + * copies of the Software, and to permit persons to whom the Software is + * furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in + * all copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE + * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, + * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE + * SOFTWARE. + */ + +#define BT_LOG_OUTPUT_LEVEL bt_plugin_utils_muxer_log_level +#include + +BT_LOG_LEVEL_EXTERN_SYMBOL(bt_plugin_utils_muxer_log_level); + +#endif /* PLUGINS_UTILS_MUXER_LOGGING_H */ diff --git a/plugins/utils/muxer/muxer.c b/plugins/utils/muxer/muxer.c index dbc135c8..8a4ae4e1 100644 --- a/plugins/utils/muxer/muxer.c +++ b/plugins/utils/muxer/muxer.c @@ -20,6 +20,9 @@ * SOFTWARE. */ +#define BT_LOG_TAG "PLUGIN-UTILS-MUXER-FLT" +#include "logging.h" + #include #include #include @@ -27,9 +30,11 @@ #include #include #include +#include #include #include #include +#include #include #include #include @@ -39,9 +44,12 @@ #include #include #include +#include +#include #include #include #include +#include #include #include #include @@ -133,6 +141,11 @@ void destroy_muxer_upstream_notif_iter( return; } + BT_LOGD("Destroying muxer's upstream notification iterator wrapper: " + "addr=%p, notif-iter-addr=%p, is-valid=%d", + muxer_upstream_notif_iter, + muxer_upstream_notif_iter->notif_iter, + muxer_upstream_notif_iter->is_valid); bt_put(muxer_upstream_notif_iter->notif_iter); g_free(muxer_upstream_notif_iter); } @@ -147,6 +160,7 @@ struct muxer_upstream_notif_iter *muxer_notif_iter_add_upstream_notif_iter( g_new0(struct muxer_upstream_notif_iter, 1); if (!muxer_upstream_notif_iter) { + BT_LOGE_STR("Failed to allocate one muxer's upstream notification iterator wrapper."); goto end; } @@ -154,6 +168,10 @@ struct muxer_upstream_notif_iter *muxer_notif_iter_add_upstream_notif_iter( muxer_upstream_notif_iter->is_valid = false; g_ptr_array_add(muxer_notif_iter->muxer_upstream_notif_iters, muxer_upstream_notif_iter); + BT_LOGD("Added muxer's upstream notification iterator wrapper: " + "addr=%p, muxer-notif-iter-addr=%p, notif-iter-addr=%p", + muxer_upstream_notif_iter, muxer_notif_iter, + notif_iter); end: return muxer_upstream_notif_iter; @@ -176,6 +194,7 @@ enum bt_component_status ensure_available_input_port( port_name = g_string_new("in"); if (!port_name) { + BT_LOGE_STR("Failed to allocate a GString."); status = BT_COMPONENT_STATUS_NOMEM; goto end; } @@ -184,12 +203,18 @@ enum bt_component_status ensure_available_input_port( status = bt_private_component_filter_add_input_private_port( priv_comp, port_name->str, NULL, NULL); if (status != BT_COMPONENT_STATUS_OK) { + BT_LOGE("Cannot add input port to muxer component: " + "port-name=\"%s\", comp-addr=%p, status=%s", + port_name->str, priv_comp, + bt_component_status_string(status)); goto end; } muxer_comp->available_input_ports++; muxer_comp->next_port_num++; - + BT_LOGD("Added one input port to muxer component: " + "port-name=\"%s\", comp-addr=%p", + port_name->str, priv_comp); end: if (port_name) { g_string_free(port_name, TRUE); @@ -213,6 +238,10 @@ void destroy_muxer_comp(struct muxer_comp *muxer_comp) return; } + BT_LOGD("Destroying muxer component: muxer-comp-addr=%p, " + "muxer-notif-iter-count=%u", muxer_comp, + muxer_comp->muxer_notif_iters->len); + if (muxer_comp->muxer_notif_iters) { g_ptr_array_free(muxer_comp->muxer_notif_iters, TRUE); } @@ -228,12 +257,14 @@ struct bt_value *get_default_params(void) params = bt_value_map_create(); if (!params) { + BT_LOGE_STR("Cannot create a map value object."); goto error; } ret = bt_value_map_insert_bool(params, ASSUME_ABSOLUTE_CLOCK_CLASSES_PARAM_NAME, false); if (ret) { + BT_LOGE_STR("Cannot add boolean value to map value object."); goto error; } @@ -257,26 +288,37 @@ int configure_muxer_comp(struct muxer_comp *muxer_comp, struct bt_value *params) default_params = get_default_params(); if (!default_params) { + BT_LOGE("Cannot get default parameters: " + "muxer-comp-addr=%p", muxer_comp); goto error; } real_params = bt_value_map_extend(default_params, params); if (!real_params) { + BT_LOGE("Cannot extend default parameters map value: " + "muxer-comp-addr=%p, def-params-addr=%p, " + "params-addr=%p", muxer_comp, default_params, + params); goto error; } assume_absolute_clock_classes = bt_value_map_get(real_params, ASSUME_ABSOLUTE_CLOCK_CLASSES_PARAM_NAME); if (!bt_value_is_bool(assume_absolute_clock_classes)) { + BT_LOGE("Expecting a boolean value for the `%s` parameter: " + "muxer-comp-addr=%p, value-type=%s", + ASSUME_ABSOLUTE_CLOCK_CLASSES_PARAM_NAME, muxer_comp, + bt_value_type_string( + bt_value_get_type(assume_absolute_clock_classes))); goto error; } - if (bt_value_bool_get(assume_absolute_clock_classes, &bool_val)) { - goto error; - } - + ret = bt_value_bool_get(assume_absolute_clock_classes, &bool_val); + assert(ret == 0); muxer_comp->assume_absolute_clock_classes = (bool) bool_val; - + BT_LOGD("Configured muxer component: muxer-comp-addr=%p, " + "assume-absolute-clock-classes=%d", + muxer_comp, muxer_comp->assume_absolute_clock_classes); goto end; error: @@ -298,17 +340,25 @@ enum bt_component_status muxer_init( enum bt_component_status status = BT_COMPONENT_STATUS_OK; struct muxer_comp *muxer_comp = g_new0(struct muxer_comp, 1); + BT_LOGD("Initializing muxer component: " + "comp-addr=%p, params-addr=%p", priv_comp, params); + if (!muxer_comp) { + BT_LOGE_STR("Failed to allocate one muxer component."); goto error; } ret = configure_muxer_comp(muxer_comp, params); if (ret) { + BT_LOGE("Cannot configure muxer component: " + "muxer-comp-addr=%p, params-addr=%p", + muxer_comp, params); goto error; } muxer_comp->muxer_notif_iters = g_ptr_array_new(); if (!muxer_comp->muxer_notif_iters) { + BT_LOGE_STR("Failed to allocate a GPtrArray."); goto error; } @@ -317,14 +367,26 @@ enum bt_component_status muxer_init( assert(ret == 0); status = ensure_available_input_port(priv_comp); if (status != BT_COMPONENT_STATUS_OK) { + BT_LOGE("Cannot ensure that at least one muxer component's input port is available: " + "muxer-comp-addr=%p, status=%s", + muxer_comp, + bt_component_status_string(status)); goto error; } - ret = create_output_port(priv_comp); - if (ret) { + status = create_output_port(priv_comp); + if (status) { + BT_LOGE("Cannot create muxer component's output port: " + "muxer-comp-addr=%p, status=%s", + muxer_comp, + bt_component_status_string(status)); goto error; } + BT_LOGD("Initialized muxer component: " + "comp-addr=%p, params-addr=%p, muxer-comp-addr=%p", + priv_comp, params, muxer_comp); + goto end; error: @@ -346,6 +408,8 @@ void muxer_finalize(struct bt_private_component *priv_comp) struct muxer_comp *muxer_comp = bt_private_component_get_user_data(priv_comp); + BT_LOGD("Finalizing muxer component: comp-addr=%p", + priv_comp); destroy_muxer_comp(muxer_comp); } @@ -361,13 +425,9 @@ struct bt_notification_iterator *create_notif_iter_on_input_port( assert(ret); *ret = 0; assert(port); - assert(bt_port_is_connected(port)); priv_conn = bt_private_port_get_private_connection(priv_port); - if (!priv_conn) { - *ret = -1; - goto end; - } + assert(priv_conn); // TODO: Advance the iterator to >= the time of the latest // returned notification by the muxer notification @@ -375,10 +435,20 @@ struct bt_notification_iterator *create_notif_iter_on_input_port( conn_status = bt_private_connection_create_notification_iterator( priv_conn, NULL, ¬if_iter); if (conn_status != BT_CONNECTION_STATUS_OK) { + BT_LOGE("Cannot create upstream notification iterator on input port's connection: " + "port-addr=%p, port-name=\"%s\", conn-addr=%p, " + "status=%s", + port, bt_port_get_name(port), priv_conn, + bt_connection_status_string(conn_status)); *ret = -1; goto end; } + BT_LOGD("Created upstream notification iterator on input port's connection: " + "port-addr=%p, port-name=\"%s\", conn-addr=%p, " + "notif-iter-addr=%p", + port, bt_port_get_name(port), priv_conn, notif_iter); + end: bt_put(port); bt_put(priv_conn); @@ -391,8 +461,14 @@ enum bt_notification_iterator_status muxer_upstream_notif_iter_next( { enum bt_notification_iterator_status status; + BT_LOGV("Calling upstream notification iterator's \"next\" method: " + "muxer-upstream-notif-iter-wrap-addr=%p, notif-iter-addr=%p", + muxer_upstream_notif_iter, + muxer_upstream_notif_iter->notif_iter); status = bt_notification_iterator_next( muxer_upstream_notif_iter->notif_iter); + BT_LOGV("Upstream notification iterator's \"next\" method returned: " + "status=%s", bt_notification_iterator_status_string(status)); switch (status) { case BT_NOTIFICATION_ITERATOR_STATUS_OK: @@ -400,6 +476,7 @@ enum bt_notification_iterator_status muxer_upstream_notif_iter_next( * Notification iterator's current notification is valid: * it must be considered for muxing operations. */ + BT_LOGV_STR("Validated upstream notification iterator wrapper."); muxer_upstream_notif_iter->is_valid = true; break; case BT_NOTIFICATION_ITERATOR_STATUS_AGAIN: @@ -409,6 +486,7 @@ enum bt_notification_iterator_status muxer_upstream_notif_iter_next( * BT_NOTIFICATION_ITERATOR_STATUS_AGAIN * immediately. */ + BT_LOGV_STR("Invalidated upstream notification iterator wrapper because of BT_NOTIFICATION_ITERATOR_STATUS_AGAIN."); muxer_upstream_notif_iter->is_valid = false; break; case BT_NOTIFICATION_ITERATOR_STATUS_END: /* Fall-through. */ @@ -418,12 +496,15 @@ enum bt_notification_iterator_status muxer_upstream_notif_iter_next( * won't be considered again to find the youngest * notification. */ + BT_LOGV_STR("Invalidated upstream notification iterator wrapper because of BT_NOTIFICATION_ITERATOR_STATUS_END or BT_NOTIFICATION_ITERATOR_STATUS_CANCELED."); BT_PUT(muxer_upstream_notif_iter->notif_iter); muxer_upstream_notif_iter->is_valid = false; status = BT_NOTIFICATION_ITERATOR_STATUS_OK; break; default: /* Error or unsupported status code */ + BT_LOGE("Error or unsupported status code: " + "status-code=%d", status); status = BT_NOTIFICATION_ITERATOR_STATUS_ERROR; break; } @@ -437,6 +518,9 @@ int muxer_notif_iter_handle_newly_connected_ports( { int ret = 0; + BT_LOGV("Handling newly connected ports: " + "muxer-notif-iter-addr=%p", muxer_notif_iter); + /* * Here we create one upstream notification iterator for each * newly connected port. We do not perform an initial "next" on @@ -474,6 +558,7 @@ int muxer_notif_iter_handle_newly_connected_ports( upstream_notif_iter = create_notif_iter_on_input_port(priv_port, &ret); if (ret) { + /* create_notif_iter_on_input_port() logs errors */ assert(!upstream_notif_iter); goto error; } @@ -484,6 +569,10 @@ int muxer_notif_iter_handle_newly_connected_ports( priv_port); BT_PUT(upstream_notif_iter); if (!muxer_upstream_notif_iter) { + /* + * muxer_notif_iter_add_upstream_notif_iter() + * logs errors. + */ goto error; } @@ -519,10 +608,16 @@ int get_notif_ts_ns(struct muxer_comp *muxer_comp, struct bt_ctf_event *event = NULL; int ret = 0; const unsigned char *cc_uuid; + const char *cc_name; assert(notif); assert(ts_ns); + BT_LOGV("Getting notification's timestamp: " + "muxer-notif-iter-addr=%p, notif-addr=%p, " + "last-returned-ts=%" PRId64, + muxer_notif_iter, notif, last_returned_ts_ns); + switch (bt_notification_get_type(notif)) { case BT_NOTIFICATION_TYPE_EVENT: cc_prio_map = @@ -537,11 +632,14 @@ int get_notif_ts_ns(struct muxer_comp *muxer_comp, break; default: /* All the other notifications have a higher priority */ + BT_LOGV_STR("Notification has no timestamp: using the last returned timestamp."); *ts_ns = last_returned_ts_ns; goto end; } if (!cc_prio_map) { + BT_LOGE("Cannot get notification's clock class priority map: " + "notif-addr=%p", notif); goto error; } @@ -551,6 +649,8 @@ int get_notif_ts_ns(struct muxer_comp *muxer_comp, * the youngest. */ if (bt_clock_class_priority_map_get_clock_class_count(cc_prio_map) == 0) { + BT_LOGV_STR("Notification's clock class priorty map contains 0 clock classes: " + "using the last returned timestamp."); *ts_ns = last_returned_ts_ns; goto end; } @@ -559,10 +659,13 @@ int get_notif_ts_ns(struct muxer_comp *muxer_comp, bt_clock_class_priority_map_get_highest_priority_clock_class( cc_prio_map); if (!clock_class) { + BT_LOGE("Cannot get the clock class with the highest priority from clock class priority map: " + "cc-prio-map-addr=%p", cc_prio_map); goto error; } cc_uuid = bt_ctf_clock_class_get_uuid(clock_class); + cc_name = bt_ctf_clock_class_get_name(clock_class); if (muxer_notif_iter->clock_class_expectation == MUXER_NOTIF_ITER_CLOCK_CLASS_EXPECTATION_ANY) { @@ -602,34 +705,112 @@ int get_notif_ts_ns(struct muxer_comp *muxer_comp, switch (muxer_notif_iter->clock_class_expectation) { case MUXER_NOTIF_ITER_CLOCK_CLASS_EXPECTATION_ABSOLUTE: if (!bt_ctf_clock_class_is_absolute(clock_class)) { + BT_LOGE("Expecting an absolute clock class, " + "but got a non-absolute one: " + "clock-class-addr=%p, clock-class-name=\"%s\"", + clock_class, cc_name); goto error; } break; case MUXER_NOTIF_ITER_CLOCK_CLASS_EXPECTATION_NOT_ABS_NO_UUID: if (bt_ctf_clock_class_is_absolute(clock_class)) { + BT_LOGE("Expecting a non-absolute clock class with no UUID, " + "but got an absolute one: " + "clock-class-addr=%p, clock-class-name=\"%s\"", + clock_class, cc_name); goto error; } if (cc_uuid) { + BT_LOGE("Expecting a non-absolute clock class with no UUID, " + "but got one with a UUID: " + "clock-class-addr=%p, clock-class-name=\"%s\", " + "uuid=\"%02x%02x%02x%02x-%02x%02x-%02x%02x-%02x%02x-%02x%02x%02x%02x%02x%02x\"", + clock_class, cc_name, + (unsigned int) cc_uuid[0], + (unsigned int) cc_uuid[1], + (unsigned int) cc_uuid[2], + (unsigned int) cc_uuid[3], + (unsigned int) cc_uuid[4], + (unsigned int) cc_uuid[5], + (unsigned int) cc_uuid[6], + (unsigned int) cc_uuid[7], + (unsigned int) cc_uuid[8], + (unsigned int) cc_uuid[9], + (unsigned int) cc_uuid[10], + (unsigned int) cc_uuid[11], + (unsigned int) cc_uuid[12], + (unsigned int) cc_uuid[13], + (unsigned int) cc_uuid[14], + (unsigned int) cc_uuid[15]); goto error; } break; case MUXER_NOTIF_ITER_CLOCK_CLASS_EXPECTATION_NOT_ABS_SPEC_UUID: if (bt_ctf_clock_class_is_absolute(clock_class)) { + BT_LOGE("Expecting a non-absolute clock class with a specific UUID, " + "but got an absolute one: " + "clock-class-addr=%p, clock-class-name=\"%s\"", + clock_class, cc_name); goto error; } if (!cc_uuid) { + BT_LOGE("Expecting a non-absolute clock class with a specific UUID, " + "but got one with no UUID: " + "clock-class-addr=%p, clock-class-name=\"%s\"", + clock_class, cc_name); goto error; } if (memcmp(muxer_notif_iter->expected_clock_class_uuid, cc_uuid, BABELTRACE_UUID_LEN) != 0) { + BT_LOGE("Expecting a non-absolute clock class with a specific UUID, " + "but got one with different UUID: " + "clock-class-addr=%p, clock-class-name=\"%s\", " + "expected-uuid=\"%02x%02x%02x%02x-%02x%02x-%02x%02x-%02x%02x-%02x%02x%02x%02x%02x%02x\", " + "uuid=\"%02x%02x%02x%02x-%02x%02x-%02x%02x-%02x%02x-%02x%02x%02x%02x%02x%02x\"", + clock_class, cc_name, + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[0], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[1], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[2], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[3], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[4], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[5], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[6], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[7], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[8], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[9], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[10], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[11], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[12], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[13], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[14], + (unsigned int) muxer_notif_iter->expected_clock_class_uuid[15], + (unsigned int) cc_uuid[0], + (unsigned int) cc_uuid[1], + (unsigned int) cc_uuid[2], + (unsigned int) cc_uuid[3], + (unsigned int) cc_uuid[4], + (unsigned int) cc_uuid[5], + (unsigned int) cc_uuid[6], + (unsigned int) cc_uuid[7], + (unsigned int) cc_uuid[8], + (unsigned int) cc_uuid[9], + (unsigned int) cc_uuid[10], + (unsigned int) cc_uuid[11], + (unsigned int) cc_uuid[12], + (unsigned int) cc_uuid[13], + (unsigned int) cc_uuid[14], + (unsigned int) cc_uuid[15]); goto error; } break; default: /* Unexpected */ + BT_LOGF("Unexpected clock class expectation: " + "expectation-code=%d", + muxer_notif_iter->clock_class_expectation); abort(); } } @@ -646,15 +827,22 @@ int get_notif_ts_ns(struct muxer_comp *muxer_comp, notif, clock_class); break; default: + BT_LOGF("Unexpected notification type at this point: " + "type=%d", bt_notification_get_type(notif)); abort(); } if (!clock_value) { + BT_LOGE("Cannot get notification's clock value for clock class: " + "clock-class-addr=%p, clock-class-name=\"%s\"", + clock_class, cc_name); goto error; } ret = bt_ctf_clock_value_get_value_ns_from_epoch(clock_value, ts_ns); if (ret) { + BT_LOGE("Cannot get nanoseconds from Epoch of clock value: " + "clock-value-addr=%p", clock_value); goto error; } @@ -664,6 +852,14 @@ error: ret = -1; end: + if (ret == 0) { + BT_LOGV("Found notification's timestamp: " + "muxer-notif-iter-addr=%p, notif-addr=%p, " + "last-returned-ts=%" PRId64 ", ts=%" PRId64, + muxer_notif_iter, notif, last_returned_ts_ns, + *ts_ns); + } + bt_put(cc_prio_map); bt_put(event); bt_put(clock_class); @@ -715,6 +911,9 @@ muxer_notif_iter_youngest_upstream_notif_iter( if (!cur_muxer_upstream_notif_iter->notif_iter) { /* This upstream notification iterator is ended */ + BT_LOGV("Skipping ended upstream notification iterator: " + "muxer-upstream-notif-iter-wrap-addr=%p", + cur_muxer_upstream_notif_iter); continue; } @@ -726,6 +925,7 @@ muxer_notif_iter_youngest_upstream_notif_iter( muxer_notif_iter->last_returned_ts_ns, ¬if_ts_ns); bt_put(notif); if (ret) { + /* get_notif_ts_ns() logs errors */ *muxer_upstream_notif_iter = NULL; status = BT_NOTIFICATION_ITERATOR_STATUS_ERROR; goto end; @@ -755,11 +955,16 @@ enum bt_notification_iterator_status validate_muxer_upstream_notif_iter( enum bt_notification_iterator_status status = BT_NOTIFICATION_ITERATOR_STATUS_OK; + BT_LOGV("Validating muxer's upstream notification iterator wrapper: " + "muxer-upstream-notif-iter-wrap-addr=%p", + muxer_upstream_notif_iter); + if (muxer_upstream_notif_iter->is_valid || !muxer_upstream_notif_iter->notif_iter) { goto end; } + /* muxer_upstream_notif_iter_next() logs details/errors */ status = muxer_upstream_notif_iter_next(muxer_upstream_notif_iter); end: @@ -774,6 +979,9 @@ enum bt_notification_iterator_status validate_muxer_upstream_notif_iters( BT_NOTIFICATION_ITERATOR_STATUS_OK; size_t i; + BT_LOGV("Validating muxer's upstream notification iterator wrappers: " + "muxer-notif-iter-addr=%p", muxer_notif_iter); + for (i = 0; i < muxer_notif_iter->muxer_upstream_notif_iters->len; i++) { struct muxer_upstream_notif_iter *muxer_upstream_notif_iter = g_ptr_array_index( @@ -783,6 +991,20 @@ enum bt_notification_iterator_status validate_muxer_upstream_notif_iters( status = validate_muxer_upstream_notif_iter( muxer_upstream_notif_iter); if (status != BT_NOTIFICATION_ITERATOR_STATUS_OK) { + if (status < 0) { + BT_LOGE("Cannot validate muxer's upstream notification iterator wrapper: " + "muxer-notif-iter-addr=%p, " + "muxer-upstream-notif-iter-wrap-addr=%p", + muxer_notif_iter, + muxer_upstream_notif_iter); + } else { + BT_LOGV("Cannot validate muxer's upstream notification iterator wrapper: " + "muxer-notif-iter-addr=%p, " + "muxer-upstream-notif-iter-wrap-addr=%p", + muxer_notif_iter, + muxer_upstream_notif_iter); + } + goto end; } @@ -795,6 +1017,10 @@ enum bt_notification_iterator_status validate_muxer_upstream_notif_iters( * Use g_ptr_array_remove_fast() because the * order of those elements is not important. */ + BT_LOGV("Removing muxer's upstream notification iterator wrapper: ended or canceled: " + "muxer-notif-iter-addr=%p, " + "muxer-upstream-notif-iter-wrap-addr=%p", + muxer_notif_iter, muxer_upstream_notif_iter); g_ptr_array_remove_index_fast( muxer_notif_iter->muxer_upstream_notif_iters, i); @@ -823,6 +1049,10 @@ struct bt_notification_iterator_next_return muxer_notif_iter_do_next( muxer_notif_iter); if (ret) { + BT_LOGE("Cannot handle newly connected input ports for muxer's notification iterator: " + "muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "ret=%d", + muxer_comp, muxer_notif_iter, ret); next_return.status = BT_NOTIFICATION_ITERATOR_STATUS_ERROR; goto end; @@ -831,6 +1061,11 @@ struct bt_notification_iterator_next_return muxer_notif_iter_do_next( next_return.status = validate_muxer_upstream_notif_iters(muxer_notif_iter); if (next_return.status != BT_NOTIFICATION_ITERATOR_STATUS_OK) { + BT_LOGE("Cannot validate upstream notification iterator wrappers for muxer's notification iterator: " + "muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "status=%s", + muxer_comp, muxer_notif_iter, + bt_notification_iterator_status_string(next_return.status)); goto end; } @@ -843,6 +1078,8 @@ struct bt_notification_iterator_next_return muxer_notif_iter_do_next( * during this operation, exit the loop. */ if (!muxer_notif_iter->newly_connected_priv_ports) { + BT_LOGV("Not breaking this loop: muxer's notification iterator still has newly connected input ports to handle: " + "muxer-comp-addr=%p", muxer_comp); break; } } @@ -862,14 +1099,34 @@ struct bt_notification_iterator_next_return muxer_notif_iter_do_next( if (next_return.status < 0 || next_return.status == BT_NOTIFICATION_ITERATOR_STATUS_END || next_return.status == BT_NOTIFICATION_ITERATOR_STATUS_CANCELED) { + if (next_return.status < 0) { + BT_LOGE("Cannot find the youngest upstream notification iterator wrapper: " + "status=%s", + bt_notification_iterator_status_string(next_return.status)); + } else { + BT_LOGV("Cannot find the youngest upstream notification iterator wrapper: " + "status=%s", + bt_notification_iterator_status_string(next_return.status)); + } + goto end; } if (next_return_ts < muxer_notif_iter->last_returned_ts_ns) { + BT_LOGE("Youngest upstream notification iterator wrapper's timestamp is less than muxer's notification iterator's last returned timestamp: " + "muxer-notif-iter-addr=%p, ts=%" PRId64 ", " + "last-returned-ts=%" PRId64, + muxer_notif_iter, next_return_ts, + muxer_notif_iter->last_returned_ts_ns); next_return.status = BT_NOTIFICATION_ITERATOR_STATUS_ERROR; goto end; } + BT_LOGV("Found youngest upstream notification iterator wrapper: " + "muxer-notif-iter-addr=%p, " + "muxer-upstream-notif-iter-wrap-addr=%p, " + "ts=%" PRId64, + muxer_notif_iter, muxer_upstream_notif_iter, next_return_ts); assert(next_return.status == BT_NOTIFICATION_ITERATOR_STATUS_OK); assert(muxer_upstream_notif_iter); next_return.notification = bt_notification_iterator_get_notification( @@ -895,7 +1152,11 @@ void destroy_muxer_notif_iter(struct muxer_notif_iter *muxer_notif_iter) return; } + BT_LOGD("Destroying muxer component's notification iterator: " + "muxer-notif-iter-addr=%p", muxer_notif_iter); + if (muxer_notif_iter->muxer_upstream_notif_iters) { + BT_LOGD_STR("Destroying muxer's upstream notification iterator wrappers."); g_ptr_array_free( muxer_notif_iter->muxer_upstream_notif_iters, TRUE); } @@ -922,6 +1183,9 @@ int muxer_notif_iter_init_newly_connected_ports(struct muxer_comp *muxer_comp, assert(comp); count = bt_component_filter_get_input_port_count(comp); if (count < 0) { + BT_LOGD("No input port to initialize for muxer component's notification iterator: " + "muxer-comp-addr=%p, muxer-notif-iter-addr=%p", + muxer_comp, muxer_notif_iter); goto end; } @@ -936,6 +1200,9 @@ int muxer_notif_iter_init_newly_connected_ports(struct muxer_comp *muxer_comp, assert(port); if (!bt_port_is_connected(port)) { + BT_LOGD("Skipping input port: not connected: " + "muxer-comp-addr=%p, port-addr=%p, port-name\"%s\"", + muxer_comp, port, bt_port_get_name(port)); bt_put(priv_port); bt_put(port); continue; @@ -948,9 +1215,18 @@ int muxer_notif_iter_init_newly_connected_ports(struct muxer_comp *muxer_comp, muxer_notif_iter->newly_connected_priv_ports, priv_port); if (!muxer_notif_iter->newly_connected_priv_ports) { + BT_LOGE("Cannot append port to muxer's notification iterator list of newly connected input ports: " + "port-addr=%p, port-name=\"%s\", " + "muxer-notif-iter-addr=%p", port, + bt_port_get_name(port), muxer_notif_iter); ret = -1; goto end; } + + BT_LOGD("Appended port to muxer's notification iterator list of newly connected input ports: " + "port-addr=%p, port-name=\"%s\", " + "muxer-notif-iter-addr=%p", port, + bt_port_get_name(port), muxer_notif_iter); } end: @@ -975,6 +1251,9 @@ enum bt_notification_iterator_status muxer_notif_iter_init( assert(priv_comp); muxer_comp = bt_private_component_get_user_data(priv_comp); assert(muxer_comp); + BT_LOGD("Initializing muxer component's notification iterator: " + "comp-addr=%p, muxer-comp-addr=%p, notif-iter-addr=%p", + priv_comp, muxer_comp, priv_notif_iter); if (muxer_comp->initializing_muxer_notif_iter) { /* @@ -982,12 +1261,16 @@ enum bt_notification_iterator_status muxer_notif_iter_init( * creates a muxer notification iterator while creating * another muxer notification iterator (same component). */ + BT_LOGE("Recursive initialization of muxer component's notification iterator: " + "comp-addr=%p, muxer-comp-addr=%p, notif-iter-addr=%p", + priv_comp, muxer_comp, priv_notif_iter); goto error; } muxer_comp->initializing_muxer_notif_iter = true; muxer_notif_iter = g_new0(struct muxer_notif_iter, 1); if (!muxer_notif_iter) { + BT_LOGE_STR("Failed to allocate one muxer component's notification iterator."); goto error; } @@ -996,6 +1279,7 @@ enum bt_notification_iterator_status muxer_notif_iter_init( g_ptr_array_new_with_free_func( (GDestroyNotify) destroy_muxer_upstream_notif_iter); if (!muxer_notif_iter->muxer_upstream_notif_iters) { + BT_LOGE_STR("Failed to allocate a GPtrArray."); goto error; } @@ -1011,12 +1295,21 @@ enum bt_notification_iterator_status muxer_notif_iter_init( ret = muxer_notif_iter_init_newly_connected_ports(muxer_comp, muxer_notif_iter); if (ret) { + BT_LOGE("Cannot initialize newly connected input ports for muxer component's notification iterator: " + "comp-addr=%p, muxer-comp-addr=%p, " + "muxer-notif-iter-addr=%p, notif-iter-addr=%p, ret=%d", + priv_comp, muxer_comp, muxer_notif_iter, + priv_notif_iter, ret); goto error; } ret = bt_private_notification_iterator_set_user_data(priv_notif_iter, muxer_notif_iter); assert(ret == 0); + BT_LOGD("Initialized muxer component's notification iterator: " + "comp-addr=%p, muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "notif-iter-addr=%p", + priv_comp, muxer_comp, muxer_notif_iter, priv_notif_iter); goto end; error: @@ -1051,6 +1344,10 @@ void muxer_notif_iter_finalize( priv_notif_iter); assert(priv_comp); muxer_comp = bt_private_component_get_user_data(priv_comp); + BT_LOGD("Finalizing muxer component's notification iterator: " + "comp-addr=%p, muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "notif-iter-addr=%p", + priv_comp, muxer_comp, muxer_notif_iter, priv_notif_iter); if (muxer_comp) { (void) g_ptr_array_remove_fast(muxer_comp->muxer_notif_iters, @@ -1078,14 +1375,35 @@ struct bt_notification_iterator_next_return muxer_notif_iter_next( muxer_comp = bt_private_component_get_user_data(priv_comp); assert(muxer_comp); + BT_LOGV("Muxer component's notification iterator's \"next\" method called: " + "comp-addr=%p, muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "notif-iter-addr=%p", + priv_comp, muxer_comp, muxer_notif_iter, priv_notif_iter); + /* Are we in an error state set elsewhere? */ if (unlikely(muxer_comp->error)) { + BT_LOGE("Muxer component is already in an error state: returning BT_NOTIFICATION_ITERATOR_STATUS_ERROR: " + "comp-addr=%p, muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "notif-iter-addr=%p", + priv_comp, muxer_comp, muxer_notif_iter, priv_notif_iter); next_ret.notification = NULL; next_ret.status = BT_NOTIFICATION_ITERATOR_STATUS_ERROR; goto end; } next_ret = muxer_notif_iter_do_next(muxer_comp, muxer_notif_iter); + if (next_ret.status < 0) { + BT_LOGE("Cannot get next notification: " + "comp-addr=%p, muxer-comp-addr=%p, muxer-notif-iter-addr=%p, " + "notif-iter-addr=%p, status=%s", + priv_comp, muxer_comp, muxer_notif_iter, priv_notif_iter, + bt_notification_iterator_status_string(next_ret.status)); + } else { + BT_LOGV("Returning from muxer component's notification iterator's \"next\" method: " + "status=%s, notif-addr=%p", + bt_notification_iterator_status_string(next_ret.status), + next_ret.notification); + } end: bt_put(priv_comp); @@ -1107,6 +1425,12 @@ void muxer_port_connected( assert(self_port); assert(muxer_comp); + BT_LOGD("Port connected: " + "comp-addr=%p, muxer-comp-addr=%p, " + "port-addr=%p, port-name=\"%s\", " + "other-port-addr=%p, other-port-name=\"%s\"", + priv_comp, muxer_comp, self_port, bt_port_get_name(self_port), + other_port, bt_port_get_name(other_port)); if (bt_port_get_type(self_port) == BT_PORT_TYPE_OUTPUT) { goto end; @@ -1122,18 +1446,24 @@ void muxer_port_connected( * the end of this list while * muxer_notif_iter_handle_newly_connected_ports() * removes the nodes from the beginning. - * - * The list node owns the private port. */ muxer_notif_iter->newly_connected_priv_ports = g_list_append( muxer_notif_iter->newly_connected_priv_ports, self_private_port); if (!muxer_notif_iter->newly_connected_priv_ports) { - /* Put reference taken by bt_get() above */ + BT_LOGE("Cannot append port to muxer's notification iterator list of newly connected input ports: " + "port-addr=%p, port-name=\"%s\", " + "muxer-notif-iter-addr=%p", self_port, + bt_port_get_name(self_port), muxer_notif_iter); muxer_comp->error = true; goto end; } + + BT_LOGD("Appended port to muxer's notification iterator list of newly connected input ports: " + "port-addr=%p, port-name=\"%s\", " + "muxer-notif-iter-addr=%p", self_port, + bt_port_get_name(self_port), muxer_notif_iter); } /* One less available input port */ @@ -1144,6 +1474,9 @@ void muxer_port_connected( * Only way to report an error later since this * method does not return anything. */ + BT_LOGE("Cannot ensure that at least one muxer component's input port is available: " + "muxer-comp-addr=%p, status=%s", + muxer_comp, bt_component_status_string(ret)); muxer_comp->error = true; goto end; } @@ -1162,6 +1495,10 @@ void muxer_port_disconnected(struct bt_private_component *priv_comp, assert(port); assert(muxer_comp); + BT_LOGD("Port disconnected: " + "comp-addr=%p, muxer-comp-addr=%p, port-addr=%p, " + "port-name=\"%s\"", priv_comp, muxer_comp, + port, bt_port_get_name(port)); /* * There's nothing special to do when a port is disconnected @@ -1177,6 +1514,11 @@ void muxer_port_disconnected(struct bt_private_component *priv_comp, if (bt_port_get_type(port) == BT_PORT_TYPE_INPUT) { /* One more available input port */ muxer_comp->available_input_ports++; + BT_LOGD("Leaving disconnected input port available for future connections: " + "comp-addr=%p, muxer-comp-addr=%p, port-addr=%p, " + "port-name=\"%s\", avail-input-port-count=%zu", + priv_comp, muxer_comp, port, bt_port_get_name(port), + muxer_comp->available_input_ports); } bt_put(port); diff --git a/plugins/utils/trimmer/Makefile.am b/plugins/utils/trimmer/Makefile.am index db1ca0f9..5e40a9a1 100644 --- a/plugins/utils/trimmer/Makefile.am +++ b/plugins/utils/trimmer/Makefile.am @@ -11,12 +11,3 @@ libbabeltrace_plugin_trimmer_la_SOURCES = \ copy.h \ logging.c \ logging.h - -libbabeltrace_plugin_trimmer_la_LIBADD = - -if !BUILT_IN_PLUGINS -libbabeltrace_plugin_trimmer_la_LIBADD += \ - $(top_builddir)/plugins/libctfcopytrace/libctfcopytrace.la \ - $(top_builddir)/common/libbabeltrace-common.la \ - $(top_builddir)/logging/libbabeltrace-logging.la -endif -- 2.34.1