Tests: ctf: add tracers timestamp quirks workaround test cases
authorFrancis Deslauriers <francis.deslauriers@efficios.com>
Fri, 21 Jun 2019 20:46:37 +0000 (16:46 -0400)
committerPhilippe Proulx <eeppeliteloop@gmail.com>
Fri, 16 Aug 2019 15:35:50 +0000 (11:35 -0400)
This commit adds test traces and test cases to cover the `src.ctf.fs`
workarounds used to support timestamp corner cases or bugs in the
tracers.

Note: I manually modified the test traces to contain problematic
timestamp values using an hex editor as if there would be created by an
affected tracer.

Test traces
===========
* `event-after-packet` lttng test trace
  This trace `event-after-packet` was modified manually to simulate the
  hard to reproduce `event-after-packet` LTTng tracers bug.

  When the bug occurs, the timestamp of the last event of a packet is larger than
  the `timestamp_end` of it's own packet. It makes it look like the event
  happened after the packet was closed which is non compliant with the CTF
  specification.

  To create a trace exhibiting this bug, the `timestamp_end` field of
  the last 2 packets was made one clock cycle smaller than the timestamp
  of the last event of the said packet.

  This bug was fixed in the follow versions of the LTTng tracers:
  - lttng-ust 2.11.0
  - lttng-module 2.11.0
  - lttng-module 2.10.10
  - lttng-module 2.9.13

* `lttng-crash` test trace
  This trace was modified manually to simulate a trace resulting from the
  lttng-crash utility.

  When extracting a trace using the lttng-crash utility the `timestamp_end` of
  some packets may be left uninitialized with the default value of 0.

  To create a trace exhibiting this behavior, the `timestamp_end` of the last
  three packets were set to 0.

  This is _not_ a bug and all LTTng tracers can produce such trace.

* `event-before-packet` barectf test trace
  This trace `event-before-packet` exhibits a barectf bug where the first
  event of the second packet has a timestamp smaller than the
  `timestamp_begin` field of its own packet.

  This bug was fixed in barectf tracer version 2.3.1.

Test cases
==========

* `trace-info` query
  - Add test case for `event-after-packet` LTTng quirk,
  - Add test case for `lttng-crash` workaround.

  Both of this test traces used in these test cases are based on the same
  trace and the end result on the `trace-info` query is the same. We use
  the same code for both test cases.

* Trace decoding
  -Add `test_succeed` cases for all three of the above test traces.

Signed-off-by: Francis Deslauriers <francis.deslauriers@efficios.com>
Change-Id: Icfdb8052aa2a88038e22ad6a58f391b6d8dbd3df
Reviewed-on: https://review.lttng.org/c/babeltrace/+/1542
Tested-by: jenkins <jenkins@lttng.org>
Reviewed-by: Philippe Proulx <eeppeliteloop@gmail.com>
tests/data/ctf-traces/succeed/barectf-event-before-packet/metadata [new file with mode: 0644]
tests/data/ctf-traces/succeed/barectf-event-before-packet/stream [new file with mode: 0644]
tests/data/ctf-traces/succeed/lttng-crash/chan_0 [new file with mode: 0644]
tests/data/ctf-traces/succeed/lttng-crash/metadata [new file with mode: 0644]
tests/data/ctf-traces/succeed/lttng-event-after-packet/chan_0 [new file with mode: 0644]
tests/data/ctf-traces/succeed/lttng-event-after-packet/metadata [new file with mode: 0644]
tests/data/plugins/src.ctf.fs/succeed/trace-barectf-event-before-packet.expect [new file with mode: 0644]
tests/data/plugins/src.ctf.fs/succeed/trace-lttng-crash.expect [new file with mode: 0644]
tests/data/plugins/src.ctf.fs/succeed/trace-lttng-event-after-packet.expect [new file with mode: 0644]
tests/plugins/src.ctf.fs/query/test_query_trace_info.py
tests/plugins/src.ctf.fs/succeed/test_succeed

