Fix: relayd: failure to open chunk files concurrently with session clear

Observed issue
==============

When stress-testing ust clear with an active live viewer, we observe a
situation where the live viewer thread fails to open chunk files in
make_viewer_streams() when executed after the creation of the new trace
chunk at the beginning of the clear command:

  DBG3 - 16:19:50.923577790 [40834/40838]: Processing "RELAYD_CREATE_TRACE_CHUNK" command for socket 19 (in relay_process_control_command() at main.cpp:3262)
  DBG1 - 16:19:50.923577730 [40834/40841]: Relay viewer stream 225 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923600762 [40834/40838]: lttng_trace_chunk_rename_path from  to .tmp_old_chunk (in lttng_trace_chunk_rename_path_no_lock() at trace-chunk.cpp:759)
  DBG1 - 16:19:50.923627202 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_26" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923664685 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_26" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923706441 [40834/40841]: Relay viewer stream 226 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923727770 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_27" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923744686 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_27" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923773427 [40834/40841]: Relay viewer stream 227 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923803791 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_28" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923831589 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_28" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923865981 [40834/40841]: Relay viewer stream 228 not found (in viewer_stream_get_by_id() at viewer-stream.cpp:265)
  DBG1 - 16:19:50.923889329 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/index/my_chan-0_29.idx" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.923905142 [40834/40838]: Creating trace chunk: chunk_id = 1, creation time = 20211118-161950 (in lttng_trace_chunk_create() at trace-chunk.cpp:440)
  DBG1 - 16:19:50.923907984 [40834/40841]: Adding new file "ust/uid/0/64-bit/index/my_chan-0_29.idx" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  DBG1 - 16:19:50.923937804 [40834/40838]: Chunk name set to "20211118T161950+0000-1" (in lttng_trace_chunk_create() at trace-chunk.cpp:471)
  PERROR - 16:19:50.923984288 [40834/40841]: Failed to open fs handle to ust/uid/0/64-bit/index/my_chan-0_29.idx, open() returned: No such file or directory (in fd_tracker_open_fs_handle() at fd-tracker.cpp:548)
  DBG1 - 16:19:50.924050763 [40834/40841]: Opening trace chunk file "ust/uid/0/64-bit/my_chan-0_29" (in _lttng_trace_chunk_open_fs_handle_locked() at trace-chunk.cpp:1359)
  DBG1 - 16:19:50.924074480 [40834/40841]: Adding new file "ust/uid/0/64-bit/my_chan-0_29" to trace chunk "(unnamed)" (in lttng_trace_chunk_add_file() at trace-chunk.cpp:1309)
  PERROR - 16:19:50.924094720 [40834/40841]: Failed to open fs handle to ust/uid/0/64-bit/my_chan-0_29, open() returned: No such file or directory (in fd_tracker_open_fs_handle() at fd-tracker.cpp:548)
  DBG1 - 16:19:50.924193679 [40834/40841]: Viewer connection closed with 23 (in thread_worker() at live.cpp:2542)
  DBG1 - 16:19:50.924227482 [40834/40838]: Attempting to publish trace chunk: sessiond {34038782-6f74-4b2d-801e-752cf3d8885e}, session_id = 7, chunk_id = 1 (in sessiond_trace_chunk_registry_publish_chunk() at sessiond-trace-chunks.cpp:385)
  DBG1 - 16:19:50.924312916 [40834/40838]: Reset communication state of relay connection (fd = 19) (in connection_reset_protocol_state() at connection.cpp:82)
  DBG3 - 16:19:50.924350200 [40834/40838]: Relayd worker thread polling... (in relay_thread_worker() at main.cpp:3833)
  DBG3 - 16:19:50.924365222 [40834/40841]: Relayd live viewer worker thread polling... (in thread_worker() at live.cpp:2456)
  DBG1 - 16:19:50.926718319 [40834/40838]: Done receiving control command header: fd = 19, cmd = 18, cmd_version = 0, payload size = 532 bytes (in relay_process_control_receive_header() at main.cpp:3422)
  DBG3 - 16:19:50.926755574 [40834/40838]: Relayd worker thread polling... (in relay_thread_worker() at main.cpp:3833)
  DBG1 - 16:19:50.926787638 [40834/40838]: Done receiving control command payload: fd = 19, payload size = 532 bytes (in relay_process_control_receive_payload() at main.cpp:3339)
  DBG3 - 16:19:50.926811247 [40834/40838]: Processing "RELAYD_ROTATE_STREAMS" command for socket 19 (in relay_process_control_command() at main.cpp:3258)

Cause
=====

This is caused by relay_create_trace_chunk() using
lttng_trace_chunk_rename_path() to move away each trace subdirectory
into the subdirectory .tmp_old_chunk, and making this the new top-level
chunk directory (temporarily). This is a temporary state which will be
resorbed on relay_close_trace_chunk(), moving back the top-level chunk
directory to its original place.

Attempts to open chunk files from the prior chunk may result in failures,
because the chunk lock protecting the chunk rename operation only
protects the chunk owned by the relay thread, not its copy(ies) owned by
the live viewer thread.

This intermediate state should _not_ be observed by the live viewer
thread. The session ongoing rotation state should prevent the live
viewer threads from observing this.

Solution
========

