CT race condition assigns results to the wrong repo about aqua HOT 20 CLOSED

This happened today with acid-base-solutions, see phetsims/acid-base-solutions#157. Thank you @phet-steele or I would have wasted more time than I did on this. He chimed in on Slack:

When CT is maybe running a little slow, it switches tests faster than it gets results. In other words, fluid-pressure-and-flow would have errored, but before that error could be "linked" to the current test, CT switched to acid-base-solutions. It's basically a race situation (when CT is running slow). That's at least how I remember it being explained to me. this used to happen ALL the time

So I'm going to retitle this issue, and label it for dev meeting so that we can understand how significant this "race condition" is, and hopefully get it fixed.

from aqua.

Basically there's a slight race condition so if the timing is just right, it shows up in the wrong place. Presumably if I'm deep into CT code again I'll fix it.

from aqua.

@KatieWoe if you're not already aware of this weirdness in CT, FYI.

from aqua.

Thanks @pixelzoom. I saw on slack so I know the gist of what's happening

from aqua.

This happened again with one of my sims today. A charges-and-fields problem was reported for function-builder-basics:

function-builder-basics : fuzz : require.js-canvas : run
Query: brand=phet-io&phetioStandalone&ea&phetioValidateTandems&fuzz&memoryLimit=1000
Uncaught Error: Assertion failed: phetioID already registered: chargesAndFields.chargesAndFieldsScreen.view.element_1.visibleProperty
Error: Assertion failed: phetioID already registered: chargesAndFields.chargesAndFieldsScreen.view.element_1.visibleProperty
    at window.assertions.assertFunction (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/assert/js/assert.js:22:13)
    at PhetioEngine.phetioObjectAdded (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/phet-io/js/phetioEngine.js?bust=1553757336549:347:36)
    at Object.addPhetioObject (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/phet-io/js/phetioEngine.js?bust=1553757336549:434:51)
    at Tandem.addPhetioObject (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/tandem/js/Tandem.js?bust=1553757336549:126:40)
    at NodeProperty.register (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/tandem/js/PhetioObject.js?bust=1553757336549:294:19)
    at NodeProperty.initializePhetioObject (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/tandem/js/PhetioObject.js?bust=1553757336549:281:12)
    at new PhetioObject (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/tandem/js/PhetioObject.js?bust=1553757336549:129:12)
    at new Property (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/axon/js/Property.js?bust=1553757336549:70:7)
    at new NodeProperty (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/scenery/js/util/NodeProperty.js?bust=1553757336549:31:7)
    at new NodeIO (https://bayes.colorado.edu/continuous-testing/snapshot-1553735327436/scenery/js/nodes/NodeIO.js?bust=1553757336549:33:27)
id: Bayes Chrome
Approximately 3/27/2019, 9:11:48 PM

from aqua.

... and another one of my sims yesterday. An energy-skate-park problem was reported for ph-scale-basics:

ph-scale-basics : xss-fuzz : run
Query: brand=phet&ea&fuzz&rootRenderer=canvas&memoryLimit=1000
Uncaught Error: Assertion failed: Thermal energy should be non-negative: skaterState: [object Object], initialEnergy: -0.00021981084605969582, proposedPosition: Vector2(-5.668592797764344, 0), proposedVelocity: Vector2(2.0002435407868566e-17, -0.16333333333333333), dt: 0.016666666666666666, newSpeed: 2.0002435407868566e-17, newKineticEnergy: 1.2503044445186067e-32, newPotentialEnergy: 0, newThermalEnergy: -0.00021981084605969582, referenceHeight: 0, tracked in https://github.com/phetsims/energy-skate-park/issues/45
Error: Assertion failed: Thermal energy should be non-negative: skaterState: [object Object], initialEnergy: -0.00021981084605969582, proposedPosition: Vector2(-5.668592797764344, 0), proposedVelocity: Vector2(2.0002435407868566e-17, -0.16333333333333333), dt: 0.016666666666666666, newSpeed: 2.0002435407868566e-17, newKineticEnergy: 1.2503044445186067e-32, newPotentialEnergy: 0, newThermalEnergy: -0.00021981084605969582, referenceHeight: 0, tracked in https://github.com/phetsims/energy-skate-park/issues/45
    at window.assertions.assertFunction (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/assert/js/assert.js:22:13)
    at PlaygroundModel.switchToGround (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/energy-skate-park/js/energy-skate-park/common/model/EnergySkateParkModel.js?bust=1553722622112:493:17)
    at PlaygroundModel.stepFreeFall (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/energy-skate-park/js/energy-skate-park/common/model/EnergySkateParkModel.js?bust=1553722622112:528:21)
    at PlaygroundModel.stepTrack (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/energy-skate-park/js/energy-skate-park/common/model/EnergySkateParkModel.js?bust=1553722622112:990:21)
    at PlaygroundModel.stepModel (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/energy-skate-park/js/energy-skate-park/common/model/EnergySkateParkModel.js?bust=1553722622112:1300:39)
    at PlaygroundModel.step (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/energy-skate-park/js/energy-skate-park/common/model/EnergySkateParkModel.js?bust=1553722622112:398:31)
    at first (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/joist/js/Sim.js?bust=1553722622112:213:24)
    at Emitter.emit (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/axon/js/Emitter.js?bust=1553722622112:280:55)
    at EnergySkateParkBasicsSim.stepSimulation (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/joist/js/Sim.js?bust=1553722622112:916:34)
    at EnergySkateParkBasicsSim.stepOneFrame (https://bayes.colorado.edu/continuous-testing/snapshot-1553717011928/joist/js/Sim.js?bust=1553722622112:897:14)
id: Bayes Chrome
Approximately 3/27/2019, 2:03:31 PM

from aqua.

Slack:

Chris Malley [1:01 PM]
The “CT race condition” problem #49 has hit my sims multiple times this week. Prior to this, I’ve never seen it before. Maybe I was just lucky, or maybe something has changed. @jonathanolson has anything changed that might make this happen more frequently?

Jonathan Olson [1:02 PM]
Not sure, maybe bayes is overloaded a bit.

from aqua.

This is getting ridiculous. There was an issue in Molarity SolutionDescriber today. It showed up in build-a-fraction, estimation, gene-expression-essentials, and rutherford-scattering.

from aqua.

@ariel-phet This seems like it should be a priority. We lean heavily on CT and depend on the integrity of its results. For some reason, this "race condition" has gotten worse in the past week or so. I’m wasting time investigating non-issues, and I’m wondering what real issues are being reported somewhere I’m not looking.

from aqua.

Slack:

Chris Malley [10:04 AM]
@jonathanolson can you briefly describe the “race condition”?

Jonathan Olson [10:07 AM]
Sometimes the cross-frame messaging (from the script that loads simulations) takes a bit, so it will have loaded a new sim by the time the error message propagates, so it incorrectly records the error on the wrong sim

Sam Reid [10:07 AM]
Maybe that can be solved by sending the name of the sim with the error message?

Jonathan Olson [10:07 AM]
it would probably mean we'd need to add more sim-side logic, as we want to make sure it's actually running the same test (not just the same sim)

Sam Reid [10:08 AM]
To elaborate, perhaps sending the name of the sim and the ID of the SHAs.
Right, and name/parameters of test as well

from aqua.

Restarting Chrome processes seems to have reduced the frequency of this problem, so lowering priority from 'top' to 'high'.

from aqua.

In a face-to-face conversation yesterday, @KatieWoe mentioned to me that this is impacting her ability to report CT issues. It's difficult to know whether an error is legitimate, whether to create an issue, and which repo to create the issue for.

from aqua.

This happened in 4/3/2019, 7:35:48pm SHAs, charges and fields showed up in vibe.

from aqua.

Just a thought I had, don't know if there is any merit... Some A11y related unit tests are using await and timeouts to test timing related features. Could this kind of thing interfere with CT reporting or reporting to the wrong place?

from aqua.

@jonathanolson said that QUnit has 400 seconds to finish tests and as long as tests finish before then we should be OK.

from aqua.

@samreid will spend 4-8 hours next week collaborating with @jonathanolson after he has done initial investigation.

Dev team is on board for making multiple node.js functionality live in perennial (and have aqua and yotta depend on perennial).

from aqua.

From today's discussion:

OK to port to ES6, including but not limited to async await
OK to work on improving the portability/developability of CT

from aqua.

We added passing of the test information through to the individual test wrapper iframe, so that it can be passed back and included as the source of the pass/fail report. This should prevent the anticipated race condition.

We'll plan to wait and inspect continuous testing in a few days.

from aqua.

De-escalating priority and unassigning while we evaluate whether the problem occurs again.

from aqua.

Slack:

Chris Malley 10:08 AM
We used to have a problem were CT failures were assigned to the wrong repos. I haven't seen this problem since CT was overhauled. Does anyone object to me closing this issue? #49

Sam Reid 10:12 AM
I agree it can be closed

from aqua.