From 8e03dac57df3ee78b8c7c78bfdec4dec5669741c Mon Sep 17 00:00:00 2001 From: Francis Deslauriers Date: Fri, 21 Jun 2019 16:46:37 -0400 Subject: [PATCH] Tests: ctf: add tracers timestamp quirks workaround test cases 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 Change-Id: Icfdb8052aa2a88038e22ad6a58f391b6d8dbd3df Reviewed-on: https://review.lttng.org/c/babeltrace/+/1542 Tested-by: jenkins Reviewed-by: Philippe Proulx --- .../barectf-event-before-packet/metadata | 168 ++++++++++++++++++ .../barectf-event-before-packet/stream | Bin 0 -> 144 bytes .../ctf-traces/succeed/lttng-crash/chan_0 | Bin 0 -> 16384 bytes .../ctf-traces/succeed/lttng-crash/metadata | 108 +++++++++++ .../succeed/lttng-event-after-packet/chan_0 | Bin 0 -> 8192 bytes .../succeed/lttng-event-after-packet/metadata | 108 +++++++++++ .../trace-barectf-event-before-packet.expect | 65 +++++++ .../succeed/trace-lttng-crash.expect | 4 + .../trace-lttng-event-after-packet.expect | 2 + .../src.ctf.fs/query/test_query_trace_info.py | 33 ++++ tests/plugins/src.ctf.fs/succeed/test_succeed | 37 +++- 11 files changed, 524 insertions(+), 1 deletion(-) create mode 100644 tests/data/ctf-traces/succeed/barectf-event-before-packet/metadata create mode 100644 tests/data/ctf-traces/succeed/barectf-event-before-packet/stream create mode 100644 tests/data/ctf-traces/succeed/lttng-crash/chan_0 create mode 100644 tests/data/ctf-traces/succeed/lttng-crash/metadata create mode 100644 tests/data/ctf-traces/succeed/lttng-event-after-packet/chan_0 create mode 100644 tests/data/ctf-traces/succeed/lttng-event-after-packet/metadata create mode 100644 tests/data/plugins/src.ctf.fs/succeed/trace-barectf-event-before-packet.expect create mode 100644 tests/data/plugins/src.ctf.fs/succeed/trace-lttng-crash.expect create mode 100644 tests/data/plugins/src.ctf.fs/succeed/trace-lttng-event-after-packet.expect 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 index 00000000..76e60809 --- /dev/null +++ b/tests/data/ctf-traces/succeed/barectf-event-before-packet/metadata @@ -0,0 +1,168 @@ +/* CTF 1.8 */ + +/* + * The MIT License (MIT) + * + * Copyright (c) 2015-2016 Philippe Proulx + * + * 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 . + */ + +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 index 0000000000000000000000000000000000000000..55f45f203299aa48e863d4782ea2f0a25b1f249c GIT binary patch literal 144 zcmX>o|L34{xyQXJrh+ey$!9aaVg0J-umkpKVy literal 0 HcmV?d00001 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 index 0000000000000000000000000000000000000000..a570de85ae269566080165ad53d43d14430fafd6 GIT binary patch literal 16384 zcmeI2|6k2_6vvabrI@UhAry_Fu)a_}D__#3Wg^jJcS?_1Dbb1zS=`mVpL;(QYo;l9>N!C5=Jx2IAVs2#5EtrQ@( zQ(v^+{wY!`a!?8m+GATfDFs10JWEgt_S)f6S9ESS3}u<(t`zLFJ5L*l)CxUOwVKf= zOUYP_eb5K3vwbn|96z*3k z#y+zeoiAFe6b5K-vbg7B#ro%?YSsl9yJkN+ zH!4DEhYn*qq!eT9X(bqY@<~igc?LC)Jcn?vaxCa4=doKV|3v1SE@JG=%V@2>hJC)| zI+n!u7BZJtW8Sj6$o!vLtanu%T30k+?6O8=p4Eib(fTU-`Ue=OXzS@_sG{Xykg}NuwfupOfMJ{J060X&kIB6pGTnchcmF=2cxiCvSwkuN6$uU zw-`+9{tsxqcL64LHVz9qQbgEULg(v}5Kc)(QFE4HVo$fo!nfT2U*7wl{^|4AiZ|~6 zEnWhzJ)c>@&3$+c!t-je&ra8&_4|+TByf9z&I9yBno4V1igd&&-WBQeEo~*zInvNt zq@&%yM5NO<+*G6^PH8UEA@y|!q_*1v6HDld)}`G<+B$mmz{KYCLU_FmR%}i`j6KZ` zncF#Hz4e?>77GEH|Luaz4-LWC3*E5ZlVu1`@W9y9N1-epUYJ;KZ*1gl{L}1!Y(&ZmJe=Y-o@2elAOCJYW{t+E~-cC z`W6itsZkBw~*SJYJ`<{(Yeokq}H|`zrY0zXr0!GlWArX zirQCSLo40wcQmvw*1xBr&F8FVdI0_0rHf`J;`7Hoh_akeZ<#Ixln3(AA}UAc~ql2;mGDj2%2gLyO4> zH+1eSL+2(QSkPKeteC-9>V#tNNtq@yTv^oVH*)+_mEKY@ { + 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 { + 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 index 0000000000000000000000000000000000000000..fffcccd831d33d3e029d49a424161f7eef6c9fe5 GIT binary patch literal 8192 zcmX>o|L5R~4E|)}Y|ojqvpM)>q~}*NAb}ZAb_N9-Gc%-2R-Xf+PcTCz8;}&CG5`Mu z38X@Gn1a}4sd**3iD@ONMY;uv$=RtTXj(?OqaiRF0;3@?8UmvsFd71*Aut*OqaiRF z0;3@?8UmvsFd70h41t3L`u_#cUVH<|{r|?%{yz=lZPe(|5Eu=C(GVC7fzc2c4S~@R W7!85Z5Eu=C(GVC7fzc2kB?JJWA~Z+< literal 0 HcmV?d00001 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 index 00000000..3127cd57 --- /dev/null +++ b/tests/data/ctf-traces/succeed/lttng-event-after-packet/metadata @@ -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 { + 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 { + 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 index 00000000..e13461e5 --- /dev/null +++ b/tests/data/plugins/src.ctf.fs/succeed/trace-barectf-event-before-packet.expect @@ -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 index 00000000..1e15f68a --- /dev/null +++ b/tests/data/plugins/src.ctf.fs/succeed/trace-lttng-crash.expect @@ -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 index 00000000..b623a9e2 --- /dev/null +++ b/tests/data/plugins/src.ctf.fs/succeed/trace-lttng-event-after-packet.expect @@ -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 diff --git a/tests/plugins/src.ctf.fs/query/test_query_trace_info.py b/tests/plugins/src.ctf.fs/query/test_query_trace_info.py index 2d99d681..5ecec135 100644 --- a/tests/plugins/src.ctf.fs/query/test_query_trace_info.py +++ b/tests/plugins/src.ctf.fs/query/test_query_trace_info.py @@ -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() diff --git a/tests/plugins/src.ctf.fs/succeed/test_succeed b/tests/plugins/src.ctf.fs/succeed/test_succeed index a0e06d44..16f07ad1 100755 --- a/tests/plugins/src.ctf.fs/succeed/test_succeed +++ b/tests/plugins/src.ctf.fs/succeed/test_succeed @@ -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 -- 2.34.1