[DTrace-devel] Long-standing bug in DTrace discovered

[Kris Van Hees]

In the midst of fixing the semantics of the BEGIN probe, the END probe, the
exit() action, and user-initiated termination we tried various scenarios of
valid D clauses to make sure everything was working as expected.  An unusual
discrepancy was found...

dtrace -n BEGIN'{ trace(123); exit(1); trace(321); exit(2); }' -n END

yields the following output on DTrace based on BPF:

    dtrace: description 'BEGIN' matched 1 probe
    dtrace: description 'END' matched 1 probe
    CPU     ID                    FUNCTION:NAME
     11      1                           :BEGIN         123        321
     11      2                             :END 

and the return code of the dtrace command is 2.

When trying this on the legacy implementation of DTrace on Linux we get:

    dtrace: description 'BEGIN ' matched 1 probe
    dtrace: description 'END' matched 1 probe
     CPU     ID                    FUNCTION:NAME
       2      2                             :END 

and the return code of the dtrace command is 0.  That can't be right!

So, we tried this on an Oracle Solaris system and got exactly the same output
(and rc) as the legacy DTrace on Linux version!

Now, if you drop the 2nd exit action, things are very different:

    dtrace: description 'BEGIN' matched 1 probe
    dtrace: description 'END' matched 1 probe
    CPU     ID                    FUNCTION:NAME
     11      1                           :BEGIN         123        321
     11      2                             :END 

and rc = 1.  And this is the output and rc) for all three versions.

When you start digging into the implementation of DTrace on Linux (legacy) and
Oracle Solaris, the problem can be found in dtrace_probe().  When doing action
specific processing in a switch on act->dta_kind, special handling is done for
DTRACEACT_EXIT.  If the current activity state is DTRACE_ACTIVITY_COOLDOWN, we
have nothing to do (we are already processing a STOP operation issued by the
consumer).  Then, if the current activity state is not DTRACE_ACTIVITY_WARMUP,
we force the expected state to be DTRACE_ACTIVITY_ACTIVE.  Finally, the code
will set the activity state to be DTRACE_ACTIVITY_DRAINING if and only if the
current state is DTRACE_ACTIVITY_ACTIVE.

If the expected state is not DTRACE_ACTIVITY_ACTIVE, the CPU_DTRACE_DROP flag
is set which will drop all trace data recorded for the current ECB.

So, the problem is that when a clause contains two exit() actions, the first
one will move the activity state to DTRACE_ACTIVITY_DRAINING, and when the
second one gets processed, an invalid state is found (DTRACE_ACTIVITY_DRAINING
when it should be DTRACE_ACTIVITY_ACTIVE), and so the trace data for the ECB
gets dropped.  But since the state is DTRACE_ACTIVITY_DRAINING, tracing does
terminate as usual.  The trace data of the BEGIN clause (incl. the exit
value) is lost though.

So, the good news is that DTrace based on BPF is doing the right thing.  The
bad news is that pretty much all existing versions of DTrace have this bug.

Granted, I cannot really think of a real use case scenario where this action
sequence makes sense, but it is a nice example of valid code that actually
triggers a bug in the implementation.

	Kris