CT countProperty should match array length

[KatieWoe]

projectile-motion : phet-io-state-fuzz : unbuilt
https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/phet-io-wrappers/state/?sim=projectile-motion&phetioDebug&fuzz&wrapperContinuousTest=%7B%22test%22%3A%5B%22projectile-motion%22%2C%22phet-io-state-fuzz%22%2C%22unbuilt%22%5D%2C%22snapshotName%22%3A%22snapshot-1589811061330%22%2C%22timestamp%22%3A1589812894420%7D
Uncaught Error: Assertion failed: countProperty should match array length.
Error: Assertion failed: countProperty should match array length.
at window.assertions.assertFunction (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/assert/js/assert.js:22:13)
at https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/tandem/js/PhetioGroup.js:69:9
at TinyEmitter.emit (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/axon/js/TinyEmitter.js:69:53)
at https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/axon/js/Emitter.js:33:29
at Emitter.execute (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/axon/js/Action.js:225:18)
at Emitter.emit (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/axon/js/Emitter.js:58:19)
at PhetioStateEngine.setState (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/phet-io/js/PhetioStateEngine.js:215:26)
at PhetioEngineIO.implementation (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/phet-io/js/PhetioEngineIO.js:221:43)
at PhetioCommandProcessor.processCommand (https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/phet-io/js/phetioCommandProcessor.js:267:51)
at https://bayes.colorado.edu/continuous-testing/ct-snapshots/1589811061330/phet-io/js/phetioCommandProcessor.js:160:36
id: Bayes Chrome
Snapshot from 5/18/2020, 8:11:01 AM

[jbphet]

This is phet-io-related, so off to @zepumph it goes.

[zepumph]

Thanks. This has come up as a result of https://github.com/phetsims/phet-io/issues/1668, and is very nice to see, as it means an assertion is working as exposing potentialy pre-existing state problems. I dove into this briefly and didn't find it to be an easy fix.

Things to note for later in the week when I have time to devote to it:

• Coming from TrajectoryGroup, not the Node group. For a second I thought It may have been a listener order issue between PhetioDynamicElementContainer undeferring notifications and PhetioGroup asserting countProperty length based on the same emitter.
• Count is consistently 1, and the array length is 3.
• Looks like nothing is being deferred for disposal during set state, which was my first guess based on the preceding bullet.
• I noticed that there is consistently one Trajectory who's notification is being flushed when undeferring, instead of eagerly during stateProcessor step. This makes sense, and potentially is fine, but we should investigate if that is the desired behavior.

[zepumph]

Count is consistently 1, and the array length is 3.

The first numbers I just got when coming back to this was 3 and 4. . .

[zepumph]

Wow. I finally found the issue, but it took a bit to figure out how to find the problem. Steps to reproduce if you remove the above commit:

1. Add a debugger in assert.js to catch the error in the act.
2. Then go up the stack to the phetioStateEngine and copy the state out to a scrap file. Also copy phetioStateEngine.mostRecentSavedState, because it wasn't enough to just have the state, it was the combination of the current state and the state to be setting to.
3. Go to studio and download a copy of the sim. Then move it studio/ for testing in the browser without needing to build it.
4. Edit the wrapper such that it doesn't just set one state, but first sets the mostRecentSavedState, and then sets the next state. This made for an easily reproduceable case
5. Then I noticed that in this case, the count expected 2, but found 3 Trajectories. This meant I could go to PhetioGroup.createIndexedElement and put a debugger when the index was 3. I then found the stack trace for why I was getting an extra Trajectory which brought me to the above listeners.

I will keep this open and make sure CT is clear tomorrow.

[zepumph]

Looks fixed on CT!