Tcl Source Code

I wrote a simple application to gather Tk events and pass them from one interpreter to another via tequila (http://wiki.tcl.tk/1243), which uses traces and socket communication to keep array values in sync between Tcl interpreters.

My application displays a canvas, to which a <Motion> event is bound.  Thus as the cursor is moved over the canvas a steady stream of Tk events is generated; the scripts associated with these events are captured and written to an array, which tequila echoes to an interpreter in a separate process.  

When I start this application and move the cursor continually over the canvas, sometime between five and sixty seconds later one of the interpreters segfaults and crashes.

Platform is Ubuntu Hardy, with ActiveTcl 8.5.5 installed.  I duplicated the bug using Pat Thoyt's tclkits versions 8.5.8 (http://www.patthoyts.tk/tclkit/linux-ix86/8.5.8/tclkit%2d8.5.8.gz) and 8.6b1.1 (http://www.patthoyts.tk/tclkit/linux-ix86/8.6%2dbeta/tclkit%2d8.6b1.1.gz).

For ease of duplication I created a starkit containing all relevant code called echoevent.kit (attached).  To duplicate:

1. in a terminal console, execute: tclkit echoevent.kit server
This will start a tequila server.

2. in a separate terminal console, execute: tclkit echoevent.kit master
This will start a simple Tk "master" application that displays a canvas.  Moving the cursor across this "master" canvas will cause the command associated with the <Motion> event to echo repeatedly to the terminal console.

3. in a third terminal console, execute: tclkit echoevent.kit slave
This will cause an identical "slave" Tk application to appear, except event processing for the "slave" canvas is disabled.  Moving the cursor across the "master" canvas will cause the event command to echo to both the "master" console and the "slave" console.  The tequila server is passing event information from the master interpreter to the slave interpreter.

4. move the cursor continually over the master canvas to generate a constant stream of <Motion> events to be echoed to the consoles.  Either the master or the slave process will crash with a segmentation fault within 60 seconds.
            
report cross-posted at: http://bugs.activestate.com/show_bug.cgi?id=85927

allow_comments - 1

At last !!!
Thanks for fixing that "--" typo.

Applied the corrected version of your last patch.

We can't detect a trace in O(1) as that information is not collected (it can't be collected because we can't go cheaply from the state of knowing that there is a trace to knowing that there isn't one) and just because the semantics have been screwed up for a long time doesn't mean that they should not be fixed.

Your patch is *still* wrong though, independent of that. Really. (Look at the line where you're dealing with the reference count of protectedVarPtr...)

Donal, you're re-discovering hot water ;-)

The fact that [array unset *] + [trace add ... set ar($newkey) 1] leaves the array with an apparently random subset has been true since Day One of trace !!!

To try to keep the discussion on tracks, two things :

 (1) please admit that HEAD currently has a leak that my latest patch fixes, at iso-semantics with Day One.

 (2) if we are to iron out the semantics at the cost of *** POTENTIAL INCOMPATIBILITY ***, indeed I've discussed it with Miguel when evaluating "thermonuclear solutions". I was suggesting the snapshot idea, and Miguel proposed to just rewind the iterator. (I still prefer the snapshot, because the rewind leads to quadratic behavior and may fire some unset traces more than once). But the snapshot also has a performance impact wrt current code, and would need to kick in only when unset traces are present (can we detect a single-key trace in O(1) ?).

Your patch is still wrong. ;-)

More importantly, the whole semantics for how you're going about it is wrong too, and no single-iteration strategy can fix it. To show what I mean, here's a sample session (using the HEAD, but apply any fixes you want...)

% trace add variable foo unset {apply {{a b c} {if {$b eq "b"} {global foo; for {set i 0} {$i<100} {incr i} {set foo($i) 1}}}}}
% array set foo {b 1 f 1 j 1}
% parray foo
foo(b) = 1
foo(f) = 1
foo(j) = 1
% array unset foo *
% parray foo
foo(35) = 1
foo(36) = 1
foo(37) = 1

