From cbca1c06c79966c7fb9fe5b08ccd9c95fa3620cc Mon Sep 17 00:00:00 2001 From: Simon Marchi Date: Thu, 7 Nov 2019 17:27:27 -0500 Subject: [PATCH] Save and restore error in ctf_fs_iterator_next, muxer_msg_iter_do_next ctf_fs_iterator_next and muxer_msg_iter_do_next are written in such a way that if they successfully accumulate some messages, then hit an error, they will return OK to make sure that those messages propagate downstream in the graph, before the error stops the execution. This assumes that the subsequent call to _next will fail again. This poses a problem: when it returns OK in this case, it also leaves the current thread error set. This is a postcondition breach. One solution would be to simply clear the error in that case. This would still rely on some error (perhaps the same, perhaps not) to be hit again on the next _next call. What I don't like with that solution is that the behaviour of the iterator, if we call _next again after a failure, is hard to predict. We could hit the same error if we are lucky, we could hit another error, we could hit an assertion because we are in an unexpected state, etc. Instead, this patch implements the following solution: return OK, but take the error from the current thread and save it in the iterator. The next time _next is called, that error is moved back to the current thread and the error status is returned. This ensures that the error the user will see is the one that originally caused the problem. A test is added with a trace containing two valid events followed by an invalid one. We expect to see the two events printed by the details sink, as well as the error about the invalid event class id. Change-Id: I725f1de0e6fa0b430aa34bfc524811c5dcd80fa3 Signed-off-by: Simon Marchi Reviewed-on: https://review.lttng.org/c/babeltrace/+/2353 --- src/plugins/ctf/fs-src/fs.c | 33 +++++++++++++--- src/plugins/ctf/fs-src/fs.h | 8 ++++ src/plugins/utils/muxer/muxer.c | 39 +++++++++++++++++-- .../valid-events-then-invalid-events/README | 2 + .../trace/dummystream | 1 + .../trace/metadata | 21 ++++++++++ .../valid-events-then-invalid-events.expect | 22 +++++++++++ tests/plugins/src.ctf.fs/fail/test_fail | 28 +++++++++++-- 8 files changed, 141 insertions(+), 13 deletions(-) create mode 100644 tests/data/ctf-traces/fail/valid-events-then-invalid-events/README create mode 100644 tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/dummystream create mode 100644 tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/metadata create mode 100644 tests/data/plugins/src.ctf.fs/fail/valid-events-then-invalid-events.expect diff --git a/src/plugins/ctf/fs-src/fs.c b/src/plugins/ctf/fs-src/fs.c index 43b131fa..79dd49e7 100644 --- a/src/plugins/ctf/fs-src/fs.c +++ b/src/plugins/ctf/fs-src/fs.c @@ -173,19 +173,29 @@ bt_component_class_message_iterator_next_method_status ctf_fs_iterator_next( bt_message_array_const msgs, uint64_t capacity, uint64_t *count) { - bt_component_class_message_iterator_next_method_status status = - BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK; + bt_component_class_message_iterator_next_method_status status; struct ctf_fs_msg_iter_data *msg_iter_data = bt_self_message_iterator_get_data(iterator); uint64_t i = 0; - while (i < capacity && - status == BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK) { + if (G_UNLIKELY(msg_iter_data->next_saved_error)) { + /* + * Last time we were called, we hit an error but had some + * messages to deliver, so we stashed the error here. Return + * it now. + */ + BT_CURRENT_THREAD_MOVE_ERROR_AND_RESET(msg_iter_data->next_saved_error); + status = msg_iter_data->next_saved_status; + goto end; + } + + do { status = ctf_fs_iterator_next_one(msg_iter_data, &msgs[i]); if (status == BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK) { i++; } - } + } while (i < capacity && + status == BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK); if (i > 0) { /* @@ -199,10 +209,23 @@ bt_component_class_message_iterator_next_method_status ctf_fs_iterator_next( * called, possibly without any accumulated * message, in which case we'll return it. */ + if (status < 0) { + /* + * Save this error for the next _next call. Assume that + * this component always appends error causes when + * returning an error status code, which will cause the + * current thread error to be non-NULL. + */ + msg_iter_data->next_saved_error = bt_current_thread_take_error(); + BT_ASSERT(msg_iter_data->next_saved_error); + msg_iter_data->next_saved_status = status; + } + *count = i; status = BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK; } +end: return status; } diff --git a/src/plugins/ctf/fs-src/fs.h b/src/plugins/ctf/fs-src/fs.h index 95fffa24..a6594b1c 100644 --- a/src/plugins/ctf/fs-src/fs.h +++ b/src/plugins/ctf/fs-src/fs.h @@ -194,6 +194,14 @@ struct ctf_fs_msg_iter_data { /* Owned by this */ struct ctf_msg_iter *msg_iter; + + /* + * Saved error. If we hit an error in the _next method, but have some + * messages ready to return, we save the error here and return it on + * the next _next call. + */ + bt_component_class_message_iterator_next_method_status next_saved_status; + const struct bt_error *next_saved_error; }; BT_HIDDEN diff --git a/src/plugins/utils/muxer/muxer.c b/src/plugins/utils/muxer/muxer.c index 1571167c..638bc0c9 100644 --- a/src/plugins/utils/muxer/muxer.c +++ b/src/plugins/utils/muxer/muxer.c @@ -107,6 +107,14 @@ struct muxer_msg_iter { * MUXER_MSG_ITER_CLOCK_CLASS_EXPECTATION_NOT_ABS_SPEC_UUID. */ bt_uuid_t expected_clock_class_uuid; + + /* + * Saved error. If we hit an error in the _next method, but have some + * messages ready to return, we save the error here and return it on + * the next _next call. + */ + bt_component_class_message_iterator_next_method_status next_saved_status; + const struct bt_error *next_saved_error; }; static @@ -1101,17 +1109,27 @@ bt_component_class_message_iterator_next_method_status muxer_msg_iter_do_next( bt_message_array_const msgs, uint64_t capacity, uint64_t *count) { - bt_component_class_message_iterator_next_method_status status = - BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK; + bt_component_class_message_iterator_next_method_status status; uint64_t i = 0; - while (i < capacity && status == BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK) { + if (G_UNLIKELY(muxer_msg_iter->next_saved_error)) { + /* + * Last time we were called, we hit an error but had some + * messages to deliver, so we stashed the error here. Return + * it now. + */ + BT_CURRENT_THREAD_MOVE_ERROR_AND_RESET(muxer_msg_iter->next_saved_error); + status = muxer_msg_iter->next_saved_status; + goto end; + } + + do { status = muxer_msg_iter_do_next_one(muxer_comp, muxer_msg_iter, &msgs[i]); if (status == BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK) { i++; } - } + } while (i < capacity && status == BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK); if (i > 0) { /* @@ -1126,10 +1144,23 @@ bt_component_class_message_iterator_next_method_status muxer_msg_iter_do_next( * called, possibly without any accumulated * message, in which case we'll return it. */ + if (status < 0) { + /* + * Save this error for the next _next call. Assume that + * this component always appends error causes when + * returning an error status code, which will cause the + * current thread error to be non-NULL. + */ + muxer_msg_iter->next_saved_error = bt_current_thread_take_error(); + BT_ASSERT(muxer_msg_iter->next_saved_error); + muxer_msg_iter->next_saved_status = status; + } + *count = i; status = BT_COMPONENT_CLASS_MESSAGE_ITERATOR_NEXT_METHOD_STATUS_OK; } +end: return status; } diff --git a/tests/data/ctf-traces/fail/valid-events-then-invalid-events/README b/tests/data/ctf-traces/fail/valid-events-then-invalid-events/README new file mode 100644 index 00000000..4a90193b --- /dev/null +++ b/tests/data/ctf-traces/fail/valid-events-then-invalid-events/README @@ -0,0 +1,2 @@ +This trace was written by hand. It contains two valid events, followed by an +invalid one (the event id is invalid). diff --git a/tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/dummystream b/tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/dummystream new file mode 100644 index 00000000..415fe23e --- /dev/null +++ b/tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/dummystream @@ -0,0 +1 @@ +ΓΏ \ No newline at end of file diff --git a/tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/metadata b/tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/metadata new file mode 100644 index 00000000..479fdb64 --- /dev/null +++ b/tests/data/ctf-traces/fail/valid-events-then-invalid-events/trace/metadata @@ -0,0 +1,21 @@ +/* CTF 1.8 */ + +typealias integer { size = 8; align = 8; signed = false; } := uint8_t; + +trace { + major = 1; + minor = 8; + byte_order = be; +}; + +stream { + event.header := struct { + uint8_t id; + }; +}; + + +event { + name = gadoua; + id = 1; +}; diff --git a/tests/data/plugins/src.ctf.fs/fail/valid-events-then-invalid-events.expect b/tests/data/plugins/src.ctf.fs/fail/valid-events-then-invalid-events.expect new file mode 100644 index 00000000..dc6a8859 --- /dev/null +++ b/tests/data/plugins/src.ctf.fs/fail/valid-events-then-invalid-events.expect @@ -0,0 +1,22 @@ +Trace class: + Stream class (ID 0): + Supports packets: Yes + Packets have beginning default clock snapshot: No + Packets have end default clock snapshot: No + Supports discarded events: No + Supports discarded packets: No + Event class `gadoua` (ID 1): + +{Trace 0, Stream class ID 0, Stream ID 0} +Stream beginning: + Trace: + Stream (ID 0, Class ID 0) + +{Trace 0, Stream class ID 0, Stream ID 0} +Packet beginning + +{Trace 0, Stream class ID 0, Stream ID 0} +Event `gadoua` (Class ID 1): + +{Trace 0, Stream class ID 0, Stream ID 0} +Event `gadoua` (Class ID 1): diff --git a/tests/plugins/src.ctf.fs/fail/test_fail b/tests/plugins/src.ctf.fs/fail/test_fail index 7f8a9515..397c5e02 100755 --- a/tests/plugins/src.ctf.fs/fail/test_fail +++ b/tests/plugins/src.ctf.fs/fail/test_fail @@ -34,22 +34,42 @@ fail_trace_dir="$BT_CTF_TRACES_PATH/fail" stdout_file=$(mktemp -t test_ctf_fail_stdout.XXXXXX) stderr_file=$(mktemp -t test_ctf_fail_stderr.XXXXXX) +data_dir="${BT_TESTS_SRCDIR}/data/plugins/src.ctf.fs/fail" test_fail() { local name="$1" - local expected_error_msg="$2" + local expected_stdout_file="$2" + local expected_error_msg="$3" bt_cli "${stdout_file}" "${stderr_file}" \ - "${fail_trace_dir}/${name}" + -c sink.text.details -p "with-trace-name=no,with-stream-name=no" "${fail_trace_dir}/${name}" isnt $? 0 "Trace ${name}: babeltrace exits with an error" + bt_diff "${expected_stdout_file}" "${stdout_file}" + ok $? "Trace ${name}: babeltrace produces the expected stdout" + + # The expected error message will likely be found in the error stream + # even if Babeltrace aborts (e.g. hits an assert). Check that the + # Babeltrace CLI finishes gracefully by checking that the error stream + # contains an error stack printed by the CLI. + grep --silent "^CAUSED BY " "${stderr_file}" + ok $? "Trace ${name}: babeltrace produces an error stack" + grep --silent "${expected_error_msg}" "${stderr_file}" ok $? "Trace ${name}: babeltrace produces the expected error message" } -plan_tests 2 +plan_tests 8 + +test_fail \ + "invalid-packet-size/trace" \ + "/dev/null" \ + "Failed to index CTF stream file '.*channel0_3'" -test_fail "invalid-packet-size/trace" "Failed to index CTF stream file '.*channel0_3'" +test_fail \ + "valid-events-then-invalid-events" \ + "${data_dir}/valid-events-then-invalid-events.expect" \ + "No event class with ID of event class ID to use in stream class: .*stream-class-id=0, event-class-id=255" rm -f "${stdout_file}" "${stderr_file}" -- 2.34.1