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 f0151331ae2fd707bd354c85b88d5480aff040f4..7a608c2576e0aa9498511f8296e5d1f6eabb6f78 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 d2e78345a7f17e878c0dfe5715f289b431d398c8..bafb225f1e4e5314e9eb9fa503ced0fdf1ceb6a6 100644 (file)
--- a/src/bin/lttng-relayd/main.c
+++ b/src/bin/lttng-relayd/main.c
@@ -2785,6 +2785,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,
@@ -2796,7 +2798,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 = "";
@@ -2882,7 +2883,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
@@ -2891,7 +2891,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;
@@ -2900,9 +2900,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,