The fundamental issue is that when an unset trace tinkers with the contents of the array, [array unset]'s semantics go haywire. The only thing I can think of to fix this is to use a multi-step deletion process which first calculates which elements to kill and then nukes them while calling traces. (The confusion about what happens when a trace updates an element that is about to be deleted vs one that has already been deleted is probably an indication that we'll just have to be careful.) I suggest snapshotting (into a C array) at the start is sanest, and lets us avoid problems with the iterator's internal pointer entirely.

Attaching the fix. Several things to note:
  - removed the refcount-- == 1 logic, since it is wrong in that case, and CleanupVar does it too, and does it right
 - moved CleanupVar back to the bottom of the loop in the "else" of !IsVarUndefined
 - this fixes the leak, avoids using the var after freeing, and makes your comments accurate again ;-)

File Added - 361372: arrayunset3.patch

File Deleted - 361371:

File Added - 361371: arrayunset3.patch

allow_comments - 0

Donal, what you've just committed is not correct yet. The leak is still there.
I notice that your first CleanupVar is dangerous; if it succeeds, varPtr2 is now a freed structure, and yet is used in making decision.
Why not use the CleanupVar logic I posted ?

allow_comments - 1

File Added - 361360: arrayunset2.patch

File Deleted - 361330:

Attached the small delta-patch reintroducing CleanupVar and eliminating the leak.

File Added - 361330: arrayunset2.patch

allow_comments - 0

Beware, there is a leak in the non-error case now. This is due to only decrementing refcounts without ever calling CleanupVar. Not sure why you removed this call from my initial patch.

Proof of leak:

array set x {e 1 i 1}
trace add variable x unset rem
proc rem args {
    puts REM:$args
    if {![info exists ::already]} {
set ::already 1
unset ::x(e)
    }
}
array unset x i*
array stat x

=>
 number of buckets with 0 entries: 3
 number of buckets with 1 entries: 1

array size x
=> 0

What happens is that the secondary unset is delayed because "e" is in the protected state, but since the overall pattern "i*" doesn't include "e", it doesn't get directly deleted from the main iteration either.

Having noticed that VarHashRefCount(x)-- doesn't take the actual final step, we must call CleanupVar independently from the match outcome; this is exactly what my patch was doing.

allow_comments - 1

Backported to 8.5. I think it's probably not practical to backport to 8.4 since this is thoroughly dependent on miguel's VarReform work.

File Added - 361257: arrayunset.patch

File Deleted - 361174:

That patch doesn't quite work. It has excess refcount problems when there's a failure to unset midway. Evil case!

