Tests: src.ctf.lttng-live: stream creation while trace is inactive

Add a test case to exercise the case where streams are created in the
context of a live viewer session while all of its currently-known
streams are inactive.

A full description of the underlying problem is provided in the "Fix:
src.ctf.lttng-live: expect NEW_STREAM/METADATA for inactive streams"
change description.

In essence, when consuming an LTTng live session configured to use
per-PID buffers, a known bug caused Babeltrace to ignore new streams
from an application (A) if all existing streams (existing applications)
were inactive. This led to a user experience akin to a "hang" if they
were expecting events emited by 'A'.

The test replicates this issue by:
  1. Starting an initial trace (T1) with one data stream emitting events
     for a fixed duration, followed by live beacons (triggering inactivity
     messages) for the rest of the duration of the test.
  2. Introducing a second trace (T2) with one data stream while the first
     trace only provides live beacons.
  3. Ensuring messages of T1 and T2 are visible and suitably interleaved.

When running the test against without the fix, Babeltrace fails to
receive new streams when only live beacons are provided, due to an
unchecked 'NEW_STREAMS' flag.

Moreover, once T1 ends (after providing its last inactivity beacon),
the lttng-live component falls in its 'idle' state where it keeps asking
for new streams (see lttng-live.cpp:1573) until the session is torn down
by the server.

Since new streams are available, the server will provide new streams
in response to the first `LTTNG_VIEWER_GET_NEW_STREAMS` command.
However, the first index provided for T2's data stream occurs _before_
the last "live beacon" that was received on T1's behalf.

This causes an internal sanity check to fail with the following error:
  01-18 15:08:39.743 153627 153627 E PLUGIN/SRC.CTF.LTTNG-LIVE handle_late_message@plugins/ctf/lttng-live/lttng-live.cpp:1141 [lttng-live] Invalid live stream state: have a late message when no inactivity message was ever sent for that stream.

With the fix applied, the test succeeds in showing the two traces'
messages interleaved in the expected order.

Change-Id: If40161edfdbefee6189ef63041b0f967493f1db9
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Reviewed-on: https://review.lttng.org/c/babeltrace/+/11675
Reviewed-by: Philippe Proulx <eeppeliteloop@gmail.com>
CI-Build: Philippe Proulx <eeppeliteloop@gmail.com>

diff --git a/tests/data/ctf-traces/live/new-streams/first-trace.mctf b/tests/data/ctf-traces/live/new-streams/first-trace.mctf
new file mode 100644 (file)
index 0000000..c3db828
--- /dev/null
+++ b/tests/data/ctf-traces/live/new-streams/first-trace.mctf
@@ -0,0 +1,90 @@
+--- metadata
+/* CTF 1.8 */
+
+typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
+
+trace {
+       major = 1;
+       minor = 8;
+       byte_order = le;
+};
+
+clock {
+       name = cycle_counter_test;
+       uuid = "5b59e7db-5e49-418a-9adf-e1adfdf571c4";
+       freq = 1000000000;
+};
+
+typealias integer { size = 8; align = 8; signed = false; map = clock.cycle_counter_test.value; } := cc_count_t;
+
+struct packet_context {
+       cc_count_t timestamp_begin;
+       cc_count_t timestamp_end;
+       uint8_t content_size;
+       uint8_t packet_size;
+};
+
+struct event_header {
+       uint8_t id;
+       cc_count_t timestamp;
+};
+
+stream {
+       event.header := struct event_header;
+       packet.context := struct packet_context;
+};
+
+event {
+       name = "first_trace_event";
+       id = 0;
+       fields := struct {
+               uint8_t value;
+       };
+};
+
+--- first_trace_stream_0
+!macro packet(ts_beg, event_id)
+  <beg>
+  [         ts_beg : 8] # timestamp begin
+  [     ts_beg + 1 : 8] # timestamp end
+  [8 * (end - beg) : 8] # content size in bits
+  [8 * (end - beg) : 8] # packet size in bits
+
+  [       event_id : 8] # event id
+  [         ts_beg : 8] # timestamp
+  [             42 : 8] # value field
+  <end>
+!end
+
+{ p1_s0_ts = 10 }
+{ p2_s0_ts = 20 }
+
+<p1_s0>
+m:packet(p1_s0_ts, 0)
+<p1_s0_end>
+
+<p2_s0>
+m:packet(p2_s0_ts, 0)
+<p2_s0_end>
+
+--- index/first_trace_stream_0.idx
+!be
+
+[0xC1F1DCC1 : 32] # Magic number
+[         1 : 32] # Major
+[         0 : 32] # Minor
+[        56 : 32] # Index entry size (56 bytes)
+
+# Packet 1
+!macro entry(beg_label, end_label, ts_beg)
+  [                  beg_label : 64] # offset in bytes
+  [8 * (end_label - beg_label) : 64] # total size in bits
+  [8 * (end_label - beg_label) : 64] # content size in bits
+  [                     ts_beg : 64] # timestamp begin
+  [                 ts_beg + 1 : 64] # timestamp end
+  [                          0 : 64] # events discarded
+  [                          0 : 64] # stream class id
+!end
+
+m:entry(p1_s0, p1_s0_end, p1_s0_ts)
+m:entry(p2_s0, p2_s0_end, p2_s0_ts)

