From 05ad2afee3c088eff430f242996b93b779e524a6 Mon Sep 17 00:00:00 2001 From: Simon Marchi Date: Mon, 10 Aug 2020 10:55:37 -0400 Subject: [PATCH] sink.ctf.fs: append error causes where relevant The `sink.ctf.fs` component class doesn't append error causes when it encounters errors. This makes the error reporting very vague. For example, both when the user fails to pass the required `path` parameter and when they pass a path to a directory they don't have write permissions on, they get: ERROR: [Babeltrace CLI] (/home/simark/src/babeltrace/src/cli/babeltrace2.c:2462) Cannot create components. CAUSED BY [Babeltrace CLI] (/home/simark/src/babeltrace/src/cli/babeltrace2.c:2277) Cannot create component: plugin-name="ctf", comp-cls-name="fs", comp-cls-type=4, comp-name="sink.ctf.fs" CAUSED BY [libbabeltrace2] (/home/simark/src/babeltrace/src/lib/graph/graph.c:1055) Component initialization method failed: status=ERROR, comp-addr=0x60c000011d40, comp-name="sink.ctf.fs", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="fs", comp-class-partial-descr="Write CTF traces to the file sys", comp-class-is-frozen=1, comp-class-so-handle-addr=0x607000000100, comp-class-so-handle-path="/home/simark/build/babeltrace/src/plugins/ctf/babeltrace-plugin-ctf.la", comp-input-port-count=0, comp-output-port-count=0 Add calls to append error causes where relevant. It becomes much easier to distinguish the errors: ERROR: [Babeltrace CLI] (/home/simark/src/babeltrace/src/cli/babeltrace2.c:2462) Cannot create components. CAUSED BY [Babeltrace CLI] (/home/simark/src/babeltrace/src/cli/babeltrace2.c:2277) Cannot create component: plugin-name="ctf", comp-cls-name="fs", comp-cls-type=4, comp-name="sink.ctf.fs" CAUSED BY [libbabeltrace2] (/home/simark/src/babeltrace/src/lib/graph/graph.c:1055) Component initialization method failed: status=ERROR, comp-addr=0x60c000011d40, comp-name="sink.ctf.fs", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="fs", comp-class-partial-descr="Write CTF traces to the file sys", comp-class-is-frozen=1, comp-class-so-handle-addr=0x607000000100, comp-class-so-handle-path="/home/simark/build/babeltrace/src/plugins/ctf/babeltrace-plugin-ctf.la", comp-input-port-count=0, comp-output-port-count=0 CAUSED BY [sink.ctf.fs: 'sink.ctf.fs'] (/home/simark/src/babeltrace/src/plugins/ctf/fs-sink/fs-sink.c:74) Error validating parameters: missing mandatory entry `path` and ERROR: [Babeltrace CLI] (/home/simark/src/babeltrace/src/cli/babeltrace2.c:2462) Cannot create components. CAUSED BY [Babeltrace CLI] (/home/simark/src/babeltrace/src/cli/babeltrace2.c:2277) Cannot create component: plugin-name="ctf", comp-cls-name="fs", comp-cls-type=4, comp-name="sink.ctf.fs" CAUSED BY [libbabeltrace2] (/home/simark/src/babeltrace/src/lib/graph/graph.c:1055) Component initialization method failed: status=ERROR, comp-addr=0x60c000011e00, comp-name="sink.ctf.fs", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="fs", comp-class-partial-descr="Write CTF traces to the file sys", comp-class-is-frozen=1, comp-class-so-handle-addr=0x607000000100, comp-class-so-handle-path="/home/simark/build/babeltrace/src/plugins/ctf/babeltrace-plugin-ctf.la", comp-input-port-count=0, comp-output-port-count=0 CAUSED BY [sink.ctf.fs: 'sink.ctf.fs'] (/home/simark/src/babeltrace/src/plugins/ctf/fs-sink/fs-sink.c:40) Cannot create directories for output directory: Permission denied: output-dir-path="/tmp/pouet/yo" Change-Id: I384e88a1d2629ac75495518c8bce2a2cba2f9741 Signed-off-by: Simon Marchi Reviewed-on: https://review.lttng.org/c/babeltrace/+/3907 Reviewed-by: Philippe Proulx Tested-by: jenkins --- src/plugins/ctf/fs-sink/fs-sink.c | 98 ++++++++++++++++++++++--------- 1 file changed, 71 insertions(+), 27 deletions(-) diff --git a/src/plugins/ctf/fs-sink/fs-sink.c b/src/plugins/ctf/fs-sink/fs-sink.c index 0672890a..4b077507 100644 --- a/src/plugins/ctf/fs-sink/fs-sink.c +++ b/src/plugins/ctf/fs-sink/fs-sink.c @@ -37,7 +37,7 @@ bt_component_class_initialize_method_status ensure_output_dir_exists( ret = g_mkdir_with_parents(fs_sink->output_dir_path->str, 0755); if (ret) { - BT_COMP_LOGE_ERRNO( + BT_COMP_LOGE_APPEND_CAUSE_ERRNO(fs_sink->self_comp, "Cannot create directories for output directory", ": output-dir-path=\"%s\"", fs_sink->output_dir_path->str); @@ -71,6 +71,8 @@ configure_component(struct fs_sink_comp *fs_sink, const bt_value *params) fs_sink_params_descr, &validation_error); if (validation_status == BT_PARAM_VALIDATION_STATUS_VALIDATION_ERROR) { status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_ERROR; + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "%s", validation_error); goto end; } else if (validation_status == BT_PARAM_VALIDATION_STATUS_MEMORY_ERROR) { status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_MEMORY_ERROR; @@ -146,8 +148,7 @@ bt_component_class_initialize_method_status ctf_fs_sink_init( const bt_value *params, void *init_method_data) { - bt_component_class_initialize_method_status status = - BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_OK; + bt_component_class_initialize_method_status status; bt_self_component_add_port_status add_port_status; struct fs_sink_comp *fs_sink = NULL; bt_self_component *self_comp = @@ -159,6 +160,8 @@ bt_component_class_initialize_method_status ctf_fs_sink_init( if (!fs_sink) { BT_COMP_LOG_CUR_LVL(BT_LOG_ERROR, log_level, self_comp, "Failed to allocate one CTF FS sink structure."); + BT_CURRENT_THREAD_ERROR_APPEND_CAUSE_FROM_COMPONENT( + self_comp, "Failed to allocate one CTF FS sink structure."); status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_MEMORY_ERROR; goto end; } @@ -175,8 +178,9 @@ bt_component_class_initialize_method_status ctf_fs_sink_init( if (fs_sink->assume_single_trace && g_file_test(fs_sink->output_dir_path->str, G_FILE_TEST_EXISTS)) { - BT_COMP_LOGE("Single trace mode, but output path exists: " - "output-path=\"%s\"", fs_sink->output_dir_path->str); + BT_COMP_LOGE_APPEND_CAUSE(self_comp, + "Single trace mode, but output path exists: output-path=\"%s\"", + fs_sink->output_dir_path->str); status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_ERROR; goto end; } @@ -190,22 +194,17 @@ bt_component_class_initialize_method_status ctf_fs_sink_init( fs_sink->traces = g_hash_table_new_full(g_direct_hash, g_direct_equal, NULL, (GDestroyNotify) fs_sink_trace_destroy); if (!fs_sink->traces) { - BT_COMP_LOGE_STR("Failed to allocate one GHashTable."); + BT_COMP_LOGE_APPEND_CAUSE(self_comp, "Failed to allocate one GHashTable."); status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_MEMORY_ERROR; goto end; } add_port_status = bt_self_component_sink_add_input_port( self_comp_sink, in_port_name, NULL, NULL); - switch (add_port_status) { - case BT_SELF_COMPONENT_ADD_PORT_STATUS_ERROR: - status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_ERROR; + if (add_port_status != BT_SELF_COMPONENT_ADD_PORT_STATUS_OK) { + status = (int) add_port_status; + BT_COMP_LOGE_APPEND_CAUSE(self_comp, "Failed to add input port."); goto end; - case BT_SELF_COMPONENT_ADD_PORT_STATUS_MEMORY_ERROR: - status = BT_COMPONENT_CLASS_INITIALIZE_METHOD_STATUS_MEMORY_ERROR; - goto end; - default: - break; } bt_self_component_set_data(self_comp, fs_sink); @@ -230,7 +229,8 @@ struct fs_sink_stream *borrow_stream(struct fs_sink_comp *fs_sink, if (G_UNLIKELY(!trace)) { if (fs_sink->assume_single_trace && g_hash_table_size(fs_sink->traces) > 0) { - BT_COMP_LOGE("Single trace mode, but getting more than one trace: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Single trace mode, but getting more than one trace: " "stream-name=\"%s\"", bt_stream_get_name(ir_stream)); goto end; @@ -269,6 +269,8 @@ bt_component_class_sink_consume_method_status handle_event_msg( stream = borrow_stream(fs_sink, ir_stream); if (G_UNLIKELY(!stream)) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -276,6 +278,8 @@ bt_component_class_sink_consume_method_status handle_event_msg( ret = try_translate_event_class_trace_ir_to_ctf_ir(fs_sink, stream->sc, bt_event_borrow_class_const(ir_event), &ec); if (ret) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to translate event class to CTF IR."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -307,6 +311,8 @@ bt_component_class_sink_consume_method_status handle_event_msg( */ ret = fs_sink_stream_close_packet(stream, NULL); if (ret) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to close packet."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -316,6 +322,8 @@ bt_component_class_sink_consume_method_status handle_event_msg( /* Stream's packet is not currently opened: open it */ ret = fs_sink_stream_open_packet(stream, NULL, NULL); if (ret) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to open packet."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -325,6 +333,8 @@ bt_component_class_sink_consume_method_status handle_event_msg( BT_ASSERT_DBG(stream->packet_state.is_open); ret = fs_sink_stream_write_event(stream, cs, ir_event, ec); if (G_UNLIKELY(ret)) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to write event."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -348,6 +358,8 @@ bt_component_class_sink_consume_method_status handle_packet_beginning_msg( stream = borrow_stream(fs_sink, ir_stream); if (G_UNLIKELY(!stream)) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -399,7 +411,8 @@ bt_component_class_sink_consume_method_status handle_packet_beginning_msg( if (stream->discarded_events_state.beginning_cs != expected_cs) { - BT_COMP_LOGE("Incompatible discarded events message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Incompatible discarded events message: " "unexpected beginning time: " "beginning-cs-val=%" PRIu64 ", " "expected-beginning-cs-val=%" PRIu64 ", " @@ -449,7 +462,8 @@ bt_component_class_sink_consume_method_status handle_packet_beginning_msg( * this case. */ if (stream->prev_packet_state.end_cs == UINT64_C(-1)) { - BT_COMP_LOGE("Incompatible discarded packets message " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Incompatible discarded packets message " "occurring before the stream's first packet: " "stream-id=%" PRIu64 ", stream-name=\"%s\", " "trace-name=\"%s\", path=\"%s/%s\"", @@ -464,7 +478,8 @@ bt_component_class_sink_consume_method_status handle_packet_beginning_msg( if (stream->discarded_packets_state.beginning_cs != stream->prev_packet_state.end_cs) { - BT_COMP_LOGE("Incompatible discarded packets message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Incompatible discarded packets message: " "unexpected beginning time: " "beginning-cs-val=%" PRIu64 ", " "expected-beginning-cs-val=%" PRIu64 ", " @@ -485,7 +500,8 @@ bt_component_class_sink_consume_method_status handle_packet_beginning_msg( if (stream->discarded_packets_state.end_cs != expected_end_cs) { - BT_COMP_LOGE("Incompatible discarded packets message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Incompatible discarded packets message: " "unexpected end time: " "end-cs-val=%" PRIu64 ", " "expected-end-cs-val=%" PRIu64 ", " @@ -513,6 +529,8 @@ bt_component_class_sink_consume_method_status handle_packet_beginning_msg( ret = fs_sink_stream_open_packet(stream, cs, ir_packet); if (ret) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to open packet."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -536,6 +554,8 @@ bt_component_class_sink_consume_method_status handle_packet_end_msg( stream = borrow_stream(fs_sink, ir_stream); if (G_UNLIKELY(!stream)) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -575,7 +595,8 @@ bt_component_class_sink_consume_method_status handle_packet_end_msg( expected_cs = bt_clock_snapshot_get_value(cs); if (stream->discarded_events_state.end_cs != expected_cs) { - BT_COMP_LOGE("Incompatible discarded events message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Incompatible discarded events message: " "unexpected end time: " "end-cs-val=%" PRIu64 ", " "expected-end-cs-val=%" PRIu64 ", " @@ -595,6 +616,8 @@ bt_component_class_sink_consume_method_status handle_packet_end_msg( ret = fs_sink_stream_close_packet(stream, cs); if (ret) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to close packet."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -636,7 +659,8 @@ bt_component_class_sink_consume_method_status handle_stream_beginning_msg( if (!fs_sink->ignore_discarded_events && bt_stream_class_supports_discarded_events(ir_sc)) { - BT_COMP_LOGE("Unsupported stream: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Unsupported stream: " "stream does not support packets, " "but supports discarded events: " "stream-addr=%p, " @@ -656,7 +680,8 @@ bt_component_class_sink_consume_method_status handle_stream_beginning_msg( if (!fs_sink->ignore_discarded_events && bt_stream_class_discarded_events_have_default_clock_snapshots(ir_sc) && !packets_have_beginning_end_cs) { - BT_COMP_LOGE("Unsupported stream: discarded events have " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Unsupported stream: discarded events have " "default clock snapshots, but packets have no " "beginning and/or end default clock snapshots: " "stream-addr=%p, " @@ -676,7 +701,8 @@ bt_component_class_sink_consume_method_status handle_stream_beginning_msg( if (!fs_sink->ignore_discarded_packets && bt_stream_class_discarded_packets_have_default_clock_snapshots(ir_sc) && !packets_have_beginning_end_cs) { - BT_COMP_LOGE("Unsupported stream: discarded packets have " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Unsupported stream: discarded packets have " "default clock snapshots, but packets have no " "beginning and/or end default clock snapshots: " "stream-addr=%p, " @@ -690,6 +716,8 @@ bt_component_class_sink_consume_method_status handle_stream_beginning_msg( stream = borrow_stream(fs_sink, ir_stream); if (!stream) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -717,6 +745,8 @@ bt_component_class_sink_consume_method_status handle_stream_end_msg( stream = borrow_stream(fs_sink, ir_stream); if (!stream) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -727,6 +757,8 @@ bt_component_class_sink_consume_method_status handle_stream_end_msg( int ret = fs_sink_stream_close_packet(stream, NULL); if (ret) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to close packet."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -764,6 +796,8 @@ bt_component_class_sink_consume_method_status handle_discarded_events_msg( stream = borrow_stream(fs_sink, ir_stream); if (!stream) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -781,7 +815,8 @@ bt_component_class_sink_consume_method_status handle_discarded_events_msg( } if (stream->discarded_events_state.in_range) { - BT_COMP_LOGE("Unsupported contiguous discarded events message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Unsupported contiguous discarded events message: " "stream-id=%" PRIu64 ", stream-name=\"%s\", " "trace-name=\"%s\", path=\"%s/%s\"", bt_stream_get_id(ir_stream), @@ -803,7 +838,8 @@ bt_component_class_sink_consume_method_status handle_discarded_events_msg( */ if (stream->packet_state.is_open && stream->sc->discarded_events_has_ts) { - BT_COMP_LOGE("Unsupported discarded events message with " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Unsupported discarded events message with " "default clock snapshots occurring within a packet: " "stream-id=%" PRIu64 ", stream-name=\"%s\", " "trace-name=\"%s\", path=\"%s/%s\"", @@ -872,6 +908,8 @@ bt_component_class_sink_consume_method_status handle_discarded_packets_msg( stream = borrow_stream(fs_sink, ir_stream); if (!stream) { + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to borrow stream."); status = BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_ERROR; goto end; } @@ -889,7 +927,8 @@ bt_component_class_sink_consume_method_status handle_discarded_packets_msg( } if (stream->discarded_packets_state.in_range) { - BT_COMP_LOGE("Unsupported contiguous discarded packets message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Unsupported contiguous discarded packets message: " "stream-id=%" PRIu64 ", stream-name=\"%s\", " "trace-name=\"%s\", path=\"%s/%s\"", bt_stream_get_id(ir_stream), @@ -979,6 +1018,8 @@ bt_component_class_sink_consume_method_status ctf_fs_sink_consume( fs_sink->upstream_iter, &msgs, &msg_count); if (next_status < 0) { status = (int) next_status; + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to get next message from upstream iterator."); goto end; } @@ -1031,7 +1072,8 @@ bt_component_class_sink_consume_method_status ctf_fs_sink_consume( BT_MESSAGE_PUT_REF_AND_RESET(msgs[i]); if (status != BT_COMPONENT_CLASS_SINK_CONSUME_METHOD_STATUS_OK) { - BT_COMP_LOGE("Failed to handle message: " + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to handle message: " "generated CTF traces could be incomplete: " "output-dir-path=\"%s\"", fs_sink->output_dir_path->str); @@ -1080,6 +1122,8 @@ ctf_fs_sink_graph_is_configured( self_comp, in_port_name), &fs_sink->upstream_iter); if (msg_iter_status != BT_MESSAGE_ITERATOR_CREATE_FROM_SINK_COMPONENT_STATUS_OK) { status = (int) msg_iter_status; + BT_COMP_LOGE_APPEND_CAUSE(fs_sink->self_comp, + "Failed to create upstream iterator."); goto end; } -- 2.34.1