timer.setTimeout can call listeners that have been removed

[jessegreenberg]

In an unrelated issue, I encountered a case where a listener added through timer.setTimeout tried to call and then remove a listener that had already been removed. The issue happens when a listener is removed from timer in a separate listener that is also attached to timer. For example, running the following in the command line will result in an error "Assertion failed: tried to removeListener on something that wasn't a listener"

let timeoutReference = null;
const behavior = () => { console.log( 'behavior function called' ); }
const testCallbackTimer = new phet.sun.CallbackTimer( {
  callback: () => {
    console.log( 'running' );
    phet.axon.timer.clearTimeout( timeoutReference )
    timeoutReference = phet.axon.timer.setTimeout( behavior, 100 )
  }
} );
testCallbackTimer.start()

Because timer will try to remove timeoutReference again.

I think this is happening because of how TinyEmitter guards against removal of listeners with activeListenersStack.

@samreid could we add a guard in setTimeout to make sure timer still has the listener before trying to call and remove it?

[jessegreenberg]

const callback = dt => {
  elapsed += dt;

  // Convert seconds to ms and see if item has timed out
  if ( elapsed * 1000 >= timeout ) {

    // make sure that the listener hasn't already been removed since we may be calling this callback
    // from the TinyEmitter activeListenersStack, see https://github.com/phetsims/axon/issues/248
    if ( this.hasListener( callback ) ) {
      listener();
      this.removeListener( callback );
    }
  }
};
this.addListener( callback );

[samreid]

TinyEmitter's activeListenerStack is designed so that a listener that is present at the beginning of emit will still be notified, even if it is removed as a listener during traversal of emit. That is semantically what we decided is best-- @jonathanolson was involved in these discussions and decisions. The problem in this case is that clearTimeout happens first, removing the listener but this pushes it into the activeListenerStack and causes it to get notified again. It seems the proposal from @jessegreenberg addresses this problem, but I'm having difficulty thinking about this problem in a general sense. Will there sometimes be other listeners that will want to avoid being called from the activeListenerStack? Should we go about this a different way? If @jessegreenberg is running into an immediate roadblock from this, it seems OK to commit that change as a temporary-fix, but I think it would be best to consult with @jonathanolson about long term plans.

In case it helps, here is a patch that assigns a name to the listeners, and sets a debugger for the case where the listener is removed twice:

Index: faradays-law/js/faradays-law-main.js
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- faradays-law/js/faradays-law-main.js	(revision 5c0e135e25da1d934089b08d8617adb1e2fa036c)
+++ faradays-law/js/faradays-law-main.js	(date 1557413581000)
@@ -34,5 +34,40 @@
       new FaradaysLawScreen( Tandem.rootTandem.createTandem( 'faradaysLawScreen' ) )
     ], simOptions );
     sim.start();
+
+    // const timeoutReferences = [];
+    // const behavior = () => { console.log( 'behavior function called' ); };
+    // const testCallbackTimer = new phet.sun.CallbackTimer( {
+    //   interval: 100,
+    //   callback: () => {
+    //     console.log( 'callback timer running' );
+    //     console.log('clearing timeout for '+timeoutReferences.length);
+    //     timeoutReferences.forEach( t => phet.axon.timer.clearTimeout( t ) );
+    //     timeoutReferences.length = 0;
+    //
+    //     console.log('scheduling timeout');
+    //     timeoutReferences.push( phet.axon.timer.setTimeout( behavior, 100 ) );
+    //   }
+    // } );
+    // testCallbackTimer.start();
+
+    let timeoutReference = null;
+    const behavior = () => { console.log( 'behavior function called' ); };
+    const testCallbackTimer = new phet.sun.CallbackTimer( {
+      callback: () => {
+        console.log( 'running' );
+        phet.axon.timer.clearTimeout( timeoutReference )
+        timeoutReference = phet.axon.timer.setTimeout( behavior, 100 );
+      }
+    } );
+    testCallbackTimer.start();
+
+    // Try clearing a timeout before it expires.  No problem.
+    // var x = phet.axon.timer.setTimeout( () => console.log( 'hello' ), 1000 );
+    // phet.axon.timer.clearTimeout( x );
+
+    // we need the listener to appear in defended listeners so it gets called twice
+    // var t = new phet.axon.TinyEmitter();
+    // t.addListener
   } );
 } );