diff --git a/tests/data/ctf-traces/succeed/barectf-event-before-packet/metadata b/tests/data/ctf-traces/succeed/barectf-event-before-packet/metadata
new file mode 100644 (file)
index 0000000..76e6080
--- /dev/null
@@ -0,0 +1,168 @@
+/* CTF 1.8 */
+
+/*
+ * The MIT License (MIT)
+ *
+ * Copyright (c) 2015-2016 Philippe Proulx <pproulx@efficios.com>
+ *
+ * Permission is hereby granted, free of charge, to any person obtaining a copy
+ * of this software and associated documentation files (the "Software"), to deal
+ * in the Software without restriction, including without limitation the rights
+ * to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+ * copies of the Software, and to permit persons to whom the Software is
+ * furnished to do so, subject to the following conditions:
+ *
+ * The above copyright notice and this permission notice shall be included in
+ * all copies or substantial portions of the Software.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+ * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+ * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+ * AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+ * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+ * OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+ * THE SOFTWARE.
+ *
+ * - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
+ *
+ * The following TSDL code was generated by barectf v2.3.0
+ * on 2019-06-21 11:00:09.758512.
+ *
+ * For more details, see <http://barectf.org>.
+ */
+
+trace {
+       major = 1;
+       minor = 8;
+       byte_order = le;
+       uuid = "437748de-9435-11e9-8353-5254007c6857";
+       packet.header := struct {
+               integer {
+                       size = 32;
+                       align = 32;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } magic;
+               integer {
+                       size = 8;
+                       align = 8;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } uuid[16];
+               integer {
+                       size = 8;
+                       align = 8;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } stream_id;
+       } align(1);
+};
+
+env {
+       domain = "bare";
+       tracer_name = "barectf";
+       tracer_major = 2;
+       tracer_minor = 3;
+       tracer_patch = 0;
+       barectf_gen_date = "2019-06-21T11:00:09.758481";
+};
+
+clock {
+       name = default;
+       freq = 1000000000;
+       offset_s = 1434072888;
+       offset = 0;
+       precision = 0;
+       absolute = false;
+};
+
+/* default */
+stream {
+       id = 0;
+       packet.context := struct {
+               integer {
+                       size = 64;
+                       align = 64;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+                       map = clock.default.value;
+               } timestamp_begin;
+               integer {
+                       size = 64;
+                       align = 64;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+                       map = clock.default.value;
+               } timestamp_end;
+               integer {
+                       size = 32;
+                       align = 32;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } packet_size;
+               integer {
+                       size = 32;
+                       align = 32;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } content_size;
+               integer {
+                       size = 32;
+                       align = 32;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } events_discarded;
+       } align(1);
+       event.header := struct {
+               integer {
+                       size = 64;
+                       align = 64;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+                       map = clock.default.value;
+               } timestamp;
+               integer {
+                       size = 16;
+                       align = 16;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } id;
+       } align(1);
+};
+
+event {
+       name = "simple_uint32";
+       id = 0;
+       stream_id = 0; /* default */
+       loglevel = 2; /* CRIT */
+       fields := struct {
+               integer {
+                       size = 32;
+                       align = 32;
+                       signed = false;
+                       byte_order = le;
+                       base = 10;
+                       encoding = none;
+               } value;
+       } align(1);
+};
diff --git a/tests/data/ctf-traces/succeed/barectf-event-before-packet/stream b/tests/data/ctf-traces/succeed/barectf-event-before-packet/stream
new file mode 100644 (file)
index 0000000..55f45f2
Binary files /dev/null and b/tests/data/ctf-traces/succeed/barectf-event-before-packet/stream differ
diff --git a/tests/data/ctf-traces/succeed/lttng-crash/chan_0 b/tests/data/ctf-traces/succeed/lttng-crash/chan_0
new file mode 100644 (file)
index 0000000..a570de8
Binary files /dev/null and b/tests/data/ctf-traces/succeed/lttng-crash/chan_0 differ
diff --git a/tests/data/ctf-traces/succeed/lttng-crash/metadata b/tests/data/ctf-traces/succeed/lttng-crash/metadata
new file mode 100644 (file)
index 0000000..0f329eb
--- /dev/null
@@ -0,0 +1,108 @@
+/* CTF 1.8 */
+
+typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
+typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
+typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
+typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
+typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
+typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
+typealias integer { size = 27; align = 1; signed = false; } := uint27_t;
+
+trace {
+       major = 1;
+       minor = 8;
+       uuid = "a7055065-938f-439c-818e-975c13b30be2";
+       byte_order = le;
+       packet.header := struct {
+               uint32_t magic;
+               uint8_t  uuid[16];
+               uint32_t stream_id;
+               uint64_t stream_instance_id;
+       };
+};
+
+env {
+       hostname = "raton";
+       domain = "ust";
+       tracer_name = "lttng-ust";
+       tracer_major = 2;
+       tracer_minor = 11;
+};
+
+clock {
+       name = "monotonic";
+       uuid = "4d76db72-e40f-409e-ba30-532d309d5048";
+       description = "Monotonic Clock";
+       freq = 1000000000; /* Frequency, in Hz */
+       /* clock value offset from Epoch is: offset * (1/freq) */
+       offset = 1565056443054742594;
+};
+
+typealias integer {
+       size = 27; align = 1; signed = false;
+       map = clock.monotonic.value;
+} := uint27_clock_monotonic_t;
+
+typealias integer {
+       size = 32; align = 8; signed = false;
+       map = clock.monotonic.value;
+} := uint32_clock_monotonic_t;
+
+typealias integer {
+       size = 64; align = 8; signed = false;
+       map = clock.monotonic.value;
+} := uint64_clock_monotonic_t;
+
+struct packet_context {
+       uint64_clock_monotonic_t timestamp_begin;
+       uint64_clock_monotonic_t timestamp_end;
+       uint64_t content_size;
+       uint64_t packet_size;
+       uint64_t packet_seq_num;
+       unsigned long events_discarded;
+       uint32_t cpu_id;
+};
+
+struct event_header_compact {
+       enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
+       variant <id> {
+               struct {
+                       uint27_clock_monotonic_t timestamp;
+               } compact;
+               struct {
+                       uint32_t id;
+                       uint64_clock_monotonic_t timestamp;
+               } extended;
+       } v;
+} align(8);
+
+struct event_header_large {
+       enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
+       variant <id> {
+               struct {
+                       uint32_clock_monotonic_t timestamp;
+               } compact;
+               struct {
+                       uint32_t id;
+                       uint64_clock_monotonic_t timestamp;
+               } extended;
+       } v;
+} align(8);
+
+stream {
+       id = 0;
+       event.header := struct event_header_large;
+       packet.context := struct packet_context;
+};
+
+event {
+       name = "my_app:current_temp";
+       id = 0;
+       stream_id = 0;
+       loglevel = 13;
+       fields := struct {
+               integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _temp;
+               string _status;
+       };
+};
+
diff --git a/tests/data/ctf-traces/succeed/lttng-event-after-packet/chan_0 b/tests/data/ctf-traces/succeed/lttng-event-after-packet/chan_0
new file mode 100644 (file)
index 0000000..fffcccd
Binary files /dev/null and b/tests/data/ctf-traces/succeed/lttng-event-after-packet/chan_0 differ
diff --git a/tests/data/ctf-traces/succeed/lttng-event-after-packet/metadata b/tests/data/ctf-traces/succeed/lttng-event-after-packet/metadata
new file mode 100644 (file)
index 0000000..3127cd5
--- /dev/null
@@ -0,0 +1,108 @@
+/* CTF 1.8 */
+
+typealias integer { size = 8; align = 8; signed = false; } := uint8_t;
+typealias integer { size = 16; align = 8; signed = false; } := uint16_t;
+typealias integer { size = 32; align = 8; signed = false; } := uint32_t;
+typealias integer { size = 64; align = 8; signed = false; } := uint64_t;
+typealias integer { size = 64; align = 8; signed = false; } := unsigned long;
+typealias integer { size = 5; align = 1; signed = false; } := uint5_t;
+typealias integer { size = 27; align = 1; signed = false; } := uint27_t;
+
+trace {
+       major = 1;
+       minor = 8;
+       uuid = "e8680f63-336b-4999-9b6b-080f1c1b9f7b";
+       byte_order = le;
+       packet.header := struct {
+               uint32_t magic;
+               uint8_t  uuid[16];
+               uint32_t stream_id;
+               uint64_t stream_instance_id;
+       };
+};
+
+env {
+       hostname = "raton";
+       domain = "ust";
+       tracer_name = "lttng-ust";
+       tracer_major = 2;
+       tracer_minor = 10;
+};
+
+clock {
+       name = "monotonic";
+       uuid = "4d76db72-e40f-409e-ba30-532d309d5048";
+       description = "Monotonic Clock";
+       freq = 1000000000; /* Frequency, in Hz */
+       /* clock value offset from Epoch is: offset * (1/freq) */
+       offset = 1565056443054742596;
+};
+
+typealias integer {
+       size = 27; align = 1; signed = false;
+       map = clock.monotonic.value;
+} := uint27_clock_monotonic_t;
+
+typealias integer {
+       size = 32; align = 8; signed = false;
+       map = clock.monotonic.value;
+} := uint32_clock_monotonic_t;
+
+typealias integer {
+       size = 64; align = 8; signed = false;
+       map = clock.monotonic.value;
+} := uint64_clock_monotonic_t;
+
+struct packet_context {
+       uint64_clock_monotonic_t timestamp_begin;
+       uint64_clock_monotonic_t timestamp_end;
+       uint64_t content_size;
+       uint64_t packet_size;
+       uint64_t packet_seq_num;
+       unsigned long events_discarded;
+       uint32_t cpu_id;
+};
+
+struct event_header_compact {
+       enum : uint5_t { compact = 0 ... 30, extended = 31 } id;
+       variant <id> {
+               struct {
+                       uint27_clock_monotonic_t timestamp;
+               } compact;
+               struct {
+                       uint32_t id;
+                       uint64_clock_monotonic_t timestamp;
+               } extended;
+       } v;
+} align(8);
+
+struct event_header_large {
+       enum : uint16_t { compact = 0 ... 65534, extended = 65535 } id;
+       variant <id> {
+               struct {
+                       uint32_clock_monotonic_t timestamp;
+               } compact;
+               struct {
+                       uint32_t id;
+                       uint64_clock_monotonic_t timestamp;
+               } extended;
+       } v;
+} align(8);
+
+stream {
+       id = 0;
+       event.header := struct event_header_large;
+       packet.context := struct packet_context;
+};
+
+event {
+       name = "my_app:current_temp";
+       id = 0;
+       stream_id = 0;
+       loglevel = 13;
+       fields := struct {
+               integer { size = 32; align = 8; signed = 1; encoding = none; base = 10; } _temp;
+               string _status;
+       };
+};
+
diff --git a/tests/data/plugins/src.ctf.fs/succeed/trace-barectf-event-before-packet.expect b/tests/data/plugins/src.ctf.fs/succeed/trace-barectf-event-before-packet.expect
new file mode 100644 (file)
index 0000000..e13461e
--- /dev/null
@@ -0,0 +1,65 @@
+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: Yes
+    Discarded events have default clock snapshots: Yes
+    Supports discarded packets: No
+    Default clock class:
+      Name: default
+      Frequency (Hz): 1,000,000,000
+      Precision (cycles): 0
+      Offset (s): 1,434,072,888
+      Offset (cycles): 0
+      Origin is Unix epoch: No
+    Event class `simple_uint32` (ID 0):
+      Log level: Critical
+      Payload field class: Structure (1 member):
+        value: Unsigned integer (32-bit, Base 10)
+
+[Unknown]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Stream beginning:
+  Trace:
+    UUID: 437748de-9435-11e9-8353-5254007c6857
+    Environment (6 entries):
+      barectf_gen_date: 2019-06-21T11:00:09.758481
+      domain: bare
+      tracer_major: 2
+      tracer_minor: 3
+      tracer_name: barectf
+      tracer_patch: 0
+    Stream (ID 0, Class ID 0)
+
+[1,048,932,916,574,076 cycles, 1,435,121,820,916,574,076 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Packet beginning:
+
+[1,048,932,916,580,091 cycles, 1,435,121,820,916,580,091 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Event `simple_uint32` (Class ID 0):
+  Payload:
+    value: 0
+
+[1,048,932,916,584,407 cycles, 1,435,121,820,916,584,407 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Packet end
+
+[1,048,932,916,605,259 cycles, 1,435,121,820,916,605,259 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Packet beginning:
+
+[1,048,932,916,605,259 cycles, 1,435,121,820,916,605,259 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Event `simple_uint32` (Class ID 0):
+  Payload:
+    value: 1500
+
+[1,048,932,916,609,657 cycles, 1,435,121,820,916,609,657 ns from origin]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Packet end
+
+[Unknown]
+{Trace 0, Stream class ID 0, Stream ID 0}
+Stream end
diff --git a/tests/data/plugins/src.ctf.fs/succeed/trace-lttng-crash.expect b/tests/data/plugins/src.ctf.fs/succeed/trace-lttng-crash.expect
new file mode 100644 (file)
index 0000000..1e15f68
--- /dev/null
@@ -0,0 +1,4 @@
+[835,286,238,469,473 1,565,891,729,293,212,067] {0 0 0} Packet end
+[835,286,238,584,858 1,565,891,729,293,327,452] {0 0 0} Packet end
+[835,286,238,743,462 1,565,891,729,293,486,056] {0 0 0} Packet end
+[835,286,238,783,931 1,565,891,729,293,526,525] {0 0 0} Packet end
diff --git a/tests/data/plugins/src.ctf.fs/succeed/trace-lttng-event-after-packet.expect b/tests/data/plugins/src.ctf.fs/succeed/trace-lttng-event-after-packet.expect
new file mode 100644 (file)
index 0000000..b623a9e
--- /dev/null
@@ -0,0 +1,2 @@
+[900,859,125,273,445 1,565,957,302,180,016,041] {0 0 0} Packet end
+[900,859,125,273,473 1,565,957,302,180,016,069] {0 0 0} Packet end
index 2d99d681086020f909d5ab0ab3800090518b42b8..5ecec1356d16640dfddcdb48d06a5b3059a5510a 100644 (file)
@@ -231,5 +231,38 @@ class QueryTraceInfoRangeTestCase(unittest.TestCase):
         self.assertRaises(KeyError, lambda: streams[0]['range-ns'])
 
 
+class QueryTraceInfoPacketTimestampQuirksTestCase(unittest.TestCase):
+    def setUp(self):
+        ctf = bt2.find_plugin('ctf')
+        self._fs = ctf.source_component_classes['fs']
+        self._path = os.path.join(test_ctf_traces_path, 'succeed')
+
+    def _test_lttng_quirks(self, trace_name):
+        res = bt2.QueryExecutor(
+            self._fs,
+            "babeltrace.trace-info",
+            {"inputs": [os.path.join(self._path, trace_name)]},
+        ).query()
+
+        self.assertEqual(len(res), 1)
+        return res[0]
+
+    def test_event_after_packet(self):
+        trace = self._test_lttng_quirks("lttng-event-after-packet")
+        streams = trace["streams"]
+        self.assertEqual(len(streams), 1)
+
+        self.assertEqual(streams[0]['range-ns']['begin'], 1565957300948091100)
+        self.assertEqual(streams[0]['range-ns']['end'], 1565957302180016069)
+
+    def test_lttng_crash(self):
+        trace = self._test_lttng_quirks("lttng-crash")
+        streams = trace["streams"]
+        self.assertEqual(len(streams), 1)
+
+        self.assertEqual(streams[0]['range-ns']['begin'], 1565891729288866738)
+        self.assertEqual(streams[0]['range-ns']['end'], 1565891729293526525)
+
+
 if __name__ == '__main__':
     unittest.main()
index a0e06d4446806210e09714b16af24f8ff5c9dd5d..16f07ad146fa6f3b6ee302ae257ff096c808f51a 100755 (executable)
@@ -58,8 +58,43 @@ test_ctf_single() {
        ok $? "Trace '$name' gives the expected output"
 }
 
-plan_tests 3
+test_packet_end() {
+       local name="$1"
+       local expected_stdout="$expect_dir/trace-$name.expect"
+       local ret=0
+       local ret_stdout
+       local ret_stderr
+       local details_comp=("-c" "sink.text.details")
+       local details_args=("-p" "with-trace-name=no,with-stream-name=no,with-metadata=no,compact=yes")
+       local temp_stdout_output_file="$(mktemp -t actual_stdout.XXXXXX)"
+       local temp_greped_stdout_output_file="$(mktemp -t greped_stdout.XXXXXX)"
+       local temp_stderr_output_file="$(mktemp -t actual_stderr.XXXXXX)"
+
+       bt_cli "$temp_stdout_output_file" "$temp_stderr_output_file" \
+               "$succeed_trace_dir/$name" "${details_comp[@]}" \
+               "${details_args[@]}"
+
+       "$BT_TESTS_GREP_BIN" "Packet end" "$temp_stdout_output_file" > "$temp_greped_stdout_output_file"
+
+       bt_diff "$expected_stdout" "$temp_greped_stdout_output_file"
+       ret_stdout=$?
+
+       bt_diff /dev/null "$temp_stderr_output_file"
+       ret_stderr=$?
+
+       if ((ret_stdout != 0 || ret_stderr != 0)); then
+               ret=1
+       fi
+
+       ok $ret "Trace '$name' gives the expected output"
+       rm -f "$temp_stdout_output_file" "$temp_stderr_output_file" "$temp_greped_stdout_output_file"
+}
+
+plan_tests 6
 
 test_ctf_gen_single simple
 test_ctf_single smalltrace
 test_ctf_single 2packets
+test_ctf_single barectf-event-before-packet
+test_packet_end lttng-event-after-packet
+test_packet_end lttng-crash
This page took 0.032096 seconds and 4 git commands to generate.