Tcl Source Code

Execution traces of the enter type interfere with
execution traces of the enterstep type. (the
leave/leavestep case may behave similarly, but did not
check that.)

To appreciate the interference:

Run1: source the test script below without modification.
Run2: uncomment the clock command inside the
interpTraceHandler and again source the test script (in
a clean interpreter).

Comparing the output of the 2 runs (also appended)
shows that the stepTrace handler is called at
additional deeper levels in run 2 as compared to run 1.
It appears that the trigger of a command trace
re-enables further step tracing, even while a step
trace is in progress.

% parray tcl_platform
tcl_platform(byteOrder) = littleEndian
tcl_platform(machine)   = i686
tcl_platform(os)        = Linux
tcl_platform(osVersion) = 2.4.21-99-athlon
tcl_platform(platform)  = unix
tcl_platform(user)      = erik
tcl_platform(wordSize)  = 4
% info patch
8.4.12
% 

Erik Leunissen

== test script ==
proc stepTraceHandler {cmdString args} {
    puts "level [expr {[info level] -1}]: [lindex
[split $cmdString] 0] triggered a step trace handler"
    # clock clicks; # enabling/disabling this command
causes a different behaviour of step traces
    isTracedInside_2
}
proc cmdTraceHandler {cmdString args} {
    puts "level [expr {[info level] -1}]: [lindex
[split $cmdString] 0] triggered a cmd trace handler"
}
proc isTracedInside_1 {} {
    isTracedInside_2
}
proc isTracedInside_2 {} {
    set x 2
}

trace add execution clock enter cmdTraceHandler
trace add execution isTracedInside_1 enterstep
stepTraceHandler
trace add execution isTracedInside_2 enterstep
stepTraceHandler

isTracedInside_1; # start the execution

# End of script


Results of the two runs:
========================

Run1:
level 1: isTracedInside_2 triggered a step trace handler
level 2: set triggered a step trace handler
level 2: set triggered a step trace handler

Run2:
level 1: isTracedInside_2 triggered a step trace handler
level 2: clock triggered a cmd trace handler
level 3: set triggered a step trace handler
level 4: clock triggered a cmd trace handler
level 2: set triggered a step trace handler
level 3: clock triggered a cmd trace handler
level 3: isTracedInside_2 triggered a step trace handler
level 4: clock triggered a cmd trace handler
level 4: set triggered a step trace handler
level 5: clock triggered a cmd trace handler
level 2: set triggered a step trace handler
level 3: clock triggered a cmd trace handler
level 3: isTracedInside_2 triggered a step trace handler
level 4: clock triggered a cmd trace handler
level 4: set triggered a step trace handler
level 5: clock triggered a cmd trace handler

== end of message ==

Logged In: YES 
user_id=80530


ok, cmd traces and exec traces
ought not interfere with each
other, and the test case demos
at least one circumstance where
they do.  the patch corrects
that interference, and does not
create any apparent new problems
or bugs.  The substance of the
patch is sensible too, performing
an explicit save/restore instead
of a do/undo type maintenace of
a value.

On that basis, I'm accepting
these patches.

However, it sure looks to me
like the results of these tests
are just plain wrong.  I haven't
been able to come up with any
interpretation of the exec trace
documentation that would agree with
the results generated.  There's
more bugs here to find.

File Added - 174199: 1458826-85.patch

Logged In: YES 
user_id=80530


and here's the corrsponding
patch for HEAD (Tcl 8.5a4).

File Deleted - 174189: 



File Added - 174198: 1458266.patch

Logged In: YES 
user_id=80530


updated patch includes
new test trace-34.6
derived from the submitted
test case.

Logged In: YES 
user_id=80530


Is there a simple explanation
why we need two commands with
step traces on them to demo
this bug?

File Deleted - 172709: 



File Added - 174189: 1458266.patch

Logged In: YES 
user_id=80530


Here's a revised patch
to account for C (not C++)
compilers.

Logged In: YES 
user_id=113903

With respect to:

"If there are several possible answers,
because the docs are not specific enough,
then which of those answers would be
most useful to you?  We can consider
just "making" that the correct one."

In the case of multiple simultaneous traces, that may
interact in rather messy ways,
I would suggest a conservative strategy:
- start out with a rather restricted but clear and simple
definition of the behaviour
- leave room for more refined, diverse behaviour in specific
cases only after these cases have been specified.