diff --git a/tests/data/ctf-traces/live/new-streams/second-trace.mctf b/tests/data/ctf-traces/live/new-streams/second-trace.mctf
new file mode 100644 (file)
index 0000000..969e0be
--- /dev/null
+++ b/tests/data/ctf-traces/live/new-streams/second-trace.mctf
@@ -0,0 +1,90 @@
+--- metadata
+/* CTF 1.8 */
+
+typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
+
+trace {
+       major = 1;
+       minor = 8;
+       byte_order = le;
+};
+
+clock {
+       name = cycle_counter_test;
+       uuid = "5b59e7db-5e49-418a-9adf-e1adfdf571c4";
+       freq = 1000000000;
+};
+
+typealias integer { size = 8; align = 8; signed = false; map = clock.cycle_counter_test.value; } := cc_count_t;
+
+struct packet_context {
+       cc_count_t timestamp_begin;
+       cc_count_t timestamp_end;
+       uint8_t content_size;
+       uint8_t packet_size;
+};
+
+struct event_header {
+       uint8_t id;
+       cc_count_t timestamp;
+};
+
+stream {
+       event.header := struct event_header;
+       packet.context := struct packet_context;
+};
+
+event {
+       name = "second_trace_event";
+       id = 0;
+       fields := struct {
+               uint8_t value;
+       };
+};
+
+--- second_trace_stream_0
+!macro packet(ts_beg, event_id)
+  <beg>
+  [         ts_beg : 8] # timestamp begin
+  [     ts_beg + 1 : 8] # timestamp end
+  [8 * (end - beg) : 8] # content size in bits
+  [8 * (end - beg) : 8] # packet size in bits
+
+  [       event_id : 8] # event id
+  [         ts_beg : 8] # timestamp
+  [            123 : 8] # value field
+  <end>
+!end
+
+{ p1_s0_ts = 110 }
+{ p2_s0_ts = 120 }
+
+<p1_s0>
+m:packet(p1_s0_ts, 0)
+<p1_s0_end>
+
+<p2_s0>
+m:packet(p2_s0_ts, 0)
+<p2_s0_end>
+
+--- index/second_trace_stream_0.idx
+!be
+
+[0xC1F1DCC1 : 32] # Magic number
+[         1 : 32] # Major
+[         0 : 32] # Minor
+[        56 : 32] # Index entry size (56 bytes)
+
+# Packet 1
+!macro entry(beg_label, end_label, ts_beg)
+  [                  beg_label : 64] # offset in bytes
+  [8 * (end_label - beg_label) : 64] # total size in bits
+  [8 * (end_label - beg_label) : 64] # content size in bits
+  [                     ts_beg : 64] # timestamp begin
+  [                 ts_beg + 1 : 64] # timestamp end
+  [                          0 : 64] # events discarded
+  [                          0 : 64] # stream class id
+!end
+
+m:entry(p1_s0, p1_s0_end, p1_s0_ts)
+m:entry(p2_s0, p2_s0_end, p2_s0_ts)

