From: Mathieu Desnoyers Date: Tue, 16 Nov 2021 20:59:01 +0000 (-0500) Subject: Fix: relayd: live: erroneous message timestamp observed from live viewer X-Git-Url: https://git.lttng.org./?a=commitdiff_plain;h=7fb6d478a17b87805813b9409cb89903e55018ff;p=lttng-tools.git Fix: relayd: live: erroneous message timestamp observed from live viewer Observed issue ============== While running tests/regression/tools/clear/test_ust test in a loop we eventually witness the following error: # Test ust basic streaming live with viewer # Parameters: tracing_active=0, clear_twice=0, buffer_type=uid ok 425 - Create session 6jbcTSKUG7s2RIp5 with uri:net://localhost and opts: --live ok 426 - Enable channel chan for session 6jbcTSKUG7s2RIp5 ok 427 - Enable ust event tp:tptest for session 6jbcTSKUG7s2RIp5 ok 428 - Start tracing for session 6jbcTSKUG7s2RIp5 # Waiting for live trace at url: net://localhost ok 429 - Waiting for live trace at url: net://localhost # Waiting for live viewers on url: net://localhost ok 430 - Waiting for live viewers on url: net://localhost # Wait until viewer sees all 10 expected events ok 431 - Live viewer read 10 events, expect 10 ok 432 - Destroy session 6jbcTSKUG7s2RIp5 # Waiting for application to exit ok 433 - Wait for application to exit # Wait for viewer to exit 10-28 22:07:37.935 764967 764967 E PLUGIN/SRC.CTF.LTTNG-LIVE next_stream_iterator_for_trace@lttng-live.c:1222 [lttng-live] Message's timestamp is less than lttng-live's message iterator's last returned timestamp: lttng-live-msg-iter-addr=0x55fe45d4977 0, ts=1635458857116911882, last-msg-ts=1635458857123908033 10-28 22:07:37.937 764967 764967 E PLUGIN/SRC.CTF.LTTNG-LIVE lttng_live_msg_iter_next@lttng-live.c:1662 [lttng-live] Error preparing the next batch of messages: live-iter-status=LTTNG_LIVE_ITERATOR_STATUS_ERROR 10-28 22:07:37.937 764967 764967 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:861 Component input port message iterator's "next" method failed: iter-addr=0x55fe45d38c50, iter-upstream-comp-name="lttng-live", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="lttng-live", iter-upstream-comp-class-partial-descr="Connect to an LTTng relay daemon", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR 10-28 22:07:37.937 764967 764967 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next@muxer.c:452 [muxer] Upstream iterator's next method returned an error: status=ERROR 10-28 22:07:37.938 764967 764967 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters@muxer.c:986 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x55fe45d33640, muxer-upstream-msg-iter-wrap-addr=0x55fe45d3 af20 10-28 22:07:37.938 764967 764967 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next@muxer.c:1411 [muxer] Cannot get next message: comp-addr=0x55fe45d49cb0, muxer-comp-addr=0x55fe45d49d30, muxer-msg-iter-addr=0x55fe45d33640, msg-iter-addr=0x55fe45d38ae0, sta tus=ERROR 10-28 22:07:37.938 764967 764967 W LIB/MSG-ITER bt_message_iterator_next@iterator.c:861 Component input port message iterator's "next" method failed: iter-addr=0x55fe45d38ae0, iter-upstream-comp-name="muxer", iter-upstream-comp-log-level=WARNING, iter -upstream-comp-class-type=FILTER, iter-upstream-comp-class-name="muxer", iter-upstream-comp-class-partial-descr="Sort messages from multiple inpu", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="out", status=ERROR 10-28 22:07:37.938 764967 764967 W LIB/GRAPH consume_graph_sink@graph.c:469 Component's "consume" method failed: status=ERROR, comp-addr=0x55fe45d49550, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-c lass-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x55fe45d38460, comp-class-so-handle-path="/root/virtenv/usr/lib/babeltrace2/plugins/babeltrace-plugin-text.la", comp-input-port-count=1, comp-out put-port-count=0 10-28 22:07:37.938 764967 764967 E CLI cmd_run@babeltrace2.c:2547 Graph failed to complete successfully Cause ===== When doing the rotation associated with a clear, viewer_stream_sync_tracefile_array_tail aims at pushing forward the index_sent_seqcount for sessions in tracefile rotation mode to the oldest available seqcount (tail) for this stream. It does not take into consideration that the current index_sent_seqcount may already be passed that oldest available seqcount position, thus eventually re-emitting trace data. For sessions *not* in tracefile rotation mode (this is known because `tracefile_array_get_seq_tail()` returns -1ULL), this function erroneously resets the index_sent_seqcount to 0, thus also causing trace data to be re-emitted. Solution ======== Solve this by using the maximum between the current index_sent_seqcount and the tracefile array tail position as new position in viewer_stream_sync_tracefile_array_tail. Notes ===== This symptom is also observed without using the clear command, simply on destroy with a live viewer attached. This is caused by another issue (not addressed by this patch) which causes viewer_stream_rotate_to_trace_chunk to be sometimes invoked when streams are closed on destroy. Known drawbacks =============== None. Signed-off-by: Mathieu Desnoyers Signed-off-by: Jérémie Galarneau Change-Id: Ifb877d6e2bd94831ddf93077eac3cc968945d6f7 --- diff --git a/src/bin/lttng-relayd/viewer-stream.cpp b/src/bin/lttng-relayd/viewer-stream.cpp index 7a66fde5b..ca0be9a62 100644 --- a/src/bin/lttng-relayd/viewer-stream.cpp +++ b/src/bin/lttng-relayd/viewer-stream.cpp @@ -15,6 +15,7 @@ #include #include #include +#include #include "lttng-relayd.h" #include "viewer-stream.h" @@ -302,7 +303,15 @@ void viewer_stream_sync_tracefile_array_tail(struct relay_viewer_stream *vstream if (seq_tail == -1ULL) { seq_tail = 0; } - vstream->index_sent_seqcount = seq_tail; + + /* + * Move the index sent seqcount forward if it was lagging behind + * the new tail of the tracefile array. If the current + * index_sent_seqcount is already further than the tracefile + * array tail position, keep its current position. + */ + vstream->index_sent_seqcount = + std::max(seq_tail, vstream->index_sent_seqcount); } /*