Such a limited starting point *could* be:
"While any step trace handler is executing, further
invocations of Tcl commands should never trigger any step
traces again (i.e. regardless the trace that was registered,
regardless the command on which traces exist, or the trace
handler)."

But I would welcome a discussion among a wider audience
about the exact formulation of such a limited starting point.

Right now I just want to propose a strategy that leaves us
more in control of what's right and wrong.

File Added - 173113: interferenceTest.tcl

Logged In: YES 
user_id=113903

OK, then how about me supplying a fully documented test
script that you can use as a basis for the test suite? I
took the liberty to do that (see uploaded file
"interferenceTest.tcl").

The reason that I am particularly careful here, is because
we're actually in one of the corner cases that I mentioned
in the previous post: the observed bug emerges only when two
step traces are registered, both using the same trace
handler. The docs are not explicit about that case.

Therefore, the test script does a differential diagnostic,
i.e. comparing two runs, but not saying anything about the
correct behaviour of any of the two runs. It does not test
for a predefined "correct" result.

If you insist on checking for a "correct" result of a single
run, then indeed more reflection is needed. In order to keep
the progress with this issue, I post the differential
approach and await how useful that is to you.

The comments to the test script explain in detail what
should happen and what not, and why. You may use the test
for its explanation alone, or use it as a basis for other
tests; whatever you like.

As for the supplied patch:
I'm quite sure that I found the location which is
responsible for the interference. That in itself is one
value of the patch. However, this is the first time that I
provided a patch at the C level. I may not have enough
overview of the Tcl C library to know about possibly related
areas that should change as well (byte compiled scripts are
an example, because it is a sort of subsystem that I do not
grasp very well). I've used a new libtcl8.4.so (that has my
patch applied) in quite some tests. Among these are some
that exercise traces. These tests all behaved as expected.
Nevertheless, I'm curious whether the patch has any side
effects in areas that were overlooked.

Regards,

Erik Leunissen

Logged In: YES 
user_id=80530


Somehow I think you've
got the wrong impression
about my question.

As a first step toward fixing
the bug, I'm trying to convert
your report into additional tests
in the test suite.  To do that,
I need to tell the test suite
what correct answers to expect.
Then I can use those tests to help
me determine whether various changes
correct the bug.

Since it's your example, I assumed
you would have an expected answer
in mind and could easily tell me
what it is.  As you see, the docs
are rather complex, and I don't want
to put in the effort to decipher them
if you've already done it.

So, first request is, assuming everything
in the documentation were telling 
the truth, what answer do you expect?

If there are several possible answers,
because the docs are not specific enough,
then which of those answers would be
most useful to you?  We can consider
just "making" that the correct one.

If none of the answers consistent with
the docs is useful to you, then we can
even consider revising things, but that
will take some more reflection.

