5. Tracing

Printing information about a bitstream's content is extremely useful, particularly during development and debugging. Also, when two or more separate organizations are developing a specification and pursuing independent implementations, it is very important to have traces of the files generated by each tool for comparison and debugging purposes. One could of course insert verbatim printf statements for all parsable variables, but this can quickly get out of hand.

The translator can automatically generate tracing code and insert it in the get() method (using the command line option -t, or the pragma directive trace). This means that, without modifying your program or Flavor source in any way, you can automatically create detailed traces of your files.

The tracing output is directed to the standard output. Note that the translator does not print out the trace directly. Instead, it calls a quite simple trace function which is part of the run-time library. This means that you can very easily use your own tracing functions to customize both the output destination as well as formatting (more information is provided in the Run-Time Library). In the following we describe the trace output as provided by the standard run-time library implementation.

Let's first define a complex representation that will excercise all of the tracing features.

Trace.fl
class Base : int(2) id = 0 {
    bit(32) marker1 = 0xFFFF;
    bit(5)  marker2 = 0b1010.1;
    int(4)  length;
    char(8) data[length];
}

class Derived1 extends Base : int(2) id=1 {
   int(8) d1 = '1';
}

class Derived2 extends Base : int(2) id=2 {
   double(64) d2 = 2.1;
}

class Test {
   Base b[3];
}

The structure is as follows. Our Test class contains three objects of type Base. The Base objects, in turn, our polymorphic; any class out of Base, Derived1, or Derived2 can appear in their place. The Base object is composed of two markers having fixed values, followed by a length specification and a number of bytes equal to that length. The Derived1 and Derived2 objects each add a fixed variable, either an integer or a double.

We created a Test object where each of the three Base objects it contains is of type Base, Derived1, and Derived2 respectively, in that order. The data contained in variable data of each class is the name of the class in ASCII. The following is trace produced by calling the Test.get() method on that sample file.

Automatically Generated Trace from Test.fl 
   At Bit  Size    Value    Description
        0:                  begin Test
        0:                  processing Base b[0]
        0:                  begin Base
        0:    2          00 id (0)
        2:   32 00 00 FF FF marker1 (65535)
       34:    5          15 marker2 (21)
       39:    4          04 length (4)
       43:    8          42 data[0] (66)
       51:    8          61 data[1] (97)
       59:    8          73 data[2] (115)
       67:    8          65 data[3] (101)
       75:                  end Base
       75:                  processing Base b[1]
       75:                  begin Derived1
       75:    2          01 id (1)
       77:                  begin Base
       77:   32 00 00 FF FF marker1 (65535)
      109:    5          15 marker2 (21)
      114:    4          08 length (8)
      118:    8          44 data[0] (68)
      126:    8          65 data[1] (101)
      134:    8          72 data[2] (114)
      142:    8          69 data[3] (105)
      150:    8          76 data[4] (118)
      158:    8          65 data[5] (101)
      166:    8          64 data[6] (100)
      174:    8          31 data[7] (49)
      182:                  end Base
      182:    8          31 d1 (49)
      190:                  end Derived1
      190:                  processing Base b[2]
      190:                  begin Derived2
      190:    2          02 id (2)
      192:                  begin Base
      192:   32 00 00 FF FF marker1 (65535)
      224:    5          15 marker2 (21)
      229:    4          08 length (8)
      233:    8          44 data[0] (68)
      241:    8          65 data[1] (101)
      249:    8          72 data[2] (114)
      257:    8          69 data[3] (105)
      265:    8          76 data[4] (118)
      273:    8          65 data[5] (101)
      281:    8          64 data[6] (100)
      289:    8          32 data[7] (50)
      297:                  end Base
      297:   64         2.1 d2 (2.1)
      361:                  end Derived2
      361:                  end Test

As you can see, the trace output includes in each line: the bit position (starting from the beginning of the bitstream), the size of the quantity read, its value in hexadecimal (or floating point, if applicable), and a description. In some cases there is no length or value indication, meaning that no variable was parsed.