\ No newline at end of file
Index: axon/js/timer.js
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- axon/js/timer.js	(revision 438504b2a8bef22e8525c0eac5589aec8397b940)
+++ axon/js/timer.js	(date 1557414253000)
@@ -20,6 +20,8 @@
   const Emitter = require( 'AXON/Emitter' );
   const axon = require( 'AXON/axon' );
 
+  let index = 0;
+
   class Timer extends Emitter {
 
     /**
@@ -36,10 +38,16 @@
 
         // Convert seconds to ms and see if item has timed out
         if ( elapsed * 1000 >= timeout ) {
+
+          // make sure that the listener hasn't already been removed since we may be calling this callback
+          // from the TinyEmitter activeListenersStack, see https://github.com/phetsims/axon/issues/248
+          // if ( this.hasListener( callback ) ) {
           listener();
           this.removeListener( callback );
+          // }
         }
       };
+      callback.myname = 'hi_there_' + ( index++ );
       this.addListener( callback );
 
       // Return the callback so it can be removed with removeStepListener
@@ -48,12 +56,12 @@
 
     /**
      * Clear a scheduled timeout. If there was no timeout, nothing is done.
-     * @param {function} listener
+     * @param {function} handle - created by setTimeout
      * @public
      */
-    clearTimeout( listener ) {
-      if ( this.hasListener( listener ) ) {
-        this.removeListener( listener );
+    clearTimeout( handle ) {
+      if ( this.hasListener( handle ) ) {
+        this.removeListener( handle );
       }
     }
 
Index: axon/js/TinyEmitter.js
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- axon/js/TinyEmitter.js	(revision 438504b2a8bef22e8525c0eac5589aec8397b940)
+++ axon/js/TinyEmitter.js	(date 1557414253000)
@@ -85,6 +85,10 @@
      * @public
      */
     removeListener( listener ) {
+      console.log( 'removing ' + listener.myname );
+      if ( listener.myname === 'hi_there_1' ) {
+        debugger;
+      }
 
       const index = this.listeners.indexOf( listener );
 

[jessegreenberg]

@jonathanolson and @samreid could you please summarize what the reasons were for calling all listeners present at the start of an emit? I found the question posed in #72 but no documentation about reasoning for the decision.

[samreid]

@jonathanolson described examples in scenery where this behavior was important. My memory is fuzzy--would be great for @jonathanolson to elaborate.

[jonathanolson]

DOM events and other event systems I've worked with do typically have the convention that the array of listeners at the point of the event are the ones that will be notified. I recall some more practical examples of how it's beneficial (and avoids infinite loops if you remove and re-add a listener in a callback), but I'd have to think more on it.

[jessegreenberg]

OK thanks, it sounds like this is a conventional design choice and one we want to keep for most listeners.

But I don't think this is desirable for timer in particular. The example in #248 (comment) is trying to reset the elapsed time before calling a particular listener in a timeout by removing it and adding it back. And in this case that isn't possible because it was added to the activeListenerStack.

@samreid are you OK if we go forward with #248 (comment)?

[samreid]

#248 (comment) looks like an acceptable short term solution (especially if it's blocking progress) and possibly a good long term solution. But I'd like to understand #248 (comment) more, perhaps in a separate dedicated issue. Thoughts?

[jessegreenberg]

Alright, thanks, I added the hasListener check so that we can proceed with phetsims/sun#499 and created #249 for broader discussion about the decision to call all listeners present at the start of an emit. In case discussion in #249 leads us to believe that something else should have been done for this issue I am going to leave this open until then.

[samreid]

In #249 we agreed all listeners present at start of emit should be called, so it seems this issue can be closed. We also discussed in #215 that we would like sim's runtime behavior to be independent of the listener order.