I'll attach the patch I've applied to the HEAD, which addresses the issue (it's closely based on yours and includes a test). Note that it doesn't include any code to invalidate unused memory; the --enable-symbols=mem configuration works fine for that already.

The attached patch fixes the issue by properly protecting the next-in-current-bucket.
This is done modularly (without touching tclHash.c) thanks to the property that the search object has a NULL nextEntryPtr at each bucket change. So the protection is done by upping the refcount of nextEntryPtr, and decreasing it again one loop cycle later. 

Since the patch includes the "sanitizing" line, a deterministic test case will be provided shortly.

Please review.

File Added - 361174: arrayunset.patch

Upping prio. Patch under way.

Ha ! Got it now.

In truth the secondary unset _does_ kill the hash entry in that case, it's just that the reuse of the freed block doesn't cause immediate harm normally. Hence I had to add the following 'sanitizing' line to FreeVarEntry:

         if (TclIsVarUndefined(varPtr) && !TclIsVarTraced(varPtr)
     && (VarHashRefCount(varPtr) == 1)) {
+varPtr->value.objPtr=(void *)0xdeadbeef;
 ckfree((char *) varPtr);

It is simply a matter of resetting a field to a visibly invalid value just before freeing.
The effect is that, as soon as somebody reuses that freed structure (and typically by indirections off this objPtr field), a SIGSEGV or SIGBUS will burst on 0xdeadbeef.

And it does: given this sanitizing patch, the following ultrashort example crashes tclsh:

array set x {e 1 i 1}
trace add variable x unset rem
proc rem args {
    puts REM:$args
    if {![info exists ::already]} {
set ::already 1
unset ::x(e)
    }
}
array unset x *

Explanation: a nascent array with a small size has only 4 buckets, allowing a quick search of collisions.
It turns out 'e' and 'i' fall in the same bucket. Since the entries of a same bucket are stored in a LIFO linked list, the [array unset x *] iteration will do 'i', then 'e'. The rest of the code arranges for the 'e' to be removed as a side effect of the unset trace on 'i', hence removing the rug. Boom.

Renaming the bug according to this confirmation.

Sigh.
 Just produced a bucket of depth three: [array set x  {a 1 e 1 i 1}].
(verify with [array stat x])

Then tried this:
     trace add variable x unset rem
     proc rem args {puts REM:$args; if {![info exists ::again]} {set ::again 1;unset ::x(e)}}

Then [array unset x *] should remove, in order, i,e,a.
*But*, since the trace proc removes e while removing i, the outer loop should get into trouble....

Though it doesn't for some reason.
Just noticed the tricky game of Undefining a var instead of coldly killing its hash entry. Maybe this explains that, and my hypothesis was naive. Something more subtle must come into play...

Additional insight: the way the "stateful iterator" Tcl_HashSearch work, is by a {bucket index, chained intra bucket pointer} pair. So the cases where the aforementioned interaction can cause harm, is when the second-level [unset] removes the very next entry from the same bucket.

That's why the crash is so rare. Now to designing a pin-sharp case ;-)

Still not managed to reproduce, but a good candidate from RTFS:
At line 3199 of tclVar.c, for [array unset var pattern], a loop iterates over key with a stateful iterator:

   for (varPtr2=VarHashFirstVar(varPtr->value.tablePtr, &search);
    varPtr2!=NULL ; varPtr2=VarHashNextVar(&search)) {

then, in the body of that loop, when a match is found, the unset is done, possibly calling traces, possibly wreaking the chaining of hash keys.

Some kind of locking, or a more robust iterator, must be used I think.

Homing in.
Just adding [puts] around the unset, shows a reentrancy issue.

UNSETCOLLAB>: .c,queue,19,* (size:23 -- matching:10)
UNSETCOLLAB>: .c,queue,20,* (size:22 -- matching:10)
UNSETCOLLAB<
UNSETCOLLAB>: .c,queue,19,* (size:12 -- matching:9)
UNSETCOLLAB<

This in turn can be traced down to Tequila doing [vwait] in its guts. With Tk and a heavy stream of events, that [vwait] can catch a GUI event and call arbitrary code, including some doing an extra [unset] on the same var.

Knowing this, I'll try to build an atomic example.

Further analysis of the core shows the command

   array unset collab .c,queue,42,*

being executed at the time. So it seems to hint at an interaction between patterned unsets and traces. I'd appreciate somebody knowing the app at hand to trim that stuff down to a manageable size... TBC

After Steve kindly brought all the pieces beside my bed, I could get the attached gdb stack trace under Linux (Fedora 12, 32bits). Nothing about Metakit there.

File Added - 360295: crash1.txt

I've reproduced the problem on OSX 10.6.2 using wish 8.5.7.  If I can figure how, I'll attach the traceback file

Since this happens on unix, can you enable core dumps, and provide a gdb stack trace of the crash ? I'd like to dichotomize between Metakit and the vanilla Tcl core.

As a side note, a .kit is not the easiest transport for some maintainers (me at least), because it requires additional effort to crack the hull open, and reproduce with the core-under-development. I hate efforts ;-)

File Added - 360172: echoevent.kit