The first line indicates 'begin Test', signalling the entry in the get() method of Test. For all classes, the beginning and end of the get() method is signalled by 'begin' and 'end'. Then, we have the message 'processing Base b[0]'. This message is always printed before processing a variable of type class (i.e., before calling its own get() method), so that it is clear which member of the original class is being parsed. As you can see the 'processing Base b[0]' message is immediately followed by 'begin Base', signalled by the entry to Base::get(). The trace then contains each of the variables of Base, including their hexadecimal (3rd column) and actual decimal value (in parentheses, in the description text).

Moving forward, at bit position 75 we have the beginning of Test.b[1]. As this is actually a Derived1 object, the Derived1 get() function is called; as a result, the trace indicates begin Derived1. Note that the ID (id) is actually parsed by the derived class. Immediately afterwards the get() method of the Base class is called. When it ends, the Derived1 get() continues to parse the d1 variable. The situation is repeated for Test.b[2], starting at bit 190. Notice that in bit position 297 where the double variable d2 is traced, the 'Value' column indicates the actual floating point value instead of the raw bits. The trace ends at the end of the Test.get() method, which is signalled at bit 361 with the 'end Test' message.

In this particular case no error was detected. Bitstream syntax errors occur when a parsable variable has an expected value (e.g., the marker1 variable or the object ID id). When such an error is detected the trace output will include the string '(incorrect)' in the end of the description.

Also, a descriptive message is printed when the ID lookup for polymorphic classes fails. For example, at bit 190, and after the 'processing Base b[1]' message, if the ID didn't match any of Base or its derived classes the following message would be printed: 'ID b[1].id lookup failed'. In order to allow the code to continue, the base class type is used to create the new object. To demonstrate error handling, we ran the program in an arbitrary binary file so that it gets complete confused. Here is the output.

Trace Output from Test.fl on a Random Binary File 
   At Bit  Size    Value    Description
        0:                  begin Test
        0:                  processing Base b[0]
        0:                  begin Derived1
        0:    2          01 id (1)
        2:                  begin Base
        2:   32 35 A5 8D C9 marker1 (900042185) (incorrect)
       34:    5          17 marker2 (23) (incorrect)
       39:    4          0B length (11)
       43:    8          9B data[0] (-101)
       51:    8          7B data[1] (123)
       59:    8          33 data[2] (51)
       67:    8          A1 data[3] (-95)
       75:    8          02 data[4] (2)
       83:    8          19 data[5] (25)
       91:    8          7A data[6] (122)
       99:    8          19 data[7] (25)
      107:    8          59 data[8] (89)
      115:    8          59 data[9] (89)
      123:    8          03 data[10] (3)
      131:                  end Base
      131:    8          83 d1 (131) (incorrect)
      139:                  end Derived1
      139:                  processing Base b[1]
      139:                  begin Derived2
      139:    2          02 id (2)
      141:                  begin Base
      141:   32 4D EC EE 4C marker1 (1307373132) (incorrect)
      173:    5          05 marker2 (5) (incorrect)
      178:    4          0B length (11)
      182:    8          48 data[0] (72)
      190:    8          19 data[1] (25)
      198:    8          18 data[2] (24)
      206:    8          5D data[3] (93)
      214:    8          18 data[4] (24)
      222:    8          58 data[5] (88)
      230:    8          98 data[6] (-104)
      238:    8          5C data[7] (92)
      246:    8          D9 data[8] (-39)
      254:    8          48 data[9] (72)
      262:    8          0C data[10] (12)
      270:                  end Base
      270:   64 3.10235e+012 d2 (3.10235e+012) (incorrect)
      334:                  end Derived2
      334:                  processing Base b[2]
      334:    2          03 ID b[2].id lookup failed
      334:                  begin Base
      334:    2          03 id (3) (incorrect)
      336:   32 00 00 00 04 marker1 (4) (incorrect)
      368:    5          00 marker2 (0) (incorrect)
      373:    4          00 length (0)
      377:                  end Base
      377:                  end Test

As we can see, almost all the markers are incorrect. The IDs, because of their short length (2 bits), turn out to be correct except the one for b[2] at bit 334. The generated code uses the base class Base in order to be able to continue.