[Enhancement]: make trace_fmt!() emit full file and line/column information

[hzeller]

The trace_fmt!() output recently improved by actually printing the file name and line number the trace is happening.

What is

But the output is still not as useful as it could

• it contains all kinds of timestamp information due to the inheritance from absl LOG(INFO), but that is not super-helpful: we're running a test and not a long-running server, so the exact microsecond something happened is just noise.
• The filename is not complete: only the basename is shown, not the full filename. This makes it hard for an IDE to map a test output back to the actual file it happened.
• Other internal log message by XLS are also emitted.

This is how things look now:

bazel build -c opt xls/dslx:interpreter_main && bazel-bin/xls/dslx/interpreter_main xls/examples/protobuf/varint_streaming_decode.x --alsologtostderr

I0611 19:46:37.793671      16 varint_streaming_decode.x:118] input_data=[0, 0, 0, 0, 0, 0, 0] input_len=0, do_input=0
I0611 19:46:37.793847      16 varint_streaming_decode.x:127] trace of last_terminator_idx: 2
I0611 19:46:37.793851      16 varint_streaming_decode.x:128] trace of num_terminators: 7
I0611 19:46:37.793875      16 varint_streaming_decode.x:176] next_old_bytes calc: do_input=0 do_big_shift=1 num_terminators=7
I0611 19:46:37.794084      16 varint_streaming_decode.x:199] encoded=[0, 1, 0, 1, 0], decoded=0, this_bytes_taken=1, total_bytes_taken=5, bytes_len=11
I0611 19:46:37.794281      16 varint_streaming_decode.x:199] encoded=[1, 0, 1, 0, 1], decoded=1, this_bytes_taken=1, total_bytes_taken=6, bytes_len=11
I0611 19:46:37.794494      16 varint_streaming_decode.x:199] encoded=[0, 1, 0, 1, 0], decoded=0, this_bytes_taken=1, total_bytes_taken=7, bytes_len=11
I0611 19:46:37.794508      16 varint_streaming_decode.x:213] ouput_words=[0, 1, 0], num_output_words=3
I0611 19:46:37.794538      16 varint_streaming_decode.x:85] state=State {
I0611 19:46:37.794541      16 varint_streaming_decode.x:85]   work_chunk: [1, 0, 1, 0, 0, 0, 0],
I0611 19:46:37.794542      16 varint_streaming_decode.x:85]   len: 4,
I0611 19:46:37.794544      16 varint_streaming_decode.x:85]   old_bytes: [0, 0, 0, 0],
I0611 19:46:37.794546      16 varint_streaming_decode.x:85]   old_bytes_len: 0,
I0611 19:46:37.794548      16 varint_streaming_decode.x:85]   drop_count: 0
I0611 19:46:37.794550      16 varint_streaming_decode.x:85] }
I0611 19:46:37.795046      16 varint_streaming_decode.x:118] input_data=[0, 0, 0, 0, 0, 0, 0] input_len=0, do_input=0

What should

Instead of re-using the internal absl logging with different goals, make trace_fmt!() useful, possibly with a flag e.g. --trace_out, that then formats with with full relevant information for an IDE to jump to an step to each message, in the standard <filename>:<line>:<colrange>: format, but no unnecessary fluff:

xls/examples/protobuf/varint_streaming_decode.x:119:5-91: input_data=[0, 0, 0, 0, 0, 0, 0] input_len=0, do_input=0

Nice-to-have, but not needed in first implementation:

• make --trace_out get an optional parameter with the filename to emit the traces to; not sure if absl flags can take optional parameters though.
• if isatty(output_fd), color the filename.

Why is this important ?

Well, the example above shows that it is already much more relevant for a human when debugging xls code. But it is also easier for an IDE to pick up information.
I am working towards a feature where you have a 'play' button next to the test in xls (like in emacs in rust files). That will help to have a much more interactive way to interact with the code.