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 <mathieu.desnoyers@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Ifb877d6e2bd94831ddf93077eac3cc968945d6f7

diff --git a/src/bin/lttng-relayd/viewer-stream.c b/src/bin/lttng-relayd/viewer-stream.c
index 00616569ba0b147e7ce63181bcf82e21e84596c1..e49519a705483c4265a3b7d56a9a3b39641204d9 100644 (file)
--- a/src/bin/lttng-relayd/viewer-stream.c
+++ b/src/bin/lttng-relayd/viewer-stream.c
@@ -302,7 +302,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 = seq_tail > vstream->index_sent_seqcount ?
+                       seq_tail : vstream->index_sent_seqcount;
 }
 
 /*