Set the ongoing rotation state in relay_create_trace_chunk() earlier:
before invoking lttng_trace_chunk_rename_path(). Also ensure that the
session ongoing rotation state is protected by the session lock.

On the live thread side, introduce use of the session ongoing rotation
state in viewer_get_new_streams() and viewer_attach_session() to
effectively skip creation of the viewer streams if a session has a
rotation ongoing.

Viewers are expected to deal with the LTTNG_VIEWER_NEW_STREAMS_NO_NEW
reply (or handle the fact that no streams are currently available) and
try again later.

Both Babeltrace 2.0 and Babeltrace 1.5 appear to handle those replies
correctly.

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

None.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I3ad8d59dff2994bfb62efa02a620f3c0ffbb5e3b

diff --git a/src/bin/lttng-relayd/live.c b/src/bin/lttng-relayd/live.c
index 3eadbb1084da34ec07db25ceadae6a4fff4d759d..5365e17a78b6549641abfc5a123cd292e1f4d1fb 100644 (file)
--- a/src/bin/lttng-relayd/live.c
+++ b/src/bin/lttng-relayd/live.c
@@ -1165,6 +1165,16 @@ int viewer_get_new_streams(struct relay_connection *conn)
         * the viewer's point of view.
         */
        pthread_mutex_lock(&session->lock);
+       /*
+        * If a session rotation is ongoing, do not attempt to open any
+        * stream, because the chunk can be in an intermediate state
+        * due to directory renaming.
+        */
+       if (session->ongoing_rotation) {
+               DBG("Relay session %" PRIu64 " rotation ongoing", session_id);
+               response.status = htobe32(LTTNG_VIEWER_NEW_STREAMS_NO_NEW);
+               goto send_reply_unlock;
+       }
        ret = make_viewer_streams(session,
                        conn->viewer_session,
                        LTTNG_VIEWER_SEEK_BEGINNING, &nb_total, &nb_unsent,
@@ -1305,6 +1315,17 @@ int viewer_attach_session(struct relay_connection *conn)
                goto send_reply;
        }
 
+       /*
+        * If a session rotation is ongoing, do not attempt to open any
+        * stream, because the chunk can be in an intermediate state
+        * due to directory renaming.
+        */
+       if (session->ongoing_rotation) {
+               DBG("Relay session %" PRIu64 " rotation ongoing", session_id);
+               send_streams = 0;
+               goto send_reply;
+       }
+
        ret = make_viewer_streams(session,
                        conn->viewer_session, seek_type,
                        &nb_streams, NULL, NULL, &closed);

diff --git a/src/bin/lttng-relayd/main.c b/src/bin/lttng-relayd/main.c
index cfb48359354c56ae6552106cf43a8b4f47ed56d1..4f7358e623b9dfee4899ffd1e9d46298d52ed41c 100644 (file)
--- a/src/bin/lttng-relayd/main.c
+++ b/src/bin/lttng-relayd/main.c
@@ -2786,6 +2786,8 @@ static int relay_create_trace_chunk(const struct lttcomm_relayd_hdr *recv_hdr,
        msg->creation_timestamp = be64toh(msg->creation_timestamp);
        msg->override_name_length = be32toh(msg->override_name_length);
 
+       pthread_mutex_lock(&conn->session->lock);
+       session->ongoing_rotation = true;
        if (session->current_trace_chunk &&
                        !lttng_trace_chunk_get_name_overridden(session->current_trace_chunk)) {
                chunk_status = lttng_trace_chunk_rename_path(session->current_trace_chunk,
@@ -2797,7 +2799,6 @@ static int relay_create_trace_chunk(const struct lttcomm_relayd_hdr *recv_hdr,
                        goto end;
                }
        }
-       session->ongoing_rotation = true;
        if (!session->current_trace_chunk) {
                if (!session->has_rotated) {
                        new_path = "";
@@ -2891,7 +2892,6 @@ static int relay_create_trace_chunk(const struct lttcomm_relayd_hdr *recv_hdr,
                goto end;
        }
 
-       pthread_mutex_lock(&conn->session->lock);
        if (conn->session->pending_closure_trace_chunk) {
                /*
                 * Invalid; this means a second create_trace_chunk command was
@@ -2900,7 +2900,7 @@ static int relay_create_trace_chunk(const struct lttcomm_relayd_hdr *recv_hdr,
                ERR("Invalid trace chunk close command received; a trace chunk is already waiting for a trace chunk close command");
                reply_code = LTTNG_ERR_INVALID_PROTOCOL;
                ret = -1;
-               goto end_unlock_session;
+               goto end;
        }
        conn->session->pending_closure_trace_chunk =
                        conn->session->current_trace_chunk;
@@ -2909,9 +2909,8 @@ static int relay_create_trace_chunk(const struct lttcomm_relayd_hdr *recv_hdr,
        if (!conn->session->pending_closure_trace_chunk) {
                session->ongoing_rotation = false;
        }
-end_unlock_session:
-       pthread_mutex_unlock(&conn->session->lock);
 end:
+       pthread_mutex_unlock(&conn->session->lock);
        reply.ret_code = htobe32((uint32_t) reply_code);
        send_ret = conn->sock->ops->sendmsg(conn->sock,
                        &reply,