Issue observed
==============
A `session clear` test occasionaly fails on the CI (very rarely, and
more often on PowerPC executors for some reason) with babeltrace
reporting that the live connection was closed by the remote side:
PASS: tools/clear/test_ust 276 - Waiting for live viewers on url: net://localhost
07-21 16:17:07.058 23855 23855 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_recv@viewer-connection.c:198 [lttng-live] Remote side has closed connection
07-21 16:17:07.058 23855 23855 E PLUGIN/SRC.CTF.LTTNG-LIVE/VIEWER lttng_live_session_get_new_streams@viewer-connection.c:1701 [lttng-live] Error receiving get new streams reply
07-21 16:17:07.058 23855 23855 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1665 [lttng-live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
07-21 16:17:07.058 23855 23855 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:864 Component input port message iterator's "next" method failed: iter-addr=0x1014d6a8, iter-upstream-comp-name="lttng-live", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
07-21 16:17:07.059 23855 23855 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:454 [muxer] Upstream iterator's next method returned an error: status=ERROR
07-21 16:17:07.059 23855 23855 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:991 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x1014d668, muxer-upstream-msg-iter-wrap-addr=0x1014e210
07-21 16:17:07.059 23855 23855 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1415 [muxer] Cannot get next message: comp-addr=0x1014cca8, muxer-comp-addr=0x1015afd8, muxer-msg-iter-addr=0x1014d668, msg-iter-addr=0x1014d598, status=ERROR
07-21 16:17:07.059 23855 23855 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:864 Component input port message iterator's "next" method failed: iter-addr=0x1014d598, iter-upstream-comp-name="muxer", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
07-21 16:17:07.059 23855 23855 W LIB/GRAPH consume_graph_sink@graph.c:473 Component's "consume" method failed: status=ERROR, comp-addr=0x1014d128, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=1, comp-class-so-handle-addr=0x10159dd8, comp-class-so-handle-path="/home/jenkins/workspace/lttng-tools_stable-2.12_portbuild/arch/powerpc/babeltrace_version/stable-2.0/build/std/conf/agents/liburcu_version/stable-0.12/test_type/base/deps/build/lib/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
07-21 16:17:07.059 23855 23855 E CLI cmd_run@babeltrace2.c:2548 Graph failed to complete successfully
ERROR: [Babeltrace CLI] (babeltrace2.c:2548)
Graph failed to complete successfully
CAUSED BY [libbabeltrace2] (graph.c:473)
Component's "consume" method failed: status=ERROR, comp-addr=0x1014d128,
comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK,
comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages
(`text` fo", comp-class-is-frozen=1, comp-class-so-handle-addr=0x10159dd8,
comp-class-so-handle-path="/home/jenkins/workspace/lttng-tools_stable-2.12_portbuild/arch/powerpc/babeltrace_version/stable-2.0/build/std/conf/agents/liburcu_version/stable-0.12/test_type/base/deps/build/lib/babeltrace2/plugins/babeltrace-plugin-text.so",
comp-input-port-count=1, comp-output-port-count=0
CAUSED BY [libbabeltrace2] (iterator.c:864)
Component input port message iterator's "next" method failed:
iter-addr=0x1014d598, iter-upstream-comp-name="muxer",
iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=FILTER,
iter-upstream-comp-class-name="muxer",
iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu",
iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:991)
Cannot validate muxer's upstream message iterator wrapper:
muxer-msg-iter-addr=0x1014d668, muxer-upstream-msg-iter-wrap-addr=0x1014e210
CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:454)
Upstream iterator's next method returned an error: status=ERROR
CAUSED BY [libbabeltrace2] (iterator.c:864)
Component input port message iterator's "next" method failed:
iter-addr=0x1014d6a8, iter-upstream-comp-name="lttng-live",
iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE,
iter-upstream-comp-class-name="lttng-live",
iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon",
iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR
CAUSED BY [lttng-live: 'source.ctf.lttng-live'] (lttng-live.c:1665)
Error preparing the next batch of messages:
live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR
CAUSED BY [lttng-live: 'source.ctf.lttng-live'] (viewer-connection.c:1701)
Error receiving get new streams reply
CAUSED BY [lttng-live: 'source.ctf.lttng-live'] (viewer-connection.c:198)
Remote side has closed connection
ok 277 - Clear session J7WXjh7fmMleTCfE
PASS: tools/clear/test_ust 277 - Clear session J7WXjh7fmMleTCfE
ok 278 - Clear session J7WXjh7fmMleTCfE
PASS: tools/clear/test_ust 278 - Clear session J7WXjh7fmMleTCfE
ok 279 - Stop lttng tracing for session J7WXjh7fmMleTCfE
PASS: tools/clear/test_ust 279 - Stop lttng tracing for session J7WXjh7fmMleTCfE
ok 280 - Destroy session J7WXjh7fmMleTCfE
PASS: tools/clear/test_ust 280 - Destroy session J7WXjh7fmMleTCfE
# Wait for viewer to exit
not ok 281 - Babeltrace succeeds
Cause
=====
Looking at the relay daemon logs, it appears that the live client
requests an enumeration of the available streams while a rotation is
ongoing (clear).
Ultimately, this results in the relay daemon attempting to open a
non-existing file:
PERROR - 16:33:59.
242388809 [734380/734387]: Failed to open fs handle to ust/uid/1000/64-bit/chan_0, open() returned: No such file or directory (in fd_tracker_open_fs_handle() at fd-tracker.c:550)
The logs indicate that this file existed at some point. However, it
was unlinked and its newest instance was created in a trace chunk
named "20200727T163359-0400-1".
This chunk name is a temporary name used until the original trace
chunk can be unlinked (cleared) and the newest can be moved in its
place.
The file is being opened as part of the creation of a viewer stream
when make_viewer_stream() fails to find it. This implies that, somehow,
an outdated trace chunk is being used to open the viewer stream's file.
The reason why is that make_viewer_stream is called with the
viewer session's current trace chunk. During a rotation, the use of the
viewer session's current trace chunk is touchy due to the way the
switch-over to a new chunk is handled.
How viewer session/stream trace chunks are rotated
--------------------------------------------------
The viewer polls the relay daemon for new data/metadata to consume using
the `GET_NEXT_INDEX` and `GET_METADATA` commands. Both commands will
indicate to the viewer that it should try again later if a rotation is
ongoing on the "side" of the relay session.
When a rotation is not ongoing, the relay compares the `id` of the
target viewer stream's trace chunk with the relay session's current
trace chunk. If those `id`s don't match, the viewer session's current
trace chunk is then updated to a copy of the relay session's trace
chunk. The viewer stream's files are then closed and re-opened in the
context of the viewer session's now-updated trace chunk.
While the live protocol allows `GET_NEXT_INDEX` and `GET_METADATA` to
communicate to the viewer that it should "retry" later, there is no such
provisions made for the paths that lead to the creation of the viewer
streams. This means viewer streams must be created even if a rotation is
ongoing.
Solution
========
If a rotation is ongoing at the moment of the creation of the viewer
streams, we wish to use a copy of the trace chunk being used by the
relay stream. This way, we can be sure that the streams' files exist.
It is okay for viewer streams to hold references to different copies of
the trace chunks since no user-visible actions are performed when the
reference to those chunks is released. This is different from relay
streams where the detection of the completion of a rotation is done when
the last relay stream releases its reference to a specific trace chunk
instance.
Known drawbacks
===============
None beyond a slight increase (temporary until the next rotation) in the
number of FDs used when a client connects during a session rotation.
Note
====
Since make_viewer_streams now acts on relay and viewer counterparts of
the session and stream objects, the various variables are prefixed with
`relay` and `viewer` to make the code easier to understand.
The locking period of the relay stream is extended to most of the
iteration in make_viewer_stream() rather than only in
viewer_stream_create(). As a result, callers of viewer_stream_create()
must hold the relay stream's lock.
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I3b9c52a57835134712eadba0f68f6a21e922356b
*
* Return 0 on success or else a negative value.
*/
-static int make_viewer_streams(struct relay_session *session,
- struct lttng_trace_chunk *viewer_trace_chunk,
+static int make_viewer_streams(struct relay_session *relay_session,
+ struct relay_viewer_session *viewer_session,
enum lttng_viewer_seek seek_t,
uint32_t *nb_total,
uint32_t *nb_unsent,
int ret;
struct lttng_ht_iter iter;
struct ctf_trace *ctf_trace;
+ struct relay_stream *relay_stream = NULL;
- assert(session);
- ASSERT_LOCKED(session->lock);
+ assert(relay_session);
+ ASSERT_LOCKED(relay_session->lock);
- if (!viewer_trace_chunk) {
+ if (!viewer_session->current_trace_chunk) {
ERR("Internal error: viewer session associated with session \"%s\" has a NULL trace chunk",
- session->session_name);
+ relay_session->session_name);
ret = -1;
goto error;
}
- if (session->connection_closed) {
+ if (relay_session->connection_closed) {
*closed = true;
}
* used for a the given session id only.
*/
rcu_read_lock();
- cds_lfht_for_each_entry(session->ctf_traces_ht->ht, &iter.iter, ctf_trace,
- node.node) {
+ cds_lfht_for_each_entry (relay_session->ctf_traces_ht->ht, &iter.iter,
+ ctf_trace, node.node) {
bool trace_has_metadata_stream = false;
- struct relay_stream *stream;
health_code_update();
* Iterate over all the streams of the trace to see if we have a
* metadata stream.
*/
- cds_list_for_each_entry_rcu(
- stream, &ctf_trace->stream_list, stream_node)
+ cds_list_for_each_entry_rcu(relay_stream,
+ &ctf_trace->stream_list, stream_node)
{
- if (stream->is_metadata) {
+ bool is_metadata_stream;
+
+ pthread_mutex_lock(&relay_stream->lock);
+ is_metadata_stream = relay_stream->is_metadata;
+ pthread_mutex_unlock(&relay_stream->lock);
+
+ if (is_metadata_stream) {
trace_has_metadata_stream = true;
break;
}
}
+ relay_stream = NULL;
+
/*
* If there is no metadata stream in this trace at the moment
* and we never sent one to the viewer, skip the trace. We
continue;
}
- cds_list_for_each_entry_rcu(stream, &ctf_trace->stream_list, stream_node) {
- struct relay_viewer_stream *vstream;
+ cds_list_for_each_entry_rcu(relay_stream,
+ &ctf_trace->stream_list, stream_node)
+ {
+ struct relay_viewer_stream *viewer_stream;
- if (!stream_get(stream)) {
+ if (!stream_get(relay_stream)) {
continue;
}
+
+ pthread_mutex_lock(&relay_stream->lock);
/*
* stream published is protected by the session lock.
*/
- if (!stream->published) {
+ if (!relay_stream->published) {
goto next;
}
- vstream = viewer_stream_get_by_id(stream->stream_handle);
- if (!vstream) {
+ viewer_stream = viewer_stream_get_by_id(
+ relay_stream->stream_handle);
+ if (!viewer_stream) {
+ struct lttng_trace_chunk *viewer_stream_trace_chunk;
+
/*
* Save that we sent the metadata stream to the
* viewer. So that we know what trace the viewer
* is aware of.
*/
- if (stream->is_metadata) {
- ctf_trace->metadata_stream_sent_to_viewer =
- true;
+ if (relay_stream->is_metadata) {
+ ctf_trace->metadata_stream_sent_to_viewer = true;
}
- vstream = viewer_stream_create(stream,
- viewer_trace_chunk, seek_t);
- if (!vstream) {
+
+ /*
+ * If a rotation is ongoing, use a copy of the
+ * relay stream's chunk to ensure the stream
+ * files exist.
+ *
+ * Otherwise, the viewer session's current trace
+ * chunk can be used safely.
+ */
+ if ((relay_stream->ongoing_rotation.is_set ||
+ relay_session->ongoing_rotation) &&
+ relay_stream->trace_chunk) {
+ viewer_stream_trace_chunk = lttng_trace_chunk_copy(
+ relay_stream->trace_chunk);
+ if (!viewer_stream_trace_chunk) {
+ ret = -1;
+ ctf_trace_put(ctf_trace);
+ goto error_unlock;
+ }
+ } else {
+ const bool reference_acquired = lttng_trace_chunk_get(
+ viewer_session->current_trace_chunk);
+
+ assert(reference_acquired);
+ viewer_stream_trace_chunk =
+ viewer_session->current_trace_chunk;
+ }
+
+ viewer_stream = viewer_stream_create(
+ relay_stream,
+ viewer_stream_trace_chunk,
+ seek_t);
+ lttng_trace_chunk_put(viewer_stream_trace_chunk);
+ viewer_stream_trace_chunk = NULL;
+ if (!viewer_stream) {
ret = -1;
ctf_trace_put(ctf_trace);
- stream_put(stream);
goto error_unlock;
}
* Ensure a self-reference is preserved even
* after we have put our local reference.
*/
- if (!viewer_stream_get(vstream)) {
+ if (!viewer_stream_get(viewer_stream)) {
ERR("Unable to get self-reference on viewer stream, logic error.");
abort();
}
} else {
- if (!vstream->sent_flag && nb_unsent) {
+ if (!viewer_stream->sent_flag && nb_unsent) {
/* Update number of unsent stream counter. */
(*nb_unsent)++;
}
}
/* Update number of total stream counter. */
if (nb_total) {
- if (stream->is_metadata) {
- if (!stream->closed ||
- stream->metadata_received > vstream->metadata_sent) {
+ if (relay_stream->is_metadata) {
+ if (!relay_stream->closed ||
+ relay_stream->metadata_received >
+ viewer_stream->metadata_sent) {
(*nb_total)++;
}
} else {
- if (!stream->closed ||
- !(((int64_t) (stream->prev_data_seq - stream->last_net_seq_num)) >= 0)) {
-
+ if (!relay_stream->closed ||
+ !(((int64_t)(relay_stream->prev_data_seq -
+ relay_stream->last_net_seq_num)) >=
+ 0)) {
(*nb_total)++;
}
}
}
/* Put local reference. */
- viewer_stream_put(vstream);
+ viewer_stream_put(viewer_stream);
next:
- stream_put(stream);
+ pthread_mutex_unlock(&relay_stream->lock);
+ stream_put(relay_stream);
}
+ relay_stream = NULL;
ctf_trace_put(ctf_trace);
}
error_unlock:
rcu_read_unlock();
error:
+ if (relay_stream) {
+ pthread_mutex_unlock(&relay_stream->lock);
+ stream_put(relay_stream);
+ }
+
return ret;
}
pthread_mutex_lock(&session->lock);
ret = make_viewer_streams(session,
- conn->viewer_session->current_trace_chunk,
+ conn->viewer_session,
LTTNG_VIEWER_SEEK_LAST, &nb_total, &nb_unsent,
&nb_created, &closed);
if (ret < 0) {
}
ret = make_viewer_streams(session,
- conn->viewer_session->current_trace_chunk, seek_type,
+ conn->viewer_session, seek_type,
&nb_streams, NULL, NULL, &closed);
if (ret < 0) {
goto end_put_session;
*/
struct cds_list_head session_list; /* RCU list. */
pthread_mutex_t session_list_lock; /* Protects list updates. */
- /* Once set, the current trace chunk of a viewer must not change. */
struct lttng_trace_chunk *current_trace_chunk;
};
viewer_stream_destroy(vstream);
}
+/* Relay stream's lock must be held by the caller. */
struct relay_viewer_stream *viewer_stream_create(struct relay_stream *stream,
- struct lttng_trace_chunk *viewer_trace_chunk,
+ struct lttng_trace_chunk *trace_chunk,
enum lttng_viewer_seek seek_t)
{
struct relay_viewer_stream *vstream = NULL;
- const bool acquired_reference = lttng_trace_chunk_get(
- viewer_trace_chunk);
+ const bool acquired_reference = lttng_trace_chunk_get(trace_chunk);
+ ASSERT_LOCKED(stream->lock);
if (!acquired_reference) {
goto error;
}
goto error;
}
- vstream->stream_file.trace_chunk = viewer_trace_chunk;
- viewer_trace_chunk = NULL;
+ vstream->stream_file.trace_chunk = trace_chunk;
+ trace_chunk = NULL;
vstream->path_name = lttng_strndup(stream->path_name, LTTNG_VIEWER_PATH_MAX);
if (vstream->path_name == NULL) {
PERROR("relay viewer path_name alloc");
}
vstream->stream = stream;
- pthread_mutex_lock(&stream->lock);
-
if (stream->is_metadata && stream->trace->viewer_metadata_stream) {
ERR("Cannot attach viewer metadata stream to trace (busy).");
goto error_unlock;
rcu_assign_pointer(stream->trace->viewer_metadata_stream,
vstream);
}
- pthread_mutex_unlock(&stream->lock);
/* Globally visible after the add unique. */
lttng_ht_node_init_u64(&vstream->stream_n, stream->stream_handle);
if (vstream) {
viewer_stream_destroy(vstream);
}
- if (viewer_trace_chunk && acquired_reference) {
- lttng_trace_chunk_put(viewer_trace_chunk);
+ if (trace_chunk && acquired_reference) {
+ lttng_trace_chunk_put(trace_chunk);
}
return NULL;
}
projects / lttng-tools.git / commitdiff
