Bug 561881 - File processing stopped when a packet with overlapping timestamps was encountered
Summary: File processing stopped when a packet with overlapping timestamps was encount...
Status: NEW
Alias: None
Product: Tracecompass
Classification: Tools
Component: CTF (show other bugs)
Version: 5.3.0   Edit
Hardware: Macintosh Mac OS X
: P3 normal
Target Milestone: ---   Edit
Assignee: Project Inbox CLA
QA Contact: Project Inbox CLA
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-04-07 16:06 EDT by Jim White CLA
Modified: 2020-04-15 17:11 EDT (History)
1 user (show)

See Also:


Attachments
working example (933 bytes, application/zip)
2020-04-07 16:06 EDT, Jim White CLA
no flags Details
broken example (615 bytes, application/zip)
2020-04-07 16:07 EDT, Jim White CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jim White CLA 2020-04-07 16:06:52 EDT
Created attachment 282376 [details]
working example

I have a CTF encoded trace with two packets, each with two events.  Packets are ordered in the file as pktA, pktB.
The timestamps in the packet header are such that pktB.begin < pktA.begin < pktA.end < pktB.end.  Given this data in a single input file, babeltrace1 will display it, babeltrace2 refuses, and TraceCompass refuses.  However if the packets are separated into separate files, both babeltrace2 and TraceCompass process it as expected.
Comment 1 Jim White CLA 2020-04-07 16:07:20 EDT
Created attachment 282377 [details]
broken example
Comment 2 Matthew Khouzam CLA 2020-04-15 16:58:20 EDT
Hi Jim, 

Thanks for opening a bug. Sorry about the delays... Surprisingly my workload went up thanks to human malware.

I looked at your example, it's very clear, thanks!

Trace Compass's CTF Parser reads packets with the assumption that they are sequential for a given file.

The rationale being in the spec:

https://diamon.org/ctf/#spec5
<quote>
3. Event stream

An event stream can be divided into contiguous event packets of variable size. An event packet can contain a certain amount of padding at the end. The stream header is repeated at the beginning of each event packet. The rationale for the event stream design choices is explained in Stream header rationale.
</quote>

I understood contiguous as temporally contiguous too within a file. This needs to be confirmed with the authors/maintainers of the CTF spec. But I suggest the mitigation you did will be the proposed solution.

Did you file the bug with babeltrace too? what was their response.
Comment 3 Jim White CLA 2020-04-15 17:11:04 EDT
The issue is filed under https://bugs.lttng.org/issues/1255 on the babeltrace side.

<copy/pasting the response>

In the CTF model, a clock's value is updated as fields mapped to that clock's value attribute are read. The resulting value of the clock is expected to be monotonically increasing. When an N-bit update would produce a smaller N-bit value, an N-bit overflow is assumed to have occurred. The exception is the timestamp_end field which updates a clock's value at the completion of the decoding of a packet.

Here, a compliant reader will assume that an overflow occurred between pktA.end and pktB.begin or, for that matter, any two updates which causes the N-bit value of the clock to be smaller than the previous N-bit value.

From the specification:

For a N-bit integer type referring to a clock, if the integer overflows compared to the N low order bits of the clock prior value found in the same stream, then it is assumed that one, and only one, overflow occurred.
Of course, this is legal, but only you know if this is the intended effect. Your traces all reference the clock value through 8-bit integers, but I am assuming this is only for the sake of the example.

The reason why splitting the traces in separate physical streams works is that the two physical streams will be heap-sorted to form a single logical stream. That logical stream will present the packets in the expected (pktB, pktA) order to the reader.

If the timestamps of the output of babeltrace 1.x are not monotonically increasing, it points to a bug in babeltrace 1.x.
As for Babeltrace 2, the assertion is not the way this should be handled.

The specification is mute on this, but historically the "timestamp_begin" and "timestamp_end" have been assumed to contain the complete clock value and not to be an N-bit update to the value. In that case, that would make the stream invalid if any event of the second packet occurs before the first packet's final event.

<end copy/paste>

My current understanding is that even though there doesn't appear to be an explicit concept of a "physical" vs "logical" file in the spec, the implementations are behaving as if this concept exists, which is fine.  I've implemented a post-processing script here to separate the data into individual files and that seems to keep everything working as expected.