Traces are messy in concept (lots of
potential re-entrancy to deal with),
and much, much more messy in the
implementation.  You refer to a
"design specification" for the trace
mechanism.  There really ain't one.
Not beyond what's stated in either
the docs or in TIP 62 (http://tip.tcl.tk/62).
Any behavior you want that's consistent
with those is possible, and if you can
show that what they specify makes no
sense, even revising them is possible.

Logged In: YES 
user_id=113903

Don,

I've been thinking about your question "what should the
behaviour of the test script be and why?". 
I wil get to that matter shortly, but first off, I want to
emphasize that (in my view) an answer to that question is
irrelevant for the decision as to whether the observed
behaviour is faulty. 

Do you agree on that?

As to "what should the behaviour of the test script be and
why?: Only if the following statement is true, I can give
you an answer:

statement
=========
"While any step trace handler is executing, further
invocations of Tcl commands should never trigger any step
traces again (i.e. regardless the command or the trace
handler)."

So, can you (or another member of the core team) tell
whether this statement is true?

If you can't tell, or if it is not true, then I feel we're
heading into a minefield of complicating cases that exist in
the space spanned up by:
- traces on different commands (regardless trace handler)
- different trace handlers (regardless command that triggers
them)
- different types of step trace (enterstep/leavestep
- step traces vs. (non-step) command traces
- did I forget something ...?

Personally, I'm not prepared to say anything about how
traces should behave in degenerate cases in remote corners
of that space, without fully understanding the design
specification of the tracing mechanism. The manual page of
the [trace] command is explicit about the behaviour in one
specific complicating case:

if a trace handler calls the command that triggered the
trace in the first place, that command will not trigger a
trace again.

The issue that I reported appears to violate precisely that
one case about which the manual page is explicit.

Sincerely,

Erik Leunissen
==============

Logged In: YES 
user_id=113903

OK (then I misinterpreted your "why").

Tomorrow I can give additional explanation (too late now
here, going to sleep). In the meantime, please let me know
any specific points that are still unclear.

As to "the correct behaviour" of Run2, that requires
attention on my part also. It is easy to see that Run2
misbehaves (you can easily see that from additional triggers
of the step trace handler at level 3). But the correct
behaviour is another matter. I need to study the docs for
that, and you might even be quicker finding that out.

Logged In: YES 
user_id=80530


To clarify, I'm not trying
to defend the current behavior.

I'm sincerely seeking guidance
on what the correct behavior of
your test script ought to be.

Logged In: YES 
user_id=113903

The reproducible script shows that the triggering of a
command trace (i.e. "enter" or "leave" types) affects the
triggering of step traces (i.e. "enterstep" or "leavestep"
types).

That fact alone simply doesn't make sense (to me anyway).

The expected output for run 2 is: the step trace handler
should trigger for exactly the same commands as in run 1,
i.e. once at level 1 (triggered by [isTracedInside_2] and
twice at level 2 (both triggered by [set]).

(The output from the cmd trace handler, triggered by [clock]
, is only shown to enable tracking the path of execution,
but is irrelevant for the comparison of the step trace
behaviour. You may filter the extra verbosity out by making
the command trace handler mute, i.e. an empty body.)

Also, the man page for [trace] says:
"While command is executing during an execution trace,
traces on name are temporarily disabled. This allows the
command to execute name in its body without invoking any
other traces again."

I believe that the script violates this rule.

Logged In: YES 
user_id=80530


Can you talk me through
what you expect the correct
result to be, and why?

Logged In: YES 
user_id=113903

The patch was created against 8.4.12

Logged In: YES 
user_id=80530


thanks for the patch;
appears to be against 8.4.13?

File Added - 172709: tclCmdMZ.c.diff

File Deleted - 172706:

File Added - 172706: tclCmdMZ.c.diff

Logged In: YES 
user_id=113903

Uploaded a patch file, which also corrects the fact that the
replacement in my previous post lacked a:

    tcmdPtr->flags |= TCL_TRACE_EXEC_IN_PROGRESS;

Logged In: YES 
user_id=113903

The following patch remedies the observed behaviour. It
concerns the function TraceExecutionProc() in tclCmdMZ.c.

Original code (Tcl8.4.12)
=========================

    tcmdPtr->flags |= TCL_TRACE_EXEC_IN_PROGRESS;
    iPtr->flags    |= INTERP_TRACE_IN_PROGRESS;
    tcmdPtr->refCount++;
    /* 
     * This line can have quite arbitrary side-effects,
     * including deleting the trace, the command being
     * traced, or even the interpreter.
     */
    traceCode = Tcl_Eval(interp, Tcl_DStringValue(&cmd));
    tcmdPtr->flags &= ~TCL_TRACE_EXEC_IN_PROGRESS;
    iPtr->flags    &= ~INTERP_TRACE_IN_PROGRESS;

Replacement
===========

/*
 * Save the state regarding interpreter wide tracing to
 * restore it after invoking the callback. This prevents
 * any subsequent command traces at a deeper nesting level
 * from affecting the interp trace flags.
 */
    int saveInterpFlags = iPtr->flags;
    iPtr->flags    |= INTERP_TRACE_IN_PROGRESS;
    tcmdPtr->refCount++;
    /* 
     * This line can have quite arbitrary side-effects,
     * including deleting the trace, the command being
     * traced, or even the interpreter.
     */
    traceCode = Tcl_Eval(interp, Tcl_DStringValue(&cmd));
    tcmdPtr->flags &= ~TCL_TRACE_EXEC_IN_PROGRESS;

/*
 * Restore the state regarding interpreter wide tracing
 */
    iPtr->flags = saveInterpFlags;


End of patch
============