Skip to content

Trace entry format mismatch

Jump to bottom
Eric Flumerfelt edited this page Jun 17, 2022 · 1 revision

Trace entry format mismatch

The following sets of commands can be used to illustrate what an entry format mismatch would look like:

rm -f /tmp/trace_buffer_$USER; export TRACE_MSGMAX=0
setup TRACE v3_14_02; tcntl test1; TRACE_SHOW="HxNTPiCnLRB#" tshow|cat
setup TRACE v3_15_02; tcntl test1; TRACE_SHOW="%H%x%N %T %P %i %C %n %L %R %B %a %m" tshow|cat
setup TRACE v3_14_02; tcntl test1; TRACE_SHOW="HxNTPiCnLRB#" tshow|cat

and similarly:

rm -f /tmp/trace_buffer_$USER; export TRACE_MSGMAX=0
setup TRACE v3_15_02; tcntl test1; TRACE_SHOW="%H%x%N %T %P %i %C %n %L %R %B %a %m" tshow|cat
setup TRACE v3_14_02; tcntl test1; TRACE_SHOW="HxNTPiCnLRB#" tshow|cat
setup TRACE v3_15_02; tcntl test1; TRACE_SHOW="%H%x%N %T %P %i %C %n %L %R %B %a %m" tshow|cat

Note: in the above set of commands, the “entry parameter bytes” and “entry # of parameters” is added
to the default TRACE_SHOW format to more clearly show problems with the entries.

The output from the first is presented next and explained afterwards:

$ rm -f /tmp/trace_buffer_$USER; export TRACE_MSGMAX=0
--2019-09-27_16:22:56--
$ setup TRACE v3_14_02; tcntl test1; TRACE_SHOW="HxNTPiCnLRB#" tshow|cat
09-27 16:22:56.433944   TRACE nfo Hello 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
idx           us_tod    pid    tid cpu    name lvl r B args msg
--- ---------------- ------ ------ --- ------- --- - -- ---- -----------------------------
  0 1569619376433944 346816 346816  25   TRACE nfo . 8    6 Hello 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
--2019-09-27_16:22:56--
$ setup TRACE v3_15_02; tcntl test1; TRACE_SHOW="%H%x%N %T %P %i %C %n %L %R %B %a %m" tshow|cat
09-27 16:22:56.502766 trace_cntl.c nfo Hi 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
idx           us_tod    pid    tid cpu      trcname lvl r B args msg                       
--- ---------------- ------ ------ --- ------------ --- - - ---- --------------------------
  0 1569619376502766 346875 346875  37 trace_cntl.c nfo . 8    6 Hi 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
  1 1569619376433944 393218 346816 346816        TRACE d08 . 0    0 Hello %d. "c 2.5 5 5000000000 15" should be repeated here: %c %.1f %hd %lld %d
--2019-09-27_16:22:56--
$ setup TRACE v3_14_02; tcntl test1; TRACE_SHOW="HxNTPiCnLRB#" tshow|cat
09-27 16:22:56.570162        TRACE nfo Hello 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
idx           us_tod    pid    tid cpu         name lvl r B args msg
--- ---------------- ------ ------ --- ------------ --- - -- ---- -----------------------------
  0 1569619376570162 346934 346934  25        TRACE nfo . 8    6 Hello 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
  1 1569619376502766 346875     37 1080 trace_cntl.c d59 1536 2050    5 Hi 1. "c 2.5 5 5000000000 15" should be repeated here: í 0.0 0 0 *d
  2 1569619376433944 346816 346816  25        TRACE nfo . 8    6 Hello 1. "c 2.5 5 5000000000 15" should be repeated here: c 2.5 5 5000000000 15
--2019-09-27_16:22:56--

First, the trace buffer files is removed and a TRACE env.var is set to activate memory buffer tracing.
Next, a version of trace is setup and used to cause a single trace to occur which will create a new trace buffer file.
When a trace buffer file is created, the revision of the header that was used to build the creating program is include in the trace buffer file.
It should be noted that the version in the buffer file is not the version of the individual entries.
Then, tshow is used to show the entry. Since the entry was made and shown by programs build from the same Revision of trace.h, all is well.
Then, a version of trace with a Revision of trace.h which has a different entry structure is setup. Programs with this Revision of the header are
used to make another entry in the buffer file and then show the buffer.
The entry made with the other Revision of the header (entry idx 1) has problems; specifically:

  • cpu is large
  • param bytes (0) is invalid — the only valid values are 4 and 8
  • entry # of bytes is 0, but there are format specifiers, which is strange

When the entry # of args 0, the message is shown verbatim and no parameter processing occurs and hence,
the message with the format specifiers is shown (“c.1f %hd %lld %d”).

Lastly, the original version of TRACE is setup and use to make another entry and the show the resulting 3 entries. When these entries are shown,
the first and the last entries (idx 0 and 2) appear fine, but the midle entry (idx 1), based on the different header, appear invalid:

  • tid is really small
  • cpu is really large
  • retries is really large
  • param bytes (2050) is invalid

Clone this wiki locally