From: Philippe Proulx Date: Tue, 6 Jun 2017 18:58:36 +0000 (-0400) Subject: plugins/ctf/common/notif-iter/notif-iter.c: add logging X-Git-Tag: v2.0.0-pre1~49 X-Git-Url: http://git.efficios.com/?p=babeltrace.git;a=commitdiff_plain;h=fdf0e7a0859aac0e7a540ded801921bdb14cb450 plugins/ctf/common/notif-iter/notif-iter.c: add logging Remove the logging of the payload returned by the request_bytes() medium operation of the ctf.lttng.live CC because it is now logged after calling this user function in the common notif-iter.c. Make bt_ctf_field_path_string() static in its internal header instead of BT_HIDDEN because otherwise the plugin cannot access it. Signed-off-by: Philippe Proulx Signed-off-by: Jérémie Galarneau --- diff --git a/include/babeltrace/ctf-ir/field-path-internal.h b/include/babeltrace/ctf-ir/field-path-internal.h index b270094b..66f44cfa 100644 --- a/include/babeltrace/ctf-ir/field-path-internal.h +++ b/include/babeltrace/ctf-ir/field-path-internal.h @@ -29,6 +29,7 @@ */ #include +#include #include struct bt_ctf_field_path { @@ -54,7 +55,30 @@ BT_HIDDEN struct bt_ctf_field_path *bt_ctf_field_path_copy( struct bt_ctf_field_path *path); -BT_HIDDEN -GString *bt_ctf_field_path_string(struct bt_ctf_field_path *path); +static inline +GString *bt_ctf_field_path_string(struct bt_ctf_field_path *path) +{ + GString *str = g_string_new(NULL); + size_t i; + + assert(path); + + if (!str) { + goto end; + } + + g_string_append_printf(str, "[%s", bt_ctf_scope_string(path->root)); + + for (i = 0; i < path->indexes->len; i++) { + int index = g_array_index(path->indexes, int, i); + + g_string_append_printf(str, ", %d", index); + } + + g_string_append(str, "]"); + +end: + return str; +} #endif /* BABELTRACE_CTF_IR_FIELD_PATH_INTERNAL */ diff --git a/lib/ctf-ir/field-path.c b/lib/ctf-ir/field-path.c index ac42ef5c..97ce554e 100644 --- a/lib/ctf-ir/field-path.c +++ b/lib/ctf-ir/field-path.c @@ -170,29 +170,3 @@ int bt_ctf_field_path_get_index(const struct bt_ctf_field_path *field_path, end: return ret; } - -BT_HIDDEN -GString *bt_ctf_field_path_string(struct bt_ctf_field_path *path) -{ - GString *str = g_string_new(NULL); - size_t i; - - assert(path); - - if (!str) { - goto end; - } - - g_string_append_printf(str, "[%s", bt_ctf_scope_string(path->root)); - - for (i = 0; i < path->indexes->len; i++) { - int index = g_array_index(path->indexes, int, i); - - g_string_append_printf(str, ", %d", index); - } - - g_string_append(str, "]"); - -end: - return str; -} diff --git a/plugins/ctf/common/btr/btr.c b/plugins/ctf/common/btr/btr.c index 58c3a286..ecceb5b1 100644 --- a/plugins/ctf/common/btr/btr.c +++ b/plugins/ctf/common/btr/btr.c @@ -602,7 +602,7 @@ enum bt_ctf_btr_status validate_contiguous_bo(struct bt_ctf_btr *btr, } end: - if (status) { + if (status < 0) { BT_LOGW("Cannot read bit array: two different byte orders not at a byte boundary: " "btr-addr=%p, last-bo=%s, next-bo=%s", btr, bt_ctf_byte_order_string(btr->last_bo), @@ -1527,9 +1527,8 @@ size_t bt_ctf_btr_start(struct bt_ctf_btr *btr, while (true) { *status = handle_state(btr); - if (*status != BT_CTF_BTR_STATUS_OK) { - break; - } else if (btr->state == BTR_STATE_DONE) { + if (*status != BT_CTF_BTR_STATUS_OK || + btr->state == BTR_STATE_DONE) { break; } } @@ -1563,9 +1562,8 @@ size_t bt_ctf_btr_continue(struct bt_ctf_btr *btr, while (true) { *status = handle_state(btr); - if (*status != BT_CTF_BTR_STATUS_OK) { - break; - } else if (btr->state == BTR_STATE_DONE) { + if (*status != BT_CTF_BTR_STATUS_OK || + btr->state == BTR_STATE_DONE) { break; } } diff --git a/plugins/ctf/common/btr/btr.h b/plugins/ctf/common/btr/btr.h index fb7d850a..29020ca2 100644 --- a/plugins/ctf/common/btr/btr.h +++ b/plugins/ctf/common/btr/btr.h @@ -63,7 +63,7 @@ enum bt_ctf_btr_status { * #BT_CTF_BTR_STATUS_EOF is returned to complete the decoding * process of a given type. */ - BT_CTF_BTR_STATUS_EOF = -4, + BT_CTF_BTR_STATUS_EOF = 1, /** Invalid argument. */ BT_CTF_BTR_STATUS_INVAL = -3, diff --git a/plugins/ctf/common/notif-iter/Makefile.am b/plugins/ctf/common/notif-iter/Makefile.am index b19d5635..e94454de 100644 --- a/plugins/ctf/common/notif-iter/Makefile.am +++ b/plugins/ctf/common/notif-iter/Makefile.am @@ -5,4 +5,6 @@ noinst_LTLIBRARIES = libctf-notif-iter.la libctf_notif_iter_la_SOURCES = \ notif-iter.c \ - notif-iter.h + notif-iter.h \ + logging.c \ + logging.h diff --git a/plugins/ctf/common/notif-iter/logging.c b/plugins/ctf/common/notif-iter/logging.c new file mode 100644 index 00000000..082d4446 --- /dev/null +++ b/plugins/ctf/common/notif-iter/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 ctf_notif_iter_log_level +#include + +BT_LOG_INIT_LOG_LEVEL(ctf_notif_iter_log_level, + "BABELTRACE_PLUGIN_CTF_NOTIF_ITER_LOG_LEVEL"); diff --git a/plugins/ctf/common/notif-iter/logging.h b/plugins/ctf/common/notif-iter/logging.h new file mode 100644 index 00000000..74f3c8f8 --- /dev/null +++ b/plugins/ctf/common/notif-iter/logging.h @@ -0,0 +1,31 @@ +#ifndef CTF_NOTIF_ITER_LOGGING_H +#define CTF_NOTIF_ITER_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 ctf_notif_iter_log_level +#include + +BT_LOG_LEVEL_EXTERN_SYMBOL(ctf_notif_iter_log_level); + +#endif /* CTF_NOTIF_ITER_LOGGING_H */ diff --git a/plugins/ctf/common/notif-iter/notif-iter.c b/plugins/ctf/common/notif-iter/notif-iter.c index 9a7fcb2f..5a7b3255 100644 --- a/plugins/ctf/common/notif-iter/notif-iter.c +++ b/plugins/ctf/common/notif-iter/notif-iter.c @@ -23,6 +23,9 @@ * SOFTWARE. */ +#define BT_LOG_TAG "PLUGIN-CTF-NOTIF-ITER" +#include "logging.h" + #include #include #include @@ -31,7 +34,9 @@ #include #include #include +#include #include +#include #include #include #include @@ -46,15 +51,9 @@ #include #include -#define PRINT_ERR_STREAM (notit ? notit->err_stream : stderr) -#define PRINT_PREFIX "ctf-notif-iter" -#include "../print.h" - #include "notif-iter.h" #include "../btr/btr.h" -#define BYTES_TO_BITS(x) ((x) * 8) - struct bt_ctf_notif_iter; /* A visit stack entry */ @@ -249,6 +248,55 @@ struct bt_ctf_notif_iter { GHashTable *sc_field_path_caches; }; +static inline +const char *state_string(enum state state) +{ + switch (state) { + case STATE_INIT: + return "STATE_INIT"; + case STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN: + return "STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN"; + case STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE: + return "STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE"; + case STATE_AFTER_TRACE_PACKET_HEADER: + return "STATE_AFTER_TRACE_PACKET_HEADER"; + case STATE_DSCOPE_STREAM_PACKET_CONTEXT_BEGIN: + return "STATE_DSCOPE_STREAM_PACKET_CONTEXT_BEGIN"; + case STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE: + return "STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE"; + case STATE_AFTER_STREAM_PACKET_CONTEXT: + return "STATE_AFTER_STREAM_PACKET_CONTEXT"; + case STATE_EMIT_NOTIF_NEW_PACKET: + return "STATE_EMIT_NOTIF_NEW_PACKET"; + case STATE_DSCOPE_STREAM_EVENT_HEADER_BEGIN: + return "STATE_DSCOPE_STREAM_EVENT_HEADER_BEGIN"; + case STATE_DSCOPE_STREAM_EVENT_HEADER_CONTINUE: + return "STATE_DSCOPE_STREAM_EVENT_HEADER_CONTINUE"; + case STATE_AFTER_STREAM_EVENT_HEADER: + return "STATE_AFTER_STREAM_EVENT_HEADER"; + case STATE_DSCOPE_STREAM_EVENT_CONTEXT_BEGIN: + return "STATE_DSCOPE_STREAM_EVENT_CONTEXT_BEGIN"; + case STATE_DSCOPE_STREAM_EVENT_CONTEXT_CONTINUE: + return "STATE_DSCOPE_STREAM_EVENT_CONTEXT_CONTINUE"; + case STATE_DSCOPE_EVENT_CONTEXT_BEGIN: + return "STATE_DSCOPE_EVENT_CONTEXT_BEGIN"; + case STATE_DSCOPE_EVENT_CONTEXT_CONTINUE: + return "STATE_DSCOPE_EVENT_CONTEXT_CONTINUE"; + case STATE_DSCOPE_EVENT_PAYLOAD_BEGIN: + return "STATE_DSCOPE_EVENT_PAYLOAD_BEGIN"; + case STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE: + return "STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE"; + case STATE_EMIT_NOTIF_EVENT: + return "STATE_EMIT_NOTIF_EVENT"; + case STATE_EMIT_NOTIF_END_OF_PACKET: + return "STATE_EMIT_NOTIF_END_OF_PACKET"; + case STATE_SKIP_PACKET_PADDING: + return "STATE_SKIP_PACKET_PADDING"; + default: + return "(unknown)"; + } +} + static int bt_ctf_notif_iter_switch_packet(struct bt_ctf_notif_iter *notit); @@ -272,15 +320,19 @@ struct stack *stack_new(struct bt_ctf_notif_iter *notit) stack = g_new0(struct stack, 1); if (!stack) { + BT_LOGE_STR("Failed to allocate one stack."); goto error; } stack->entries = g_ptr_array_new_with_free_func(stack_entry_free_func); if (!stack->entries) { + BT_LOGE_STR("Failed to allocate a GPtrArray."); goto error; } + BT_LOGD("Created stack: notit-addr=%p, stack-addr=%p", notit, stack); return stack; + error: g_free(stack); return NULL; @@ -290,6 +342,7 @@ static void stack_destroy(struct stack *stack) { assert(stack); + BT_LOGD("Destroying stack: addr=%p", stack); g_ptr_array_free(stack->entries, TRUE); g_free(stack); } @@ -302,8 +355,12 @@ int stack_push(struct stack *stack, struct bt_ctf_field *base) assert(stack); assert(base); + BT_LOGV("Pushing base field on stack: stack-addr=%p, " + "stack-size-before=%u, stack-size-after=%u", + stack, stack->entries->len, stack->entries->len + 1); entry = g_new0(struct stack_entry, 1); if (!entry) { + BT_LOGE_STR("Failed to allocate one stack entry."); ret = -1; goto end; } @@ -328,6 +385,9 @@ void stack_pop(struct stack *stack) { assert(stack); assert(stack_size(stack)); + BT_LOGV("Popping from stack: " + "stack-addr=%p, stack-size-before=%u, stack-size-after=%u", + stack, stack->entries->len, stack->entries->len - 1); g_ptr_array_remove_index(stack->entries, stack->entries->len - 1); } @@ -352,6 +412,8 @@ void stack_clear(struct stack *stack) assert(stack); if (!stack_empty(stack)) { + BT_LOGV("Clearing stack: stack-addr=%p, stack-size=%u", + stack, stack->entries->len); g_ptr_array_remove_range(stack->entries, 0, stack_size(stack)); } @@ -368,7 +430,7 @@ enum bt_ctf_notif_iter_status notif_iter_status_from_m_status( static inline size_t buf_size_bits(struct bt_ctf_notif_iter *notit) { - return BYTES_TO_BITS(notit->buf.sz); + return notit->buf.sz * 8; } static inline @@ -386,6 +448,8 @@ size_t packet_at(struct bt_ctf_notif_iter *notit) static inline void buf_consume_bits(struct bt_ctf_notif_iter *notit, size_t incr) { + BT_LOGV("Advancing cursor: notit-addr=%p, cur-before=%zu, cur-after=%zu", + notit, notit->buf.at, notit->buf.at + incr); notit->buf.at += incr; } @@ -393,13 +457,18 @@ static enum bt_ctf_notif_iter_status request_medium_bytes( struct bt_ctf_notif_iter *notit) { - uint8_t *buffer_addr; - size_t buffer_sz; + uint8_t *buffer_addr = NULL; + size_t buffer_sz = 0; enum bt_ctf_notif_iter_medium_status m_status; + BT_LOGV("Calling user function (request bytes): notit-addr=%p, " + "request-size=%zu", notit, notit->medium.max_request_sz); m_status = notit->medium.medops.request_bytes( notit->medium.max_request_sz, &buffer_addr, &buffer_sz, notit->medium.data); + BT_LOGV("User function returned: status=%s, buf-addr=%p, buf-size=%zu", + bt_ctf_notif_iter_medium_status_string(m_status), + buffer_addr, buffer_sz); if (m_status == BT_CTF_NOTIF_ITER_MEDIUM_STATUS_OK) { assert(buffer_sz != 0); @@ -414,6 +483,16 @@ enum bt_ctf_notif_iter_status request_medium_bytes( /* New medium buffer address */ notit->buf.addr = buffer_addr; + + BT_LOGV("User function returned new bytes: " + "packet-offset=%zu, cur=%zu, size=%zu, addr=%p", + notit->buf.packet_offset, notit->buf.at, + notit->buf.sz, notit->buf.addr); + BT_LOGV_MEM(buffer_addr, buffer_sz, "Returned bytes at %p:", + buffer_addr); + } else if (m_status < 0) { + BT_LOGW("User function failed: status=%s", + bt_ctf_notif_iter_medium_status_string(m_status)); } return notif_iter_status_from_m_status(m_status); @@ -449,25 +528,42 @@ enum bt_ctf_notif_iter_status read_dscope_begin_state( status = buf_ensure_available_bits(notit); if (status != BT_CTF_NOTIF_ITER_STATUS_OK) { + if (status < 0) { + BT_LOGW("Cannot ensure that buffer has at least one byte: " + "notif-addr=%p, status=%s", + notit, bt_ctf_notif_iter_status_string(status)); + } else { + BT_LOGV("Cannot ensure that buffer has at least one byte: " + "notif-addr=%p, status=%s", + notit, bt_ctf_notif_iter_status_string(status)); + } + goto end; } bt_put(*dscope_field); notit->cur_dscope_field = dscope_field; + BT_LOGV("Starting BTR: notit-addr=%p, btr-addr=%p, ft-addr=%p", + notit, notit->btr, dscope_field_type); consumed_bits = bt_ctf_btr_start(notit->btr, dscope_field_type, notit->buf.addr, notit->buf.at, packet_at(notit), notit->buf.sz, &btr_status); + BT_LOGV("BTR consumed bits: size=%zu", consumed_bits); switch (btr_status) { case BT_CTF_BTR_STATUS_OK: /* type was read completely */ + BT_LOGV_STR("Field was completely decoded."); notit->state = done_state; break; case BT_CTF_BTR_STATUS_EOF: + BT_LOGV_STR("BTR needs more data to decode field completely."); notit->state = continue_state; break; default: - PERR("Binary type reader failed to start\n"); + BT_LOGW("BTR failed to start: notit-addr=%p, btr-addr=%p, " + "status=%s", notit, notit->btr, + bt_ctf_btr_status_string(btr_status)); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } @@ -489,22 +585,39 @@ enum bt_ctf_notif_iter_status read_dscope_continue_state( status = buf_ensure_available_bits(notit); if (status != BT_CTF_NOTIF_ITER_STATUS_OK) { + if (status < 0) { + BT_LOGW("Cannot ensure that buffer has at least one byte: " + "notif-addr=%p, status=%s", + notit, bt_ctf_notif_iter_status_string(status)); + } else { + BT_LOGV("Cannot ensure that buffer has at least one byte: " + "notif-addr=%p, status=%s", + notit, bt_ctf_notif_iter_status_string(status)); + } + goto end; } + BT_LOGV("Continuing BTR: notit-addr=%p, btr-addr=%p", + notit, notit->btr); consumed_bits = bt_ctf_btr_continue(notit->btr, notit->buf.addr, - notit->buf.sz, &btr_status); + notit->buf.sz, &btr_status); + BT_LOGV("BTR consumed bits: size=%zu", consumed_bits); switch (btr_status) { case BT_CTF_BTR_STATUS_OK: /* Type was read completely. */ + BT_LOGV_STR("Field was completely decoded."); notit->state = done_state; break; case BT_CTF_BTR_STATUS_EOF: /* Stay in this continue state. */ + BT_LOGV_STR("BTR needs more data to decode field completely."); break; default: - PERR("Binary type reader failed to continue\n"); + BT_LOGW("BTR failed to continue: notit-addr=%p, btr-addr=%p, " + "status=%s", notit, notit->btr, + bt_ctf_btr_status_string(btr_status)); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } @@ -518,16 +631,22 @@ end: static void put_event_dscopes(struct bt_ctf_notif_iter *notit) { + BT_LOGV_STR("Putting event header field."); BT_PUT(notit->dscopes.stream_event_header); + BT_LOGV_STR("Putting stream event context field."); BT_PUT(notit->dscopes.stream_event_context); + BT_LOGV_STR("Putting event context field."); BT_PUT(notit->dscopes.event_context); + BT_LOGV_STR("Putting event payload field."); BT_PUT(notit->dscopes.event_payload); } static void put_all_dscopes(struct bt_ctf_notif_iter *notit) { + BT_LOGV_STR("Putting packet header field."); BT_PUT(notit->dscopes.trace_packet_header); + BT_LOGV_STR("Putting packet context field."); BT_PUT(notit->dscopes.stream_packet_context); put_event_dscopes(notit); } @@ -540,6 +659,7 @@ enum bt_ctf_notif_iter_status read_packet_header_begin_state( enum bt_ctf_notif_iter_status ret = BT_CTF_NOTIF_ITER_STATUS_OK; if (bt_ctf_notif_iter_switch_packet(notit)) { + BT_LOGW("Cannot switch packet: notit-addr=%p", notit); ret = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } @@ -552,10 +672,22 @@ enum bt_ctf_notif_iter_status read_packet_header_begin_state( goto end; } + BT_LOGV("Decoding packet header field:" + "notit-addr=%p, trace-addr=%p, trace-name=\"%s\", ft-addr=%p", + notit, notit->meta.trace, + bt_ctf_trace_get_name(notit->meta.trace), packet_header_type); ret = read_dscope_begin_state(notit, packet_header_type, - STATE_AFTER_TRACE_PACKET_HEADER, - STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE, - ¬it->dscopes.trace_packet_header); + STATE_AFTER_TRACE_PACKET_HEADER, + STATE_DSCOPE_TRACE_PACKET_HEADER_CONTINUE, + ¬it->dscopes.trace_packet_header); + if (ret < 0) { + BT_LOGW("Cannot decode packet header field: " + "notit-addr=%p, trace-addr=%p, " + "trace-name=\"%s\", ft-addr=%p", + notit, notit->meta.trace, + bt_ctf_trace_get_name(notit->meta.trace), + packet_header_type); + } end: BT_PUT(packet_header_type); return ret; @@ -599,6 +731,7 @@ create_stream_class_field_path_cache_entry( struct bt_ctf_field_type *event_header = NULL, *packet_context = NULL; if (!cache_entry) { + BT_LOGE_STR("Failed to allocate one stream class field path cache."); goto end; } @@ -607,10 +740,9 @@ create_stream_class_field_path_cache_entry( int i, count; count = bt_ctf_field_type_structure_get_field_count( - event_header); - if (count < 0) { - goto error; - } + event_header); + assert(count >= 0); + for (i = 0; i < count; i++) { int ret; const char *name; @@ -618,13 +750,23 @@ create_stream_class_field_path_cache_entry( ret = bt_ctf_field_type_structure_get_field( event_header, &name, NULL, i); if (ret) { + BT_LOGE("Cannot get event header structure field type's field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", " + "ft-addr=%p, index=%d", + notit, stream_class, + bt_ctf_stream_class_get_name(stream_class), + bt_ctf_stream_class_get_id(stream_class), + event_header, i); goto error; } if (v != -1 && id != -1) { break; } - if (v == -1 && !strcmp(name, "v")) { + + if (v == -1 && strcmp(name, "v") == 0) { v = i; } else if (id == -1 && !strcmp(name, "id")) { id = i; @@ -638,10 +780,9 @@ create_stream_class_field_path_cache_entry( int i, count; count = bt_ctf_field_type_structure_get_field_count( - packet_context); - if (count < 0) { - goto error; - } + packet_context); + assert(count >= 0); + for (i = 0; i < count; i++) { int ret; const char *name; @@ -655,11 +796,20 @@ create_stream_class_field_path_cache_entry( ret = bt_ctf_field_type_structure_get_field( packet_context, &name, &field_type, i); if (ret) { + BT_LOGE("Cannot get packet context structure field type's field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", " + "ft-addr=%p, index=%d", + notit, stream_class, + bt_ctf_stream_class_get_name(stream_class), + bt_ctf_stream_class_get_id(stream_class), + event_header, i); goto error; } if (timestamp_end == -1 && - !strcmp(name, "timestamp_end")) { + strcmp(name, "timestamp_end") == 0) { struct field_cb_override *override = g_new0( struct field_cb_override, 1); @@ -670,10 +820,8 @@ create_stream_class_field_path_cache_entry( override->func = btr_timestamp_end_cb; override->data = notit; - g_hash_table_insert(notit->field_overrides, - bt_get(field_type), override); - + bt_get(field_type), override); timestamp_end = i; } else if (packet_size == -1 && !strcmp(name, "packet_size")) { @@ -714,9 +862,9 @@ struct stream_class_field_path_cache *get_stream_class_field_path_cache( stream_class, NULL, (gpointer) &cache_entry); if (unlikely(!cache_entry_found)) { cache_entry = create_stream_class_field_path_cache_entry(notit, - stream_class); + stream_class); g_hash_table_insert(notit->sc_field_path_caches, - bt_get(stream_class), (gpointer) cache_entry); + bt_get(stream_class), (gpointer) cache_entry); } return cache_entry; @@ -736,19 +884,21 @@ enum bt_ctf_notif_iter_status set_current_stream_class( /* Is there any "stream_id" field in the packet header? */ packet_header_type = bt_ctf_trace_get_packet_header_type( - notit->meta.trace); + notit->meta.trace); if (!packet_header_type) { - PERR("Failed to retrieve trace's packet header type\n"); - status = BT_CTF_NOTIF_ITER_STATUS_ERROR; - goto end; + /* + * No packet header, therefore no `stream_id` field, + * therefore only one stream class. + */ + goto single_stream_class; } assert(is_struct_type(packet_header_type)); // TODO: optimalize! stream_id_field_type = - bt_ctf_field_type_structure_get_field_type_by_name( - packet_header_type, "stream_id"); + bt_ctf_field_type_structure_get_field_type_by_name( + packet_header_type, "stream_id"); if (stream_id_field_type) { /* Find appropriate stream class using current stream ID */ int ret; @@ -765,30 +915,52 @@ enum bt_ctf_notif_iter_status set_current_stream_class( assert(!ret); BT_PUT(stream_id_field); } else { +single_stream_class: /* Only one stream: pick the first stream class */ assert(bt_ctf_trace_get_stream_class_count( notit->meta.trace) == 1); stream_id = 0; } + BT_LOGV("Found stream class ID to use: notit-addr=%p, " + "stream-class-id=%" PRIu64 ", " + "trace-addr=%p, trace-name=\"%s\"", + notit, stream_id, notit->meta.trace, + bt_ctf_trace_get_name(notit->meta.trace)); + BT_PUT(notit->meta.stream_class); notit->meta.stream_class = bt_ctf_trace_get_stream_class_by_id( - notit->meta.trace, stream_id); + notit->meta.trace, stream_id); if (!notit->meta.stream_class) { - PERR("Cannot find stream class with ID %" PRIu64 "\n", - stream_id); + BT_LOGW("No stream class with ID of stream class ID to use in trace: " + "notit-addr=%p, stream-class-id=%" PRIu64 ", " + "trace-addr=%p, trace-name=\"%s\"", + notit, stream_id, notit->meta.trace, + bt_ctf_trace_get_name(notit->meta.trace)); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } + BT_LOGV("Set current stream class: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", stream-class-id=%" PRId64, + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class)); + /* * Retrieve (or lazily create) the current stream class field path * cache. */ notit->cur_sc_field_path_cache = get_stream_class_field_path_cache( - notit, notit->meta.stream_class); + notit, notit->meta.stream_class); if (!notit->cur_sc_field_path_cache) { - PERR("Failed to retrieve stream class field path cache\n"); + BT_LOGW("Cannot retrieve stream class field path from cache: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", stream-class-id=%" PRId64, + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class)); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } @@ -822,16 +994,40 @@ enum bt_ctf_notif_iter_status read_packet_context_begin_state( assert(notit->meta.stream_class); packet_context_type = bt_ctf_stream_class_get_packet_context_type( - notit->meta.stream_class); + notit->meta.stream_class); if (!packet_context_type) { + BT_LOGV("No packet packet context field type in stream class: continuing: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", stream-class-id=%" PRId64, + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class)); notit->state = STATE_AFTER_STREAM_PACKET_CONTEXT; goto end; } + BT_LOGV("Decoding packet context field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " + "ft-addr=%p", + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + packet_context_type); status = read_dscope_begin_state(notit, packet_context_type, - STATE_AFTER_STREAM_PACKET_CONTEXT, - STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE, - ¬it->dscopes.stream_packet_context); + STATE_AFTER_STREAM_PACKET_CONTEXT, + STATE_DSCOPE_STREAM_PACKET_CONTEXT_CONTINUE, + ¬it->dscopes.stream_packet_context); + if (status < 0) { + BT_LOGW("Cannot decode packet context field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", ft-addr=%p", + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + packet_context_type); + } end: BT_PUT(packet_context_type); @@ -858,20 +1054,26 @@ enum bt_ctf_notif_iter_status set_current_packet_content_sizes( assert(notit->dscopes.stream_packet_context); packet_size_field = bt_ctf_field_structure_get_field( - notit->dscopes.stream_packet_context, "packet_size"); + notit->dscopes.stream_packet_context, "packet_size"); content_size_field = bt_ctf_field_structure_get_field( - notit->dscopes.stream_packet_context, "content_size"); + notit->dscopes.stream_packet_context, "content_size"); if (packet_size_field) { int ret = bt_ctf_field_unsigned_integer_get_value( - packet_size_field, &packet_size); + packet_size_field, &packet_size); - assert(!ret); + assert(ret == 0); if (packet_size == 0) { - PERR("Decoded packet size is 0\n"); + BT_LOGW("Invalid packet size: packet context field indicates packet size is zero: " + "notit-addr=%p, packet-context-field-addr=%p", + notit, notit->dscopes.stream_packet_context); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } else if ((packet_size % 8) != 0) { - PERR("Decoded packet size is not a multiple of 8\n"); + BT_LOGW("Invalid packet size: packet context field indicates packet size is not a multiple of 8: " + "notit-addr=%p, packet-context-field-addr=%p, " + "packet-size=%" PRIu64, + notit, notit->dscopes.stream_packet_context, + packet_size); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } @@ -881,13 +1083,26 @@ enum bt_ctf_notif_iter_status set_current_packet_content_sizes( int ret = bt_ctf_field_unsigned_integer_get_value( content_size_field, &content_size); - assert(!ret); + assert(ret == 0); } else { content_size = packet_size; } + if (content_size > packet_size) { + BT_LOGW("Invalid packet or content size: packet context field indicates content size is greater than packet size: " + "notit-addr=%p, packet-context-field-addr=%p, " + "packet-size=%" PRIu64 ", content-size=%" PRIu64, + notit, notit->dscopes.stream_packet_context, + packet_size, content_size); + status = BT_CTF_NOTIF_ITER_STATUS_ERROR; + goto end; + } + notit->cur_packet_size = packet_size; notit->cur_content_size = content_size; + BT_LOGV("Set current packet and content sizes: " + "notit-addr=%p, packet-size=%" PRIu64 ", content-size=%" PRIu64, + notit, packet_size, content_size); end: BT_PUT(packet_size_field); BT_PUT(content_size_field); @@ -919,14 +1134,16 @@ enum bt_ctf_notif_iter_status read_event_header_begin_state( if (notit->cur_content_size >= 0) { if (packet_at(notit) == notit->cur_content_size) { /* No more events! */ + BT_LOGV("Reached end of packet: notit-addr=%p, " + "cur=%zu", notit, packet_at(notit)); notit->state = STATE_EMIT_NOTIF_END_OF_PACKET; goto end; } else if (packet_at(notit) > notit->cur_content_size) { /* That's not supposed to happen */ - PERR("Cursor passed packet's content size:\n"); - PERR("\tDecoded content size: %zu\n", - notit->cur_content_size); - PERR("\tCursor position: %zu\n", packet_at(notit)); + BT_LOGV("Before decoding event header field: cursor is passed the packet's content: " + "notit-addr=%p, content-size=%zu, " + "cur=%zu", notit, notit->cur_content_size, + packet_at(notit)); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } @@ -940,10 +1157,28 @@ enum bt_ctf_notif_iter_status read_event_header_begin_state( } put_event_dscopes(notit); + BT_LOGV("Decoding event header field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " + "ft-addr=%p", + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + event_header_type); status = read_dscope_begin_state(notit, event_header_type, STATE_AFTER_STREAM_EVENT_HEADER, STATE_DSCOPE_STREAM_EVENT_HEADER_CONTINUE, ¬it->dscopes.stream_event_header); + if (status < 0) { + BT_LOGW("Cannot decode event header field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", ft-addr=%p", + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + event_header_type); + } end: BT_PUT(event_header_type); @@ -977,9 +1212,11 @@ enum bt_ctf_notif_iter_status set_current_event_class(struct bt_ctf_notif_iter * event_header_type = bt_ctf_stream_class_get_event_header_type( notit->meta.stream_class); if (!event_header_type) { - PERR("Failed to retrieve stream class's event header type\n"); - status = BT_CTF_NOTIF_ITER_STATUS_ERROR; - goto end; + /* + * No event header, therefore no event class ID field, + * therefore only one event class. + */ + goto single_event_class; } /* Is there any "id"/"v" field in the event header? */ @@ -1020,10 +1257,15 @@ enum bt_ctf_notif_iter_status set_current_event_class(struct bt_ctf_notif_iter * goto end_v_field_type; } - ret = bt_ctf_field_unsigned_integer_get_value( - v_struct_id_field, &event_id); - if (ret) { - event_id = -1ULL; + if (bt_ctf_field_is_integer(v_struct_id_field)) { + ret = bt_ctf_field_unsigned_integer_get_value( + v_struct_id_field, &event_id); + if (ret) { + BT_LOGV("Cannot get value of unsigned integer field (`id`): continuing: " + "notit=%p, field-addr=%p", + notit, v_struct_id_field); + event_id = -1ULL; + } } end_v_field_type: @@ -1035,19 +1277,19 @@ end_v_field_type: if (id_field_type && event_id == -1ULL) { /* Check "id" field */ struct bt_ctf_field *id_field = NULL; - int ret; + int ret = 0; // TODO: optimalize! id_field = bt_ctf_field_structure_get_field( notit->dscopes.stream_event_header, "id"); - assert(id_field); - assert(bt_ctf_field_is_integer(id_field) || - bt_ctf_field_is_enumeration(id_field)); + if (!id_field) { + goto check_event_id; + } if (bt_ctf_field_is_integer(id_field)) { ret = bt_ctf_field_unsigned_integer_get_value( id_field, &event_id); - } else { + } else if (bt_ctf_field_is_enumeration(id_field)) { struct bt_ctf_field *container; container = bt_ctf_field_enumeration_get_container( @@ -1057,26 +1299,52 @@ end_v_field_type: container, &event_id); BT_PUT(container); } - assert(!ret); + + assert(ret == 0); BT_PUT(id_field); } +check_event_id: if (event_id == -1ULL) { +single_event_class: /* Event ID not found: single event? */ assert(bt_ctf_stream_class_get_event_class_count( notit->meta.stream_class) == 1); event_id = 0; } + BT_LOGV("Found event class ID to use: notit-addr=%p, " + "stream-class-addr=%p, stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", " + "event-class-id=%" PRIu64, + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + event_id); BT_PUT(notit->meta.event_class); notit->meta.event_class = bt_ctf_stream_class_get_event_class_by_id( notit->meta.stream_class, event_id); if (!notit->meta.event_class) { - PERR("Cannot find event class with ID %" PRIu64 "\n", event_id); + BT_LOGW("No event class with ID of event class ID to use in stream class: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", " + "event-class-id=%" PRIu64, + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + event_id); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } + BT_LOGV("Set current event class: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", event-class-id=%" PRId64, + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class)); + end: BT_PUT(event_header_type); BT_PUT(id_field_type); @@ -1093,7 +1361,6 @@ enum bt_ctf_notif_iter_status after_event_header_state( status = set_current_event_class(notit); if (status != BT_CTF_NOTIF_ITER_STATUS_OK) { - PERR("Failed to set current event class\n"); goto end; } @@ -1117,10 +1384,28 @@ enum bt_ctf_notif_iter_status read_stream_event_context_begin_state( goto end; } + BT_LOGV("Decoding stream event context field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", stream-class-id=%" PRId64 ", " + "ft-addr=%p", + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + stream_event_context_type); status = read_dscope_begin_state(notit, stream_event_context_type, STATE_DSCOPE_EVENT_CONTEXT_BEGIN, STATE_DSCOPE_STREAM_EVENT_CONTEXT_CONTINUE, ¬it->dscopes.stream_event_context); + if (status < 0) { + BT_LOGW("Cannot decode stream event context field: " + "notit-addr=%p, stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", ft-addr=%p", + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + stream_event_context_type); + } end: BT_PUT(stream_event_context_type); @@ -1149,10 +1434,29 @@ enum bt_ctf_notif_iter_status read_event_context_begin_state( notit->state = STATE_DSCOPE_EVENT_PAYLOAD_BEGIN; goto end; } + + BT_LOGV("Decoding event context field: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", event-class-id=%" PRId64 ", " + "ft-addr=%p", + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + event_context_type); status = read_dscope_begin_state(notit, event_context_type, STATE_DSCOPE_EVENT_PAYLOAD_BEGIN, STATE_DSCOPE_EVENT_CONTEXT_CONTINUE, ¬it->dscopes.event_context); + if (status < 0) { + BT_LOGW("Cannot decode event context field: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", ft-addr=%p", + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + event_context_type); + } end: BT_PUT(event_context_type); @@ -1182,10 +1486,28 @@ enum bt_ctf_notif_iter_status read_event_payload_begin_state( goto end; } + BT_LOGV("Decoding event payload field: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", event-class-id=%" PRId64 ", " + "ft-addr=%p", + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + event_payload_type); status = read_dscope_begin_state(notit, event_payload_type, STATE_EMIT_NOTIF_EVENT, STATE_DSCOPE_EVENT_PAYLOAD_CONTINUE, ¬it->dscopes.event_payload); + if (status < 0) { + BT_LOGW("Cannot decode event payload field: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", ft-addr=%p", + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + event_payload_type); + } end: BT_PUT(event_payload_type); @@ -1214,12 +1536,17 @@ enum bt_ctf_notif_iter_status skip_packet_padding_state( goto end; } else { size_t bits_to_consume; + + BT_LOGV("Trying to skip %zu bits of padding: notit-addr=%p, size=%zu", + bits_to_skip, notit, bits_to_skip); status = buf_ensure_available_bits(notit); if (status != BT_CTF_NOTIF_ITER_STATUS_OK) { goto end; } bits_to_consume = MIN(buf_available_bits(notit), bits_to_skip); + BT_LOGV("Skipping %zu bits of padding: notit-addr=%p, size=%zu", + bits_to_consume, notit, bits_to_consume); buf_consume_bits(notit, bits_to_consume); bits_to_skip = notit->cur_packet_size - packet_at(notit); if (bits_to_skip == 0) { @@ -1236,11 +1563,13 @@ static inline enum bt_ctf_notif_iter_status handle_state(struct bt_ctf_notif_iter *notit) { enum bt_ctf_notif_iter_status status = BT_CTF_NOTIF_ITER_STATUS_OK; + const enum state state = notit->state; - PDBG("Handling state %d\n", notit->state); + BT_LOGV("Handling state: notit-addr=%p, state=%s", + notit, state_string(state)); // TODO: optimalize! - switch (notit->state) { + switch (state) { case STATE_INIT: notit->state = STATE_DSCOPE_TRACE_PACKET_HEADER_BEGIN; break; @@ -1301,8 +1630,16 @@ enum bt_ctf_notif_iter_status handle_state(struct bt_ctf_notif_iter *notit) case STATE_EMIT_NOTIF_END_OF_PACKET: notit->state = STATE_SKIP_PACKET_PADDING; break; + default: + BT_LOGD("Unknown CTF plugin notification iterator state: " + "notit-addr=%p, state=%d", notit, notit->state); + abort(); } + BT_LOGV("Handled state: notit-addr=%p, status=%s, " + "prev-state=%s, cur-state=%s", + notit, bt_ctf_notif_iter_status_string(status), + state_string(state), state_string(notit->state)); return status; } @@ -1313,6 +1650,7 @@ static void bt_ctf_notif_iter_reset(struct bt_ctf_notif_iter *notit) { assert(notit); + BT_LOGD("Resetting notification iterator: addr=%p", notit); stack_clear(notit->stack); BT_PUT(notit->meta.stream_class); BT_PUT(notit->meta.event_class); @@ -1333,6 +1671,8 @@ int bt_ctf_notif_iter_switch_packet(struct bt_ctf_notif_iter *notit) int ret = 0; assert(notit); + BT_LOGV("Switching packet: notit-addr=%p, cur=%zu", + notit, notit->buf.at); stack_clear(notit->stack); BT_PUT(notit->meta.stream_class); BT_PUT(notit->meta.event_class); @@ -1349,6 +1689,8 @@ int bt_ctf_notif_iter_switch_packet(struct bt_ctf_notif_iter *notit) /* Packets are assumed to start on a byte frontier. */ if (notit->buf.at % CHAR_BIT) { + BT_LOGW("Cannot switch packet: current position is not a multiple of 8: " + "notit-addr=%p, cur=%zu", notit, notit->buf.at); ret = -1; goto end; } @@ -1357,11 +1699,14 @@ int bt_ctf_notif_iter_switch_packet(struct bt_ctf_notif_iter *notit) notit->buf.sz -= consumed_bytes; notit->buf.at = 0; notit->buf.packet_offset = 0; + BT_LOGV("Adjusted buffer: addr=%p, size=%zu", + notit->buf.addr, notit->buf.sz); } notit->cur_content_size = -1; notit->cur_packet_size = -1; notit->cur_sc_field_path_cache = NULL; + end: return ret; } @@ -1377,11 +1722,9 @@ struct bt_ctf_field *get_next_field(struct bt_ctf_notif_iter *notit) assert(!stack_empty(notit->stack)); index = stack_top(notit->stack)->index; base_field = stack_top(notit->stack)->base; + assert(base_field); base_type = bt_ctf_field_get_type(base_field); - if (!base_type) { - PERR("Failed to get base field's type\n"); - goto end; - } + assert(base_type); switch (bt_ctf_field_type_get_type_id(base_type)) { case BT_CTF_FIELD_TYPE_ID_STRUCT: @@ -1398,12 +1741,15 @@ struct bt_ctf_field *get_next_field(struct bt_ctf_notif_iter *notit) next_field = bt_ctf_field_variant_get_current_field(base_field); break; default: + BT_LOGF("Unknown base field type ID: " + "notit-addr=%p, ft-addr=%p, ft-id=%s", + notit, base_type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(base_type))); abort(); } -end: BT_PUT(base_type); - return next_field; } @@ -1420,11 +1766,10 @@ void update_clock_state(uint64_t *state, value_type = bt_ctf_field_get_type(value_field); assert(value_type); - + assert(bt_ctf_field_type_is_integer(value_type)); requested_new_value_size = bt_ctf_field_type_integer_get_size(value_type); assert(requested_new_value_size > 0); - ret = bt_ctf_field_unsigned_integer_get_value(value_field, &requested_new_value); assert(!ret); @@ -1457,6 +1802,8 @@ void update_clock_state(uint64_t *state, /* Set the low bits of the current clock value. */ *state |= requested_new_value; end: + BT_LOGV("Updated clock's value from integer field's value: " + "value=%" PRIu64, *state); bt_put(value_type); } @@ -1471,10 +1818,7 @@ enum bt_ctf_btr_status update_clock(struct bt_ctf_notif_iter *notit, struct bt_ctf_clock_class *clock_class = NULL; int_field_type = bt_ctf_field_get_type(int_field); - if (unlikely(!int_field_type)) { - goto end; - } - + assert(int_field_type); clock_class = bt_ctf_field_type_integer_get_mapped_clock_class( int_field_type); if (likely(!clock_class)) { @@ -1482,13 +1826,8 @@ enum bt_ctf_btr_status update_clock(struct bt_ctf_notif_iter *notit, } clock_class_found = g_hash_table_lookup_extended(notit->clock_states, - clock_class, NULL, (gpointer) &clock_state); + clock_class, NULL, (gpointer) &clock_state); if (unlikely(!clock_class_found)) { - const char *clock_class_name = - bt_ctf_clock_class_get_name(clock_class); - - PERR("Unknown clock class %s mapped to integer encountered in stream\n", - clock_class_name ? : "NULL"); ret = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1496,14 +1835,21 @@ enum bt_ctf_btr_status update_clock(struct bt_ctf_notif_iter *notit, if (unlikely(!clock_state)) { clock_state = g_new0(uint64_t, 1); if (!clock_state) { + BT_LOGE_STR("Failed to allocate a uint64_t."); ret = BT_CTF_BTR_STATUS_ENOMEM; goto end; } + g_hash_table_insert(notit->clock_states, bt_get(clock_class), - clock_state); + clock_state); } /* Update the clock's state. */ + BT_LOGV("Updating notification iterator's clock's value from integer field: " + "notit-addr=%p, clock-class-addr=%p, " + "clock-class-name=\"%s\", value=%" PRIu64, + notit, clock_class, + bt_ctf_clock_class_get_name(clock_class), *clock_state); update_clock_state(clock_state, int_field); end: bt_put(int_field_type); @@ -1522,10 +1868,18 @@ enum bt_ctf_btr_status btr_unsigned_int_common(uint64_t value, struct bt_ctf_notif_iter *notit = data; int ret; + BT_LOGV("Common unsigned integer function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s, value=%" PRIu64, + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type)), + value); + /* Create next field */ field = get_next_field(notit); if (!field) { - PERR("Failed to get next field (unsigned int)\n"); + BT_LOGW("Cannot get next field: notit-addr=%p", notit); status = BT_CTF_BTR_STATUS_ERROR; goto end_no_put; } @@ -1538,26 +1892,27 @@ enum bt_ctf_btr_status btr_unsigned_int_common(uint64_t value, break; case BT_CTF_FIELD_TYPE_ID_ENUM: int_field = bt_ctf_field_enumeration_get_container(field); + assert(int_field); type = bt_ctf_field_get_type(int_field); + assert(type); break; default: + BT_LOGF("Unexpected field type ID: " + "notit-addr=%p, ft-addr=%p, ft-id=%s", + notit, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); abort(); } - if (!int_field) { - PERR("Failed to get integer field\n"); - status = BT_CTF_BTR_STATUS_ERROR; - goto end; - } - + assert(int_field); ret = bt_ctf_field_unsigned_integer_set_value(int_field, value); - assert(!ret); + assert(ret == 0); stack_top(notit->stack)->index++; *out_int_field = int_field; - -end: BT_PUT(field); BT_PUT(type); + end_no_put: return status; } @@ -1570,6 +1925,12 @@ enum bt_ctf_btr_status btr_timestamp_end_cb(void *value, struct bt_ctf_field *field = NULL; struct bt_ctf_notif_iter *notit = data; + BT_LOGV("`timestamp_end` unsigned integer function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); status = btr_unsigned_int_common(*((uint64_t *) value), type, data, &field); @@ -1587,15 +1948,23 @@ enum bt_ctf_btr_status btr_unsigned_int_cb(uint64_t value, struct bt_ctf_field *field = NULL; struct field_cb_override *override; - override = g_hash_table_lookup(notit->field_overrides, - type); + BT_LOGV("Unsigned integer function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s, value=%" PRIu64, + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type)), + value); + override = g_hash_table_lookup(notit->field_overrides, type); if (unlikely(override)) { + /* Override function logs errors */ status = override->func(&value, type, override->data); goto end; } status = btr_unsigned_int_common(value, type, data, &field); if (status != BT_CTF_BTR_STATUS_OK) { + /* btr_unsigned_int_common() logs errors */ goto end; } @@ -1615,10 +1984,18 @@ enum bt_ctf_btr_status btr_signed_int_cb(int64_t value, struct bt_ctf_notif_iter *notit = data; int ret; + BT_LOGV("Signed integer function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s, value=%" PRId64, + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type)), + value); + /* create next field */ field = get_next_field(notit); if (!field) { - PERR("Failed to get next field (signed int)\n"); + BT_LOGW("Cannot get next field: notit-addr=%p", notit); status = BT_CTF_BTR_STATUS_ERROR; goto end_no_put; } @@ -1631,26 +2008,28 @@ enum bt_ctf_btr_status btr_signed_int_cb(int64_t value, break; case BT_CTF_FIELD_TYPE_ID_ENUM: int_field = bt_ctf_field_enumeration_get_container(field); + assert(int_field); type = bt_ctf_field_get_type(int_field); + assert(type); break; default: + BT_LOGF("Unexpected field type ID: " + "notit-addr=%p, ft-addr=%p, ft-id=%s", + notit, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); abort(); } - if (!int_field) { - PERR("Failed to get integer field\n"); - status = BT_CTF_BTR_STATUS_ERROR; - goto end; - } - + assert(int_field); ret = bt_ctf_field_signed_integer_set_value(int_field, value); assert(!ret); stack_top(notit->stack)->index++; status = update_clock(notit, int_field); -end: BT_PUT(field); BT_PUT(int_field); BT_PUT(type); + end_no_put: return status; } @@ -1664,10 +2043,18 @@ enum bt_ctf_btr_status btr_floating_point_cb(double value, struct bt_ctf_notif_iter *notit = data; int ret; + BT_LOGV("Floating point number function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s, value=%f", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type)), + value); + /* Create next field */ field = get_next_field(notit); if (!field) { - PERR("Failed to get next field (floating point number)\n"); + BT_LOGW("Cannot get next field: notit-addr=%p", notit); status = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1678,7 +2065,6 @@ enum bt_ctf_btr_status btr_floating_point_cb(double value, end: BT_PUT(field); - return status; } @@ -1691,10 +2077,17 @@ enum bt_ctf_btr_status btr_string_begin_cb( struct bt_ctf_notif_iter *notit = data; int ret; + BT_LOGV("String (beginning) function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); + /* Create next field */ field = get_next_field(notit); if (!field) { - PERR("Failed to get next field (string)\n"); + BT_LOGW("Cannot get next field: notit-addr=%p", notit); status = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1706,7 +2099,8 @@ enum bt_ctf_btr_status btr_string_begin_cb( */ ret = stack_push(notit->stack, field); if (ret) { - PERR("Failed to push string field onto the stack\n"); + BT_LOGE("Cannot push string field on stack: " + "notit-addr=%p, field-addr=%p", notit, field); status = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1718,7 +2112,9 @@ enum bt_ctf_btr_status btr_string_begin_cb( */ ret = bt_ctf_field_string_set_value(field, ""); if (ret) { - PERR("Failed to initialize string field\n"); + BT_LOGE("Cannot initialize string field's value to an empty string: " + "notit-addr=%p, field-addr=%p, ret=%d", + notit, field, ret); status = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1738,6 +2134,14 @@ enum bt_ctf_btr_status btr_string_cb(const char *value, struct bt_ctf_notif_iter *notit = data; int ret; + BT_LOGV("String (substring) function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s, string-length=%zu", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type)), + len); + /* Get string field */ field = stack_top(notit->stack)->base; assert(field); @@ -1745,7 +2149,9 @@ enum bt_ctf_btr_status btr_string_cb(const char *value, /* Append current string */ ret = bt_ctf_field_string_append_len(field, value, len); if (ret) { - PERR("Failed to append a string to a string field\n"); + BT_LOGE("Cannot append substring to string field's value: " + "notit-addr=%p, field-addr=%p, string-length=%zu, " + "ret=%d", notit, field, len, ret); status = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1760,12 +2166,18 @@ enum bt_ctf_btr_status btr_string_end_cb( { struct bt_ctf_notif_iter *notit = data; + BT_LOGV("String (end) function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); + /* Pop string field */ stack_pop(notit->stack); /* Go to next field */ stack_top(notit->stack)->index++; - return BT_CTF_BTR_STATUS_OK; } @@ -1777,6 +2189,13 @@ enum bt_ctf_btr_status btr_compound_begin_cb( struct bt_ctf_field *field; int ret; + BT_LOGV("Compound (beginning) function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); + /* Create field */ if (stack_empty(notit->stack)) { /* Root: create dynamic scope field */ @@ -1790,20 +2209,35 @@ enum bt_ctf_btr_status btr_compound_begin_cb( * later), so also get it for our context to own it. */ bt_get(*notit->cur_dscope_field); + + if (!field) { + BT_LOGE("Cannot create compound field: " + "notit-addr=%p, ft-addr=%p, ft-id=%s", + notit, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); + status = BT_CTF_BTR_STATUS_ERROR; + goto end; + } } else { field = get_next_field(notit); - } - - if (!field) { - PERR("Failed to get next field or create dynamic scope field\n"); - status = BT_CTF_BTR_STATUS_ERROR; - goto end; + if (!field) { + BT_LOGW("Cannot get next field: notit-addr=%p", notit); + status = BT_CTF_BTR_STATUS_ERROR; + goto end; + } } /* Push field */ + assert(field); ret = stack_push(notit->stack, field); if (ret) { - PERR("Failed to push compound field onto the stack\n"); + BT_LOGE("Cannot push compound field onto the stack: " + "notit-addr=%p, ft-addr=%p, ft-id=%s, ret=%d", + notit, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type)), + ret); status = BT_CTF_BTR_STATUS_ERROR; goto end; } @@ -1819,6 +2253,12 @@ enum bt_ctf_btr_status btr_compound_end_cb( { struct bt_ctf_notif_iter *notit = data; + BT_LOGV("Compound (end) function called from BTR: " + "notit-addr=%p, btr-addr=%p, ft-addr=%p, " + "ft-id=%s", + notit, notit->btr, type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(type))); assert(!stack_empty(notit->stack)); /* Pop stack */ @@ -1839,6 +2279,17 @@ struct bt_ctf_field *resolve_field(struct bt_ctf_notif_iter *notit, struct bt_ctf_field *field = NULL; unsigned int i; + if (BT_LOG_ON_VERBOSE) { + GString *gstr = bt_ctf_field_path_string(path); + + BT_LOGV("Resolving field path: notit-addr=%p, field-path=\"%s\"", + notit, gstr ? gstr->str : NULL); + + if (gstr) { + g_string_free(gstr, TRUE); + } + } + switch (bt_ctf_field_path_get_root_scope(path)) { case BT_CTF_SCOPE_TRACE_PACKET_HEADER: field = notit->dscopes.trace_packet_header; @@ -1859,10 +2310,18 @@ struct bt_ctf_field *resolve_field(struct bt_ctf_notif_iter *notit, field = notit->dscopes.event_payload; break; default: - break; + BT_LOGF("Cannot resolve field path: unknown scope: " + "notit-addr=%p, root-scope=%s", + notit, bt_ctf_scope_string( + bt_ctf_field_path_get_root_scope(path))); + abort(); } if (!field) { + BT_LOGW("Cannot resolve field path: root field not found: " + "notit-addr=%p, root-scope=%s", + notit, bt_ctf_scope_string( + bt_ctf_field_path_get_root_scope(path))); goto end; } @@ -1874,10 +2333,7 @@ struct bt_ctf_field *resolve_field(struct bt_ctf_notif_iter *notit, int index = bt_ctf_field_path_get_index(path, i); field_type = bt_ctf_field_get_type(field); - if (!field_type) { - BT_PUT(field); - goto end; - } + assert(field_type); if (is_struct_type(field_type)) { next_field = bt_ctf_field_structure_get_field_by_index( @@ -1891,6 +2347,12 @@ struct bt_ctf_field *resolve_field(struct bt_ctf_notif_iter *notit, BT_PUT(field_type); if (!next_field) { + BT_LOGW("Cannot find next field: " + "notit-addr=%p, ft-addr=%p, ft-id=%s, index=%d", + notit, field_type, + bt_ctf_field_type_id_string( + bt_ctf_field_type_get_type_id(field_type)), + index); goto end; } @@ -1907,31 +2369,40 @@ int64_t btr_get_sequence_length_cb(struct bt_ctf_field_type *type, void *data) { int64_t ret = -1; int iret; + struct bt_ctf_field *seq_field; struct bt_ctf_field_path *field_path; struct bt_ctf_notif_iter *notit = data; struct bt_ctf_field *length_field = NULL; uint64_t length; field_path = bt_ctf_field_type_sequence_get_length_field_path(type); - if (!field_path) { - goto end; - } - + assert(field_path); length_field = resolve_field(notit, field_path); if (!length_field) { + BT_LOGW("Cannot resolve sequence field type's length field path: " + "notit-addr=%p, ft-addr=%p", + notit, type); goto end; } iret = bt_ctf_field_unsigned_integer_get_value(length_field, &length); if (iret) { + BT_LOGE("Cannot get value of sequence length field: " + "notit-addr=%p, field-addr=%p", + notit, length_field); goto end; } - iret = bt_ctf_field_sequence_set_length(stack_top(notit->stack)->base, - length_field); + seq_field = stack_top(notit->stack)->base; + iret = bt_ctf_field_sequence_set_length(seq_field, length_field); if (iret) { + BT_LOGE("Cannot set sequence field's length field: " + "notit-addr=%p, seq-field-addr=%p, " + "length-field-addr=%p, ", + notit, seq_field, length_field); goto end; } + ret = (int64_t) length; end: @@ -1947,17 +2418,18 @@ struct bt_ctf_field_type *btr_get_variant_type_cb( { struct bt_ctf_field_path *path; struct bt_ctf_notif_iter *notit = data; + struct bt_ctf_field *var_field; struct bt_ctf_field *tag_field = NULL; struct bt_ctf_field *selected_field = NULL; struct bt_ctf_field_type *selected_field_type = NULL; path = bt_ctf_field_type_variant_get_tag_field_path(type); - if (!path) { - goto end; - } - + assert(path); tag_field = resolve_field(notit, path); if (!tag_field) { + BT_LOGW("Cannot resolve variant field type's tag field path: " + "notit-addr=%p, ft-addr=%p", + notit, type); goto end; } @@ -1973,9 +2445,12 @@ struct bt_ctf_field_type *btr_get_variant_type_cb( * function call which is used to fill the current selected * field. */ - selected_field = bt_ctf_field_variant_get_field( - stack_top(notit->stack)->base, tag_field); + var_field = stack_top(notit->stack)->base; + selected_field = bt_ctf_field_variant_get_field(var_field, tag_field); if (!selected_field) { + BT_LOGW("Cannot get variant field's selection using tag field: " + "notit-addr=%p, var-field-addr=%p, tag-field-addr=%p", + notit, var_field, tag_field); goto end; } @@ -2007,15 +2482,39 @@ int set_event_clocks(struct bt_ctf_event *event, clock_value = bt_ctf_clock_value_create(clock_class, *clock_state); if (!clock_value) { + BT_LOGE("Cannot create clock value from clock class: " + "notit-addr=%p, clock-class-addr=%p, " + "clock-class-name=\"%s\"", + notit, clock_class, + bt_ctf_clock_class_get_name(clock_class)); ret = -1; goto end; } ret = bt_ctf_event_set_clock_value(event, clock_value); bt_put(clock_value); if (ret) { + struct bt_ctf_event_class *event_class = + bt_ctf_event_get_class(event); + + assert(event_class); + BT_LOGE("Cannot set event's clock value: " + "notit-addr=%p, event-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", " + "clock-class-addr=%p, " + "clock-class-name=\"%s\", " + "clock-value-addr=%p", + notit, event, + bt_ctf_event_class_get_name(event_class), + bt_ctf_event_class_get_id(event_class), + clock_class, + bt_ctf_clock_class_get_name(clock_class), + clock_value); + bt_put(event_class); goto end; } } + ret = 0; end: return ret; @@ -2027,9 +2526,24 @@ struct bt_ctf_event *create_event(struct bt_ctf_notif_iter *notit) int ret; struct bt_ctf_event *event; + BT_LOGV("Creating event for event notification: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64, + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class)); + /* Create event object. */ event = bt_ctf_event_create(notit->meta.event_class); if (!event) { + BT_LOGE("Cannot create event: " + "notit-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64, + notit, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class)); goto error; } @@ -2037,29 +2551,68 @@ struct bt_ctf_event *create_event(struct bt_ctf_notif_iter *notit) ret = bt_ctf_event_set_header(event, notit->dscopes.stream_event_header); if (ret) { + BT_LOGE("Cannot set event's header field: " + "notit-addr=%p, event-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", field-addr=%p", + notit, event, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + notit->dscopes.stream_event_header); goto error; } ret = bt_ctf_event_set_stream_event_context(event, notit->dscopes.stream_event_context); if (ret) { + BT_LOGE("Cannot set event's context field: " + "notit-addr=%p, event-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", field-addr=%p", + notit, event, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + notit->dscopes.stream_event_context); goto error; } ret = bt_ctf_event_set_event_context(event, notit->dscopes.event_context); if (ret) { + BT_LOGE("Cannot set event's stream event context field: " + "notit-addr=%p, event-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", field-addr=%p", + notit, event, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + notit->dscopes.event_context); goto error; } ret = bt_ctf_event_set_event_payload(event, notit->dscopes.event_payload); if (ret) { + BT_LOGE("Cannot set event's payload field: " + "notit-addr=%p, event-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", field-addr=%p", + notit, event, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + notit->dscopes.event_payload); goto error; } ret = set_event_clocks(event, notit); if (ret) { + BT_LOGE("Cannot set event's clock values: " + "notit-addr=%p, event-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64, + notit, event, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class)); goto error; } @@ -2067,12 +2620,22 @@ struct bt_ctf_event *create_event(struct bt_ctf_notif_iter *notit) assert(notit->packet); ret = bt_ctf_event_set_packet(event, notit->packet); if (ret) { + BT_LOGE("Cannot set event's header field: " + "notit-addr=%p, event-addr=%p, event-class-addr=%p, " + "event-class-name=\"%s\", " + "event-class-id=%" PRId64 ", packet-addr=%p", + notit, event, notit->meta.event_class, + bt_ctf_event_class_get_name(notit->meta.event_class), + bt_ctf_event_class_get_id(notit->meta.event_class), + notit->packet); goto error; } goto end; + error: BT_PUT(event); + end: return event; } @@ -2084,39 +2647,92 @@ void create_packet(struct bt_ctf_notif_iter *notit) struct bt_ctf_stream *stream = NULL; struct bt_ctf_packet *packet = NULL; + BT_LOGV("Creating packet for packet notification: " + "notit-addr=%p", notit); + /* Ask the user for the stream */ + BT_LOGV("Calling user function (get stream): notit-addr=%p, " + "stream-class-addr=%p, stream-class-name=\"%s\", " + "stream-class-id=%" PRId64, + notit, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class)); stream = notit->medium.medops.get_stream(notit->meta.stream_class, notit->medium.data); + BT_LOGV("User function returned: stream-addr=%p", + stream); if (!stream) { + BT_LOGW_STR("User function failed to return a stream object for the given stream class."); goto error; } + BT_LOGV("Creating packet from stream: " + "notit-addr=%p, stream-addr=%p, " + "stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64, + notit, stream, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class)); + /* Create packet */ packet = bt_ctf_packet_create(stream); if (!packet) { + BT_LOGE("Cannot create packet from stream: " + "notit-addr=%p, stream-addr=%p, " + "stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64, + notit, stream, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class)); goto error; } /* Set packet's context and header fields */ if (notit->dscopes.trace_packet_header) { ret = bt_ctf_packet_set_header(packet, - notit->dscopes.trace_packet_header); + notit->dscopes.trace_packet_header); if (ret) { + BT_LOGE("Cannot set packet's header field: " + "notit-addr=%p, packet-addr=%p, " + "stream-addr=%p, " + "stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", " + "field-addr=%p", + notit, packet, stream, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + notit->dscopes.trace_packet_header); goto error; } } if (notit->dscopes.stream_packet_context) { ret = bt_ctf_packet_set_context(packet, - notit->dscopes.stream_packet_context); + notit->dscopes.stream_packet_context); if (ret) { + BT_LOGE("Cannot set packet's context field: " + "notit-addr=%p, packet-addr=%p, " + "stream-addr=%p, " + "stream-class-addr=%p, " + "stream-class-name=\"%s\", " + "stream-class-id=%" PRId64 ", " + "field-addr=%p", + notit, packet, stream, notit->meta.stream_class, + bt_ctf_stream_class_get_name(notit->meta.stream_class), + bt_ctf_stream_class_get_id(notit->meta.stream_class), + notit->dscopes.trace_packet_header); goto error; } } goto end; + error: BT_PUT(packet); + end: BT_MOVE(notit->packet, packet); } @@ -2130,11 +2746,16 @@ void notify_new_packet(struct bt_ctf_notif_iter *notit, /* Initialize the iterator's current packet */ create_packet(notit); if (!notit->packet) { + BT_LOGE("Cannot create packet for packet notification: " + "notit-addr=%p", notit); return; } ret = bt_notification_packet_begin_create(notit->packet); if (!ret) { + BT_LOGE("Cannot create packet beginning notification: " + "notit-addr=%p, packet-addr=%p", + notit, notit->packet); return; } *notification = ret; @@ -2152,6 +2773,9 @@ void notify_end_of_packet(struct bt_ctf_notif_iter *notit, ret = bt_notification_packet_end_create(notit->packet); if (!ret) { + BT_LOGE("Cannot create packet end notification: " + "notit-addr=%p, packet-addr=%p", + notit, notit->packet); return; } BT_PUT(notit->packet); @@ -2169,11 +2793,17 @@ void notify_event(struct bt_ctf_notif_iter *notit, /* Create event */ event = create_event(notit); if (!event) { + BT_LOGE("Cannot create event for event notification: " + "notit-addr=%p", notit); goto end; } ret = bt_notification_event_create(event, cc_prio_map); if (!ret) { + BT_LOGE("Cannot create event notification: " + "notit-addr=%p, event-addr=%p, " + "cc-prio-map-addr=%p", + notit, event, cc_prio_map); goto end; } *notification = ret; @@ -2186,25 +2816,19 @@ int init_clock_states(GHashTable *clock_states, struct bt_ctf_trace *trace) { int clock_class_count, i, ret = 0; + assert(trace); clock_class_count = bt_ctf_trace_get_clock_class_count(trace); - if (clock_class_count <= 0) { - ret = -1; - goto end; - } + assert(clock_class_count >= 0); for (i = 0; i < clock_class_count; i++) { struct bt_ctf_clock_class *clock_class; clock_class = bt_ctf_trace_get_clock_class_by_index(trace, i); - if (!clock_class) { - ret = -1; - goto end; - } - + assert(clock_class); g_hash_table_insert(clock_states, bt_get(clock_class), NULL); bt_put(clock_class); } -end: + return ret; } @@ -2227,9 +2851,7 @@ void init_trace_field_path_cache(struct bt_ctf_trace *trace, } count = bt_ctf_field_type_structure_get_field_count(packet_header); - if (count < 0) { - goto end; - } + assert(count >= 0); for (i = 0; (i < count && (stream_id == -1 || stream_instance_id == -1)); i++) { int ret; @@ -2238,6 +2860,9 @@ void init_trace_field_path_cache(struct bt_ctf_trace *trace, ret = bt_ctf_field_type_structure_get_field(packet_header, &field_name, NULL, i); if (ret) { + BT_LOGE("Cannot get structure field's field: " + "field-addr=%p, index=%d", + packet_header, i); goto end; } @@ -2248,6 +2873,7 @@ void init_trace_field_path_cache(struct bt_ctf_trace *trace, stream_instance_id = i; } } + end: trace_field_path_cache->stream_id = stream_id; trace_field_path_cache->stream_instance_id = stream_instance_id; @@ -2282,20 +2908,24 @@ struct bt_ctf_notif_iter *bt_ctf_notif_iter_create(struct bt_ctf_trace *trace, assert(trace); assert(medops.request_bytes); assert(medops.get_stream); + BT_LOGD("Creating CTF plugin notification iterator: " + "trace-addr=%p, trace-name=\"%s\", max-request-size=%zu, " + "data=%p", + trace, bt_ctf_trace_get_name(trace), max_request_sz, data); notit = g_new0(struct bt_ctf_notif_iter, 1); if (!notit) { - PERR("Failed to allocate memory for CTF notification iterator\n"); + BT_LOGE_STR("Failed to allocate one CTF plugin notification iterator."); goto end; } notit->clock_states = g_hash_table_new_full(g_direct_hash, - g_direct_equal, bt_put, g_free); + g_direct_equal, bt_put, g_free); if (!notit->clock_states) { - PERR("Failed to create hash table\n"); + BT_LOGE_STR("Failed to allocate a GHashTable."); goto error; } ret = init_clock_states(notit->clock_states, trace); if (ret) { - PERR("Failed to initialize stream clock states\n"); + BT_LOGW("Cannot initialize clock values."); goto error; } notit->meta.trace = bt_get(trace); @@ -2305,34 +2935,41 @@ struct bt_ctf_notif_iter *bt_ctf_notif_iter_create(struct bt_ctf_trace *trace, notit->err_stream = err_stream; notit->stack = stack_new(notit); if (!notit->stack) { - PERR("Failed to create stack\n"); + BT_LOGE_STR("Failed to create field stack."); goto error; } notit->btr = bt_ctf_btr_create(cbs, notit, err_stream); if (!notit->btr) { - PERR("Failed to create binary type reader\n"); + BT_LOGE_STR("Failed to create binary type reader (BTR)."); goto error; } bt_ctf_notif_iter_reset(notit); - init_trace_field_path_cache(trace, ¬it->trace_field_path_cache); notit->sc_field_path_caches = g_hash_table_new_full(g_direct_hash, - g_direct_equal, bt_put, g_free); + g_direct_equal, bt_put, g_free); if (!notit->sc_field_path_caches) { - PERR("Failed to create stream class field path caches\n"); + BT_LOGE_STR("Failed to allocate a GHashTable."); goto error; } notit->field_overrides = g_hash_table_new_full(g_direct_hash, - g_direct_equal, bt_put, g_free); + g_direct_equal, bt_put, g_free); if (!notit->field_overrides) { + BT_LOGE_STR("Failed to allocate a GHashTable."); goto error; } + BT_LOGD("Created CTF plugin notification iterator: " + "trace-addr=%p, trace-name=\"%s\", max-request-size=%zu, " + "data=%p, notit-addr=%p", + trace, bt_ctf_trace_get_name(trace), max_request_sz, data, + notit); + end: return notit; + error: bt_ctf_notif_iter_destroy(notit); notit = NULL; @@ -2348,11 +2985,15 @@ void bt_ctf_notif_iter_destroy(struct bt_ctf_notif_iter *notit) BT_PUT(notit->cur_timestamp_end); put_all_dscopes(notit); + BT_LOGD("Destroying CTF plugin notification iterator: addr=%p", notit); + if (notit->stack) { + BT_LOGD_STR("Destroying field stack."); stack_destroy(notit->stack); } if (notit->btr) { + BT_LOGD("Destroying BTR: btr-addr=%p", notit->btr); bt_ctf_btr_destroy(notit->btr); } @@ -2367,6 +3008,7 @@ void bt_ctf_notif_iter_destroy(struct bt_ctf_notif_iter *notit) if (notit->field_overrides) { g_hash_table_destroy(notit->field_overrides); } + g_free(notit); } @@ -2380,32 +3022,36 @@ enum bt_ctf_notif_iter_status bt_ctf_notif_iter_get_next_notification( assert(notit); assert(notification); + BT_LOGV("Getting next notification: notit-addr=%p, cc-prio-map-addr=%p", + notit, cc_prio_map); + while (true) { status = handle_state(notit); if (status == BT_CTF_NOTIF_ITER_STATUS_AGAIN) { - PDBG("Medium operation reported \"try again later\""); + BT_LOGV_STR("Medium returned BT_CTF_NOTIF_ITER_STATUS_AGAIN."); goto end; } if (status != BT_CTF_NOTIF_ITER_STATUS_OK) { if (status == BT_CTF_NOTIF_ITER_STATUS_EOF) { - PDBG("Medium operation reported end of stream\n"); + BT_LOGV_STR("Medium returned BT_CTF_NOTIF_ITER_STATUS_EOF."); } else { - PERR("Failed to handle state:\n"); - PERR("\tState: %d\n", notit->state); + BT_LOGW("Cannot handle state: " + "notit-addr=%p, state=%s", + notit, state_string(notit->state)); } goto end; } switch (notit->state) { case STATE_EMIT_NOTIF_NEW_PACKET: - PDBG("Emitting new packet notification\n"); + /* notify_new_packet() logs errors */ notify_new_packet(notit, notification); if (!*notification) { status = BT_CTF_NOTIF_ITER_STATUS_ERROR; } goto end; case STATE_EMIT_NOTIF_EVENT: - PDBG("Emitting event notification\n"); + /* notify_event() logs errors */ notify_event(notit, cc_prio_map, notification); if (!*notification) { status = BT_CTF_NOTIF_ITER_STATUS_ERROR; @@ -2419,16 +3065,19 @@ enum bt_ctf_notif_iter_status bt_ctf_notif_iter_get_next_notification( bt_ctf_field_get_type( notit->cur_timestamp_end); + assert(field_type); btr_status = update_clock(notit, notit->cur_timestamp_end); BT_PUT(field_type); if (btr_status != BT_CTF_BTR_STATUS_OK) { + BT_LOGW("Cannot update stream's clock value: " + "notit-addr=%p", notit); status = BT_CTF_NOTIF_ITER_STATUS_ERROR; goto end; } } - PDBG("Emitting end of packet notification\n"); + /* notify_end_of_packet() logs errors */ notify_end_of_packet(notit, notification); if (!*notification) { status = BT_CTF_NOTIF_ITER_STATUS_ERROR; @@ -2462,15 +3111,16 @@ enum bt_ctf_notif_iter_status bt_ctf_notif_iter_get_packet_header_context_fields while (true) { status = handle_state(notit); if (status == BT_CTF_NOTIF_ITER_STATUS_AGAIN) { - PDBG("Medium operation reported \"try again later\""); + BT_LOGV_STR("Medium returned BT_CTF_NOTIF_ITER_STATUS_AGAIN."); goto end; } if (status != BT_CTF_NOTIF_ITER_STATUS_OK) { if (status == BT_CTF_NOTIF_ITER_STATUS_EOF) { - PDBG("Medium operation reported end of stream\n"); + BT_LOGV_STR("Medium returned BT_CTF_NOTIF_ITER_STATUS_EOF."); } else { - PERR("Failed to handle state:\n"); - PERR("\tState: %d\n", notit->state); + BT_LOGW("Cannot handle state: " + "notit-addr=%p, state=%s", + notit, state_string(notit->state)); } goto end; } @@ -2496,6 +3146,8 @@ enum bt_ctf_notif_iter_status bt_ctf_notif_iter_get_packet_header_context_fields * We should never get past the * STATE_EMIT_NOTIF_NEW_PACKET state. */ + BT_LOGF("Unexpected state: notit-addr=%p, state=%s", + notit, state_string(notit->state)); abort(); } } diff --git a/plugins/ctf/common/notif-iter/notif-iter.h b/plugins/ctf/common/notif-iter/notif-iter.h index 23277754..1fbf952a 100644 --- a/plugins/ctf/common/notif-iter/notif-iter.h +++ b/plugins/ctf/common/notif-iter/notif-iter.h @@ -54,12 +54,12 @@ enum bt_ctf_notif_iter_medium_status { * The medium function called by the notification iterator * function reached the end of the file. */ - BT_CTF_NOTIF_ITER_MEDIUM_STATUS_EOF = -4, + BT_CTF_NOTIF_ITER_MEDIUM_STATUS_EOF = 1, /** * There is no data available right now, try again later. */ - BT_CTF_NOTIF_ITER_MEDIUM_STATUS_AGAIN = -3, + BT_CTF_NOTIF_ITER_MEDIUM_STATUS_AGAIN = 11, /** Invalid argument. */ BT_CTF_NOTIF_ITER_MEDIUM_STATUS_INVAL = -2, @@ -302,4 +302,44 @@ enum bt_ctf_notif_iter_status bt_ctf_notif_iter_get_packet_header_context_fields struct bt_ctf_field **packet_header_field, struct bt_ctf_field **packet_context_field); +static inline +const char *bt_ctf_notif_iter_medium_status_string( + enum bt_ctf_notif_iter_medium_status status) +{ + switch (status) { + case BT_CTF_NOTIF_ITER_MEDIUM_STATUS_EOF: + return "BT_CTF_NOTIF_ITER_MEDIUM_STATUS_EOF"; + case BT_CTF_NOTIF_ITER_MEDIUM_STATUS_AGAIN: + return "BT_CTF_NOTIF_ITER_MEDIUM_STATUS_AGAIN"; + case BT_CTF_NOTIF_ITER_MEDIUM_STATUS_INVAL: + return "BT_CTF_NOTIF_ITER_MEDIUM_STATUS_INVAL"; + case BT_CTF_NOTIF_ITER_MEDIUM_STATUS_ERROR: + return "BT_CTF_NOTIF_ITER_MEDIUM_STATUS_ERROR"; + case BT_CTF_NOTIF_ITER_MEDIUM_STATUS_OK: + return "BT_CTF_NOTIF_ITER_MEDIUM_STATUS_OK"; + default: + return "(unknown)"; + } +} + +static inline +const char *bt_ctf_notif_iter_status_string( + enum bt_ctf_notif_iter_status status) +{ + switch (status) { + case BT_CTF_NOTIF_ITER_STATUS_EOF: + return "BT_CTF_NOTIF_ITER_STATUS_EOF"; + case BT_CTF_NOTIF_ITER_STATUS_AGAIN: + return "BT_CTF_NOTIF_ITER_STATUS_AGAIN"; + case BT_CTF_NOTIF_ITER_STATUS_INVAL: + return "BT_CTF_NOTIF_ITER_STATUS_INVAL"; + case BT_CTF_NOTIF_ITER_STATUS_ERROR: + return "BT_CTF_NOTIF_ITER_STATUS_ERROR"; + case BT_CTF_NOTIF_ITER_STATUS_OK: + return "BT_CTF_NOTIF_ITER_STATUS_OK"; + default: + return "(unknown)"; + } +} + #endif /* CTF_NOTIF_ITER_H */ diff --git a/plugins/ctf/lttng-live/data-stream.c b/plugins/ctf/lttng-live/data-stream.c index 810c93aa..43e281bd 100644 --- a/plugins/ctf/lttng-live/data-stream.c +++ b/plugins/ctf/lttng-live/data-stream.c @@ -65,7 +65,6 @@ enum bt_ctf_notif_iter_medium_status medop_request_bytes( status = lttng_live_get_stream_bytes(lttng_live, stream, stream->buf, stream->offset, read_len, &recv_len); - BT_LOGV_MEM(stream->buf, recv_len, "Live receive payload"); *buffer_addr = stream->buf; *buffer_sz = recv_len; stream->offset += recv_len;