diff --git a/tests/data/plugins/src.ctf.lttng-live/new-streams.expect b/tests/data/plugins/src.ctf.lttng-live/new-streams.expect
new file mode 100644 (file)
index 0000000..b77c326
--- /dev/null
+++ b/tests/data/plugins/src.ctf.lttng-live/new-streams.expect
@@ -0,0 +1,181 @@
+Trace class:
+  Stream class (ID 0):
+    Supports packets: Yes
+    Packets have beginning default clock snapshot: Yes
+    Packets have end default clock snapshot: Yes
+    Supports discarded events: No
+    Supports discarded packets: No
+    Default clock class:
+      Name: cycle_counter_test
+      Frequency (Hz): 1,000,000,000
+      Precision (cycles): 0
+      Offset (s): 0
+      Offset (cycles): 0
+      Origin is Unix epoch: No
+      UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+    Event class `first_trace_event` (ID 0):
+      Payload field class: Structure (1 member):
+        value: Unsigned integer (8-bit, Base 10)
+
+[Unknown]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Stream beginning:
+  Name: stream-1
+  Trace:
+    Stream (ID 1, Class ID 0)
+
+[10 cycles, 10 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Packet beginning
+
+[10 cycles, 10 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Event `first_trace_event` (Class ID 0):
+  Payload:
+    value: 42
+
+[11 cycles, 11 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Packet end
+
+[20 cycles, 20 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Packet beginning
+
+[20 cycles, 20 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Event `first_trace_event` (Class ID 0):
+  Payload:
+    value: 42
+
+[21 cycles, 21 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Packet end
+
+[40 cycles, 40 ns from origin]
+Message iterator inactivity:
+  Clock class:
+    Name: cycle_counter_test
+    Frequency (Hz): 1,000,000,000
+    Precision (cycles): 0
+    Offset (s): 0
+    Offset (cycles): 0
+    Origin is Unix epoch: No
+    UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+
+[50 cycles, 50 ns from origin]
+Message iterator inactivity:
+  Clock class:
+    Name: cycle_counter_test
+    Frequency (Hz): 1,000,000,000
+    Precision (cycles): 0
+    Offset (s): 0
+    Offset (cycles): 0
+    Origin is Unix epoch: No
+    UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+
+Trace class:
+  Stream class (ID 0):
+    Supports packets: Yes
+    Packets have beginning default clock snapshot: Yes
+    Packets have end default clock snapshot: Yes
+    Supports discarded events: No
+    Supports discarded packets: No
+    Default clock class:
+      Name: cycle_counter_test
+      Frequency (Hz): 1,000,000,000
+      Precision (cycles): 0
+      Offset (s): 0
+      Offset (cycles): 0
+      Origin is Unix epoch: No
+      UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+    Event class `second_trace_event` (ID 0):
+      Payload field class: Structure (1 member):
+        value: Unsigned integer (8-bit, Base 10)
+
+[Unknown]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Stream beginning:
+  Name: stream-3
+  Trace:
+    Stream (ID 3, Class ID 0)
+
+[85 cycles, 85 ns from origin]
+Message iterator inactivity:
+  Clock class:
+    Name: cycle_counter_test
+    Frequency (Hz): 1,000,000,000
+    Precision (cycles): 0
+    Offset (s): 0
+    Offset (cycles): 0
+    Origin is Unix epoch: No
+    UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+
+[100 cycles, 100 ns from origin]
+Message iterator inactivity:
+  Clock class:
+    Name: cycle_counter_test
+    Frequency (Hz): 1,000,000,000
+    Precision (cycles): 0
+    Offset (s): 0
+    Offset (cycles): 0
+    Origin is Unix epoch: No
+    UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+
+[110 cycles, 110 ns from origin]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Packet beginning
+
+[110 cycles, 110 ns from origin]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Event `second_trace_event` (Class ID 0):
+  Payload:
+    value: 123
+
+[111 cycles, 111 ns from origin]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Packet end
+
+[120 cycles, 120 ns from origin]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Packet beginning
+
+[120 cycles, 120 ns from origin]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Event `second_trace_event` (Class ID 0):
+  Payload:
+    value: 123
+
+[120 cycles, 120 ns from origin]
+Message iterator inactivity:
+  Clock class:
+    Name: cycle_counter_test
+    Frequency (Hz): 1,000,000,000
+    Precision (cycles): 0
+    Offset (s): 0
+    Offset (cycles): 0
+    Origin is Unix epoch: No
+    UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+
+[121 cycles, 121 ns from origin]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Packet end
+
+[Unknown]
+{Trace 1, Stream class ID 0, Stream ID 3}
+Stream end
+
+[200 cycles, 200 ns from origin]
+Message iterator inactivity:
+  Clock class:
+    Name: cycle_counter_test
+    Frequency (Hz): 1,000,000,000
+    Precision (cycles): 0
+    Offset (s): 0
+    Offset (cycles): 0
+    Origin is Unix epoch: No
+    UUID: 5b59e7db-5e49-418a-9adf-e1adfdf571c4
+
+[Unknown]
+{Trace 0, Stream class ID 0, Stream ID 1}
+Stream end

diff --git a/tests/data/plugins/src.ctf.lttng-live/new-streams.json b/tests/data/plugins/src.ctf.lttng-live/new-streams.json
new file mode 100644 (file)
index 0000000..6cf4d10
--- /dev/null
+++ b/tests/data/plugins/src.ctf.lttng-live/new-streams.json
@@ -0,0 +1,22 @@
+[
+    {
+        "name": "new-streams",
+        "id": 0,
+        "hostname": "hostname",
+        "live-timer-freq": 1,
+        "client-count": 0,
+        "traces": [
+            {
+                "path": "first-trace",
+                "creation-timestamp": 0,
+                "beacons": {
+                    "first_trace_stream_0": [40, 50, 85, 100, 120, 200]
+                }
+            },
+            {
+                "path": "second-trace",
+                "creation-timestamp": 80
+            }
+        ]
+    }
+]

diff --git a/tests/plugins/src.ctf.lttng-live/test-live.sh b/tests/plugins/src.ctf.lttng-live/test-live.sh
index 4c904d2f524c1438f0063c48e552ef66ca8af1d5..6516120e74f3c8c51999a2e0c4a1519a0edfffe9 100755 (executable)
--- a/tests/plugins/src.ctf.lttng-live/test-live.sh
+++ b/tests/plugins/src.ctf.lttng-live/test-live.sh
@@ -393,7 +393,30 @@ test_stored_values() {
        rm -rf "$tmp_dir"
 }
 
-plan_tests 18
+test_live_new_stream_during_inactivity() {
+       # Announce a new stream while an existing stream is inactive.
+       # This requires the live consumer to check for new announced streams
+       # when it receives inactivity beacons.
+       local test_text="new stream announced while an existing stream is inactive"
+       local cli_args_template="-i lttng-live net://localhost:@PORT@/host/hostname/new-streams -c sink.text.details"
+       local server_args=("$test_data_dir/new-streams.json")
+       local expected_stdout="${test_data_dir}/new-streams.expect"
+       local expected_stderr="/dev/null"
+       local tmp_dir
+
+       tmp_dir=$(mktemp -d -t 'test-new-streams.XXXXXXX')
+
+       # Generate test trace.
+       bt_gen_mctf_trace "${trace_dir}/live/new-streams/first-trace.mctf" "$tmp_dir/first-trace"
+       bt_gen_mctf_trace "${trace_dir}/live/new-streams/second-trace.mctf" "$tmp_dir/second-trace"
+
+       run_test "$test_text" "$cli_args_template" "$expected_stdout" \
+               "$expected_stderr" "$tmp_dir" "${server_args[@]}"
+
+       rm -rf "$tmp_dir"
+}
+
+plan_tests 20
 
 test_list_sessions
 test_base
@@ -403,3 +426,4 @@ test_compare_to_ctf_fs
 test_inactivity_discarded_packet
 test_split_metadata
 test_stored_values
+test_live_new_stream_during_inactivity