[lttng-dev] [barectf] How to debug a malformed trace event?

[Yoann Farré]

Hello,

I'm new in the world of tracing. And I have a question about barectf and malformed trace event.

For the context, I use the tool Papyrus to build UML models and then generate C++ code. The code can be instrumented to generate CTF traces (with barectf) and follow some relevant model elements.

More precisely, I generated a trace and tried to read it with TraceCompass. The traces seems to contains a malformed event. Unfortunately it avoids to read the follow-up (if any).

[cid:image001.png at 01D7E2EF.6EEA7800]

I also tried to read the trace with babeltrace which clearly shows that there is a malformed event [1].

Can anyone give me some help to avoid generate malformed event / or to enable to read the follow-up of the trace ?

To be complete, I join the raw trace [2]. I can also provide the code which produces this trace if it has any kind of interest.

[1] error_babeltrace.txt
[2] ctftrace04.zip

Thanks for reading and your help.
Regards.

Yoann Farré.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20211126/f158d4c2/attachment-0001.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image001.png
Type: image/png
Size: 12217 bytes
Desc: image001.png
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20211126/f158d4c2/attachment-0001.png>
-------------- next part --------------
[13:24:51.848097200] (+0.000002300) op_starts_User_inform_the_driver_of_the_car_speed_00000: { instanceId = "User", value = 25.7674 }
[13:24:51.863064900] (+0.014967700) transition_Speed_ManagementBB_T4_00003: { instanceId = "Speed_ManagementBB" }
[13:24:51.863066400] (+0.000001500) op_starts_Speed_ManagementBB_accelerate_00008: { instanceId = "Speed_ManagementBB" }
[13:24:51.863069000] (+0.000002600) op_starts_Environment_send_car_acceleration_00001: { instanceId = "Environment", value = 0.85 }
11-26 13:32:19.933  6610  6610 E PLUGIN/CTF/MSG-ITER set_current_event_class at msg-iter.c:1282 [auto-disc-source-ctf-fs] No event class with ID of event class ID to use in stream class: msg-it-addr=0x187d3e0, stream-class-id=0, event-class-id=7011365079688245331, trace-class-addr=0x17c3710
11-26 13:32:19.933  6610  6610 E PLUGIN/CTF/MSG-ITER ctf_msg_iter_get_next_message at msg-iter.c:2899 [auto-disc-source-ctf-fs] Cannot handle state: msg-it-addr=0x187d3e0, state=AFTER_EVENT_HEADER
11-26 13:32:19.933  6610  6610 E PLUGIN/SRC.CTF.FS ctf_fs_iterator_next_one at fs.c:109 [auto-disc-source-ctf-fs] Failed to get next message from CTF message iterator.
11-26 13:32:19.933  6610  6610 W LIB/MSG-ITER bt_message_iterator_next at iterator.c:864 Component input port message iterator's "next" method failed: iter-addr=0x187d1f0, iter-upstream-comp-name="auto-disc-source-ctf-fs", iter-upstream-comp-log-level=WARNING, iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="fs", iter-upstream-comp-class-partial-descr="Read CTF traces from the file sy", iter-upstream-port-type=OUTPUT, iter-upstream-port-name="/home/cil4sys/Desktop/ctftrace03 | 0 | /home/cil4sys/Desktop/ctftrace03/stream", status=ERROR
11-26 13:32:19.933  6610  6610 E PLUGIN/FLT.UTILS.MUXER muxer_upstream_msg_iter_next at muxer.c:454 [muxer] Upstream iterator's next method returned an error: status=ERROR
11-26 13:32:19.933  6610  6610 E PLUGIN/FLT.UTILS.MUXER validate_muxer_upstream_msg_iters at muxer.c:991 [muxer] Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x187d1a0, muxer-upstream-msg-iter-wrap-addr=0x187d7b0
[13:24:51.878071400] (+0.015002400) op_starts_Speed_ManagementBB_the_car_speed_is_received_00010: { instanceId = "Speed_ManagementBB", value = 25.897 }
[13:24:51.878076100] (+0.000004700) op_starts_Speed_ManagementBB_the_driver_requests_to_accelerate_00009: { instanceId = "\e", coef = 3.53968e-199 }
11-26 13:32:19.933  6610  6610 E PLUGIN/FLT.UTILS.MUXER muxer_msg_iter_next at muxer.c:1415 [muxer] Cannot get next message: comp-addr=0x187c470, muxer-comp-addr=0x187c4f0, muxer-msg-iter-addr=0x187d1a0, msg-iter-addr=0x187d030, status=ERROR
11-26 13:32:19.933  6610  6610 W LIB/MSG-ITER bt_message_iterator_next at iterator.c:864 Component input port message iterator's "next" method failed: iter-addr=0x187d030, 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
11-26 13:32:19.934  6610  6610 W LIB/GRAPH consume_graph_sink at graph.c:473 Component's "consume" method failed: status=ERROR, comp-addr=0x187c670, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty", comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x17ced30, comp-class-so-handle-path="/usr/lib/x86_64-linux-gnu/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
11-26 13:32:19.934  6610  6610 E CLI cmd_run at babeltrace2.c:2548 Graph failed to complete successfully

