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>
Thu, 14 Mar 2024 19:09:31 +0000 (15:09 -0400)
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.c
src/bin/lttng-relayd/stream.c
src/bin/lttng-relayd/stream.h

index 37bdfc2e5a2c5326ae0104523d6c4d3c2994a98a..0355cf9d91f06cf95c62a84efd61ccb07fa29f60 100644 (file)
@@ -1984,6 +1984,7 @@ 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 = NULL;
+       bool dispose_of_stream = false;
 
        assert(conn);
 
@@ -2014,6 +2015,9 @@ 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");
@@ -2022,11 +2026,7 @@ 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_sent to 0 until the
+                * Clear feature resets the metadata_received to 0 until the
                 * same metadata is received again.
                 */
                reply.status = htobe32(LTTNG_VIEWER_NO_NEW_METADATA);
@@ -2034,13 +2034,7 @@ 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. */
-                               viewer_stream_put(vstream);
-                       }
-                       vstream->stream->no_new_metadata_notified = true;
-               }
+               dispose_of_stream = vstream->metadata_sent > 0 && vstream->stream->closed;
                goto send_reply;
        }
 
@@ -2080,6 +2074,19 @@ 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;
@@ -2209,6 +2216,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) {
@@ -2233,7 +2242,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 6759bed17fd7a16d4703f3341eeaf9b2a1c0a390..8d5baa94b15e34fdd3e154311a43f604076efd96 100644 (file)
@@ -1105,9 +1105,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 c64b180451f6d1d05a97e87757d8fb73bb627634..d4a2e34304aa930b1273edc7b96097a7de90da38 100644 (file)
@@ -163,8 +163,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.03094 seconds and 4 git commands to generate.