From: Mathieu Desnoyers Date: Thu, 18 Nov 2021 20:22:39 +0000 (-0500) Subject: Fix: relayd: failure to open chunk files concurrently with session clear X-Git-Url: http://drtracing.org/?a=commitdiff_plain;h=8433d9169dcae9f9c5896492b60aae6d43e2d058;p=lttng-tools.git 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 Signed-off-by: Jérémie Galarneau Change-Id: I3ad8d59dff2994bfb62efa02a620f3c0ffbb5e3b --- diff --git a/src/bin/lttng-relayd/live.c b/src/bin/lttng-relayd/live.c index 3eadbb108..5365e17a7 100644 --- 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 cfb483593..4f7358e62 100644 --- 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,