ERROR:    [Babeltrace CLI] (babeltrace2.c:2548)
  Graph failed to complete successfully
CAUSED BY [libbabeltrace2] (graph.c:473)
  Component's "consume" method failed: status=ERROR, comp-addr=0x187c670, comp-name="pretty", comp-log-level=WARNING, comp-class-type=SINK, comp-class-name="pretty",
  comp-class-partial-descr="Pretty-print messages (`text` fo", comp-class-is-frozen=0, comp-class-so-handle-addr=0x17ced30,
  comp-class-so-handle-path="/usr/lib/x86_64-linux-gnu/babeltrace2/plugins/babeltrace-plugin-text.so", comp-input-port-count=1, comp-output-port-count=0
CAUSED BY [libbabeltrace2] (iterator.c:864)
  Component input port message iterator's "next" method failed: iter-addr=0x187d030, 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
CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:991)
  Cannot validate muxer's upstream message iterator wrapper: muxer-msg-iter-addr=0x187d1a0, muxer-upstream-msg-iter-wrap-addr=0x187d7b0
CAUSED BY [muxer: 'filter.utils.muxer'] (muxer.c:454)
  Upstream iterator's next method returned an error: status=ERROR
CAUSED BY [libbabeltrace2] (iterator.c:864)
  Component input port message iterator's "next" method failed: iter-addr=0x187d1f0, iter-upstream-comp-name="auto-disc-source-ctf-fs", iter-upstream-comp-log-level=WARNING,
  iter-upstream-comp-class-type=SOURCE, iter-upstream-comp-class-name="fs", iter-upstream-comp-class-partial-descr="Read CTF traces from the file sy", iter-upstream-port-type=OUTPUT,
  iter-upstream-port-name="/home/cil4sys/Desktop/ctftrace03 | 0 | /home/cil4sys/Desktop/ctftrace03/stream", status=ERROR
CAUSED BY [auto-disc-source-ctf-fs (/home/cil4sys/Desktop/ctftrace03 | 0 | /home/cil4sys/Desktop/ctftrace03/stream): 'source.ctf.fs'] (fs.c:109)
  Failed to get next message from CTF message iterator.
CAUSED BY [auto-disc-source-ctf-fs: 'source.ctf.fs'] (msg-iter.c:2899)
  Cannot handle state: msg-it-addr=0x187d3e0, state=AFTER_EVENT_HEADER
CAUSED BY [auto-disc-source-ctf-fs: 'source.ctf.fs'] (msg-iter.c:1282)
  No event class with ID of event class ID to use in stream class: msg-it-addr=0x187d3e0, stream-class-id=0, event-class-id=7011365079688245331, trace-class-addr=0x17c3710
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ctftrace04.zip
Type: application/x-zip-compressed
Size: 35482 bytes
Desc: ctftrace04.zip
URL: <https://lists.lttng.org/pipermail/lttng-dev/attachments/20211126/f158d4c2/attachment-0001.bin>