Tcl Source Code

I have found some probable issues with variable tracing of arrays.

The following example seems to cause incorrect recursion of tracing
It also results in a final read value that does not include the changes that occured during tracing.


Program:

# Setup
set y(bar) 1
trace variable y r { puts "in trace2 reading y     "; puts  [array get y]  ; puts "end trace2" ;#} 
trace variable y r { puts "in trace1 set   y(foo) 1"; set y(foo) 1         ; puts "end trace1" ;#} 

# when running the following command, traces get run in reverse order of creation - i.e. trace1, then trace2
# On entry to the command, y is ( bar=>1 )
# trace1 should get called setting y(foo) to 1  which results in y ( bar=>1, foo=>1 ) 
# trace2 should then run:
#          it unsets y(bar) which results in y ( foo=>1 )
#          it then reads elements of y, however as per the documentation, traces on y are currently disabled during execution of this trace handler. Hence this read should solely result in printing "foo 1"
# No more tracing should occur

puts "y = [array get y]"

# What actually happens:
# 	trace1 is called setting y(foo) to 1 which results in y ( bar=>1, foo=>1 )
#   trace2 is called:
#            it reads y using "array get" command
#            trace1 is incorrectly triggered again - it should have been currently disabled, value of y does not change
#            trace2 is incorrectly triggered again - 
#                                  it reads y using "array get" command again - this time the trace recursion seems to be correctly disabled.
#                                  prints values of y "foo 1 bar 1" - value is as expected
#                                  repeated trace2 ends
#            prints values of y "foo 1 bar 1" - as expected
#            repeated trace2 ends
#
#   print which triggered the tracing prints wrong value "y = bar 1"  - should be "y = foo 1 bar 1"


Actual output:

in trace1 set   y(foo) 1                                                                                                                                                                                                                               
end trace1                                                                                                                                                                                                                                             
in trace2 reading y                                                                                                                                                                                                                                    
in trace1 set   y(foo) 1                                                                                                                                                                                                                               
end trace1                                                                                                                                                                                                                                             
in trace2 reading y                                                                                                                                                                                                                                    
foo 1 bar 1                                                                                                                                                                                                                                            
end trace2                                                                                                                                                                                                                                             
foo 1 bar 1                                                                                                                                                                                                                                            
end trace2                                                                                                                                                                                                                                             
y = bar 1  



Regards,

Evan Hunter

There's a fairly complex set of internal states, but arrays exist independently of their contents. Furthermore, it's possible for a variable to exist but be reported (e.g., by info exists) as not existing; that typically means that either there's a trace keeping the storage alive or that there's an upvar-link pointing to it. It'll get reaped once there's no more references to it on the C side, or it'll have something put into it and become persistent (until it is deleted or has its owning context destroyed).

However, once you start using multiple array-level traces that modify the array on read, my ability to figure out sanity gets strained. Traces never run while they are already running, but one trace can cause another to run. Moreover, array get triggers traces in two phases, once to allow the set of keys to be correct (used to make ::env work right) and again when the individual elements are read (and failures to read the variable there cause the key to be omitted from the result). It doesn't detect keys added while it is running since that might well cause all sorts of flapping.

It's probably not a good idea to put a reading-trace on an array when there's another reading trace that does a read on the array. In fact, don't do that. Do consider using trace add variable y array as well for setting the foo element. That runs at a time before the list of keys is constructed.

I won't fix anything here. What we've got is probably as good as is practical.

I think test-case trace.test 1.11 is OK. It can be shown by doing an "array get x" a second time. Then the expected "foo 1" is produced:
# set x(bar) 0
% trace variable x r {set x(foo) 1;#}
% trace variable x r {unset -nocomplain x(bar) ;#}
% array get x
% array get x
foo 1
%

Explanation: The "array get x" first looks at what keys there are. Initially it's only "bar", so that array entry is read. But ... reading this entry fires the two triggers, removing element "bar" and adding "foo". But the addition of "bar" cannot be seen any more, because "array get" already handled the last key.

So, I think trace.test 1.11 gives the expected result. Whatever bug there is (Donal can judge that better than I can), trace.test 1.11 is not involved with this 'bug'.

A bit more testing regarding test 1.11 in tests/trace.test:

It seems that arrays do still exist after the last element has been removed. This means that either the expected value of trace.test 1.11 is wrong or the array existence is wrong.

i.e. I would expect test 1.11 to return "foo 1"


Test code:

puts "X content \'[array get x]\'"
puts "X existence [info exists x]"
puts "\nSetting x(foo)\n"
set x(foo) 0
puts "X content \'[array get x]\'"
puts "X existence [info exists x]"
puts "\nUnsetting x(foo)\n"
unset x(foo)
puts "X content \'[array get x]\'"
puts "X existence [info exists x]"

Assigning to Donal (he's the expert on that. Want prove?: See [219226])

This may also affect the test 1.11 in tests/trace.test:

test trace-1.11 {read traces that modify the array structure} {
    catch {unset x}
    set x(bar) 0 
    trace variable x r {set x(foo) 1 ;#} 
    trace variable x r {unset -nocomplain x(bar) ;#} 
    array get x
} {}

The trace called first (which was defined second) would cause the array x to be empty by unsetting x(bar).

I am not sure whether this constitutes the whole variable x being unset too. If so, then the traces should get removed, and the expected output is correct.

If the array variable is still considered valid with no elements, then the output is incorrect, as the second trace would get run, setting x(foo) 1.

Regards,

Evan

I've attached a file with a failing tcltest script (and a near variation which passes).

The issues seem to hit when trace1 creates an array element that did not previously exist:

---- Output was:
In trace1 {y foo read}: 1
End trace1
In trace2 {y foo read}: 1
In trace1 {y bar read}: 1
End trace1
In trace2 {y bar read}: 1
foo 1 bar 2
End trace2
foo 1 bar 2
End trace2
y = foo 1

---- Output should have been (exact matching):
In trace1 {y foo read}: 1
End trace1
In trace2 {y foo read}: 2
foo 2
End trace2
y = foo 1 bar 2

I'm not sure if the recursive triggering should happen when the y(foo) handler modifies y(bar), but the change remaining invisible to the main program is clearly a bug.

See also what happens with `set y(bar) 3` inserted before creating the traces.