Fix: relayd: live: dispose of zombie viewer metadata stream
authorJérémie Galarneau <jeremie.galarneau@efficios.com>
Sat, 17 Feb 2024 13:57:47 +0000 (08:57 -0500)
committerJérémie Galarneau <jeremie.galarneau@efficios.com>
Fri, 1 Mar 2024 19:07:30 +0000 (14:07 -0500)
Issue observed
==============

In the CI, builds on SLES15SP5 frequently experience timeouts. From
prior inspections, there are hangs during
tests/regression/tools/clear/test_ust while waiting for babeltrace to
exit.

It is possible to reproduce the problem fairly easily:

  $ lttng create --live
  $ lttng enable-event --userspace --all
  $ lttng start

  # Launch an application that emits a couple of events
  $ ./my_app
  $ lttng stop

  # Clear the data, this eventually results in the deletion of all
  # trace files on the relay daemon's end.
  $ lttng clear

  # Attach to the live session from another terminal
  $ babeltrace -i lttng-live net://...

  # The 'destroy' command completes, but the viewer never exits.
  $ lttng destroy

Cause
=====

After the clear command completes, the relay daemon no longer has any
data to serve. We notice that the live client loops endlessly repeatably
sending GET_METADATA requests. In response, the relay daemon replies
with the NO_NEW_METADATA status.

In concrete terms, the viewer_get_metadata() function short-circuits to
send that reply when it sees that the metadata stream has no active
trace chunk (i.e., there are no backing files from which to read the
data at the moment).

This situation is not abnormal in itself: it is legitimate for a client
to wait for the metadata to become available again. For example, in the
reproducer above, it would be possible for the user to restart the
tracing (lttng start), which would create a new trace chunk and make the
metadata stream available. New events could also be emitted following
this restart.

However, when a session's connection is closed, there is no hope that
the metadata stream will ever transition back to an active trace chunk.

Solution
========

When the metadata stream has no active chunk and the corresponding
consumerd-side connection has been closed, there is no way the relay
daemon will be able to serve the metadata contents to the client.

As such, the viewer stream can be disposed-of since it will no longer be
of any use to the client. Since some client implementations expect at
least one GET_METADATA command to result in NO_NEW_METADATA, that status
code is initially returned.

Later, when the client emits a follow-up GET_METADATA request for that
same stream, it will receive an "error" status indicating that the
stream no longer exists. This situation is not treated as an error by
the clients. For instance, babeltrace2 will simply close the
corresponding trace and indicate it ended.

The 'no_new_metadata_notified' flag doesn't appear to be necessary to
implement the behaviour expected by the clients (seeing at least one
NO_NEW_METADATA status reply for every metadata stream). The
viewer_get_metadata() function is refactored a bit to drop the global
reference to the viewer metadata stream as it exits, while still
returning the NO_NEW_METADATA status code.

Known drawbacks
===============

None.

Note
====

The commit message of e8b269fa provides more details behind the
intention of the 'no_new_metadata_notified' flag.

Change-Id: Ib1b80148d7f214f7aed221d3559e479b69aedd82
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
src/bin/lttng-relayd/live.cpp
src/bin/lttng-relayd/stream.cpp
src/bin/lttng-relayd/stream.hpp

index 99037e417c0db58cd76e267383a9f3f7dc1bd068..f1f97f91748b9337c43636d2949cf77b187ed336 100644 (file)
@@ -2128,6 +2128,7 @@ static int viewer_get_metadata(struct relay_connection *conn)
        struct lttng_viewer_get_metadata request;
        struct lttng_viewer_metadata_packet reply;
        struct relay_viewer_stream *vstream = nullptr;
+       bool dispose_of_stream = false;
 
        LTTNG_ASSERT(conn);
 
@@ -2156,6 +2157,9 @@ static int viewer_get_metadata(struct relay_connection *conn)
                reply.status = htobe32(LTTNG_VIEWER_METADATA_ERR);
                goto send_reply;
        }
+
+       pthread_mutex_lock(&vstream->stream->trace->session->lock);
+       pthread_mutex_lock(&vstream->stream->trace->lock);
        pthread_mutex_lock(&vstream->stream->lock);
        if (!vstream->stream->is_metadata) {
                ERR("Invalid metadata stream");
@@ -2164,10 +2168,6 @@ static int viewer_get_metadata(struct relay_connection *conn)
 
        if (vstream->metadata_sent >= vstream->stream->metadata_received) {
                /*
-                * The live viewers expect to receive a NO_NEW_METADATA
-                * status before a stream disappears, otherwise they abort the
-                * entire live connection when receiving an error status.
-                *
                 * Clear feature resets the metadata_received to 0 until the
                 * same metadata is received again.
                 */
@@ -2176,20 +2176,7 @@ static int viewer_get_metadata(struct relay_connection *conn)
                 * The live viewer considers a closed 0 byte metadata stream as
                 * an error.
                 */
-               if (vstream->metadata_sent > 0) {
-                       if (vstream->stream->closed && vstream->stream->no_new_metadata_notified) {
-                               /*
-                                * Release ownership for the viewer metadata
-                                * stream. Note that this reference is the
-                                * viewer's reference. The vstream still exists
-                                * until the end of the function as
-                                * viewer_stream_get_by_id() took a reference.
-                                */
-                               viewer_stream_put(vstream);
-                       }
-
-                       vstream->stream->no_new_metadata_notified = true;
-               }
+               dispose_of_stream = vstream->metadata_sent > 0 && vstream->stream->closed;
                goto send_reply;
        }
 
@@ -2227,6 +2214,19 @@ static int viewer_get_metadata(struct relay_connection *conn)
        len = vstream->stream->metadata_received - vstream->metadata_sent;
 
        if (!vstream->stream_file.trace_chunk) {
+               if (vstream->stream->trace->session->connection_closed) {
+                       /*
+                        * If the connection is closed, there is no way for the metadata stream
+                        * to ever transition back to an active chunk. As such, signal to the viewer
+                        * that there is no new metadata available.
+                        *
+                        * The stream can be disposed-of. On the next execution of this command,
+                        * the relay daemon will reply with an error status since the stream can't
+                        * be found.
+                        */
+                       dispose_of_stream = true;
+               }
+
                reply.status = htobe32(LTTNG_VIEWER_NO_NEW_METADATA);
                len = 0;
                goto send_reply;
@@ -2357,6 +2357,8 @@ send_reply:
        health_code_update();
        if (vstream) {
                pthread_mutex_unlock(&vstream->stream->lock);
+               pthread_mutex_unlock(&vstream->stream->trace->lock);
+               pthread_mutex_unlock(&vstream->stream->trace->session->lock);
        }
        ret = send_response(conn->sock, &reply, sizeof(reply));
        if (ret < 0) {
@@ -2382,7 +2384,22 @@ end_free:
 end:
        if (vstream) {
                viewer_stream_put(vstream);
+               if (dispose_of_stream) {
+                       /*
+                        * Trigger the destruction of the viewer stream
+                        * by releasing its global reference.
+                        *
+                        * The live viewers expect to receive a NO_NEW_METADATA
+                        * status before a stream disappears, otherwise they abort the
+                        * entire live connection when receiving an error status.
+                        *
+                        * On the next query for this stream, an error will be reported to the
+                        * client.
+                        */
+                       viewer_stream_put(vstream);
+               }
        }
+
        return ret;
 }
 
index 94d5d6d177c6855a059dfba36333a24a57de9f36..a0935231d039280598ad538dfcaaa2f8189d3c27 100644 (file)
@@ -1109,9 +1109,6 @@ int stream_write(struct relay_stream *stream,
                recv_len = packet ? packet->size : 0;
                recv_len += padding_len;
                stream->metadata_received += recv_len;
-               if (recv_len) {
-                       stream->no_new_metadata_notified = false;
-               }
        }
 
        DBG("Wrote to %sstream %" PRIu64 ": data_length = %zu, padding_length = %zu",
index 44a89779421c94669944153bafc57e1d6ea3dbc5..a616e425aaa90df3ce28f23d971551f0a1473229 100644 (file)
@@ -162,8 +162,6 @@ struct relay_stream {
        struct cds_list_head recv_node;
        /* Protected by session lock. */
        bool published;
-       /* Notified viewer that no new metadata is available. */
-       bool no_new_metadata_notified;
        /*
         * Node of stream within global stream hash table.
         */
This page took 0.028754 seconds and 4 git commands to generate.