Reporter out of sync with tests being run in browser.

[treshugart]

I'm compiling LESS and ES6 (using 6to5) at runtime and dynamically resolving the CommonJS require() calls in the browser for my tests and as a result, if nothing is cached, it can take awhile to run. It seems that Testee becomes out of sync with the tests. Using the Dot reporter, sometimes I only see 2 dots output to the console, sometimes I see 5, sometimes 6, but the reporter never actually finishes even after the tests have finished running and it only seems to get through a few of them (at most) before hanging.

The command I'm running it with is:

./node_modules/.bin/testee tests/index.html --timeout 600 --browsers chrome --reporter Dot.

I've tried upping the timeout and using different reporters but it doesn't seem to help. Any ideas?

[daffl]

There are two possible solutions:

1. If you are loading the testing library asynchronously you might have to use this client side configuration - basically calling Testee.init() once it is loaded.
2. If you are loading tests asynchronously you have to wait to call mocha.run() or set QUnit.autostart = false; and then call QUnit.start() once they are all loaded (I'm not sure about Jasmine).

For easier debugging I generally use a browser other than PhantomJS and also set the DEBUG=testee:* environment variable which should output a lot more useful information.

[treshugart]

I'm loading everything sync so I shouldn't need to do number 1. I tried just in case and it recurses. However, simply calling Testee.init() doesn't cause it to fail, it's only after I call that and then mocha.run().

I do have to manually call mocha.run() but that's because 6to5 has to process everything first, even if it does it synchronously.

Here's the output from one of the test runs with debugging on:

$ DEBUG=testee:* ./node_modules/.bin/testee tests/index.html --timeout 600 --browsers chrome --reporter Dot
  testee:main running test for +0ms [ 'tests/index.html' ] [ 'chrome' ] { browsers: 'chrome', reporter: 'Dot', timeout: '600' }
  testee:main bootstrapping Testee +2ms
  testee:main starting Testee server +1ms { browsers: 'chrome',
  reporter: 'Dot',
  timeout: '600',
  port: 3996,
  root: '/Users/tshugart/Sites/atlassian/aui',
  adapter: '/testee/',
  delay: 1000,
  tunnel: { type: 'local', port: 3996 },
  launch: { type: 'local' } }
  testee:server initializing Feathers API +0ms
  testee:hosting intializing static file server +8ms /Users/tshugart/Sites/atlassian/aui
  testee:main testee server started and listening +5ms
  testee:main hooking up services to Mocha reporter +0ms
  testee:reporter setting up Mocha command line reporter +0ms
  testee:reporter start +0ms

    testee:main starting up localhost tunnel +0ms { type: 'local', port: 3996 }
  testee:main localhost tunnel started on +1ms http://localhost:3996
  testee:main using browser launcher +0ms local { type: 'local' }
  testee:main browser launcher initialized +0ms
  testee:main setting up test runner +0ms
  testee:main server bootstrapped, running tests. +0ms
  testee:runner running tests for +1ms [ 'tests/index.html' ] [ 'chrome' ]
  testee:runner initializing sequential test runs for browser +0ms chrome
  testee:runner running individual test +1ms http://localhost:3996/tests/index.html?__token=5nib71 { browser: 'chrome' }
  testee:runner browser instance started +26ms { browser: 'chrome' }
  testee:runner tracking test run +0ms http://localhost:3996/tests/index.html?__token=5nib71 { browser: 'chrome' }
  testee:html-injector injecting scripts into file +466ms /tests/index.html?__token=5nib71
  testee:reporter starting run +3s { status: 'running',
  file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  environment: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/39.0.2171.95 Safari/537.36',
  runner: 'Mocha',
  time: 1420497740625,
  id: 'e058e353476ecf76710c80835ef9bd11' }
  testee:runner checking if browser timeout can be reset +4ms http://localhost:3996/tests/index.html?__token=5nib71 true
  testee:reporter starting suite +122ms { status: 'running',
  file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: '',
  pending: false,
  root: true,
  id: '907aeb717213c95527832828827e8b84',
  parent: 'e058e353476ecf76710c80835ef9bd11' }
  testee:reporter starting suite +110ms { status: 'running',
  file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: 'AJS Unit Tests -',
  pending: false,
  root: false,
  parent: '907aeb717213c95527832828827e8b84',
  id: '5eba9240a63bb2acd1d5178f5dc2ba1c' }
  testee:reporter starting suite +114ms { status: 'running',
  file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: 'Core functions -',
  pending: false,
  root: false,
  parent: '5eba9240a63bb2acd1d5178f5dc2ba1c',
  id: '0672a26e1db608165aeed52db9e636ca' }
  testee:reporter starting test +117ms { file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: 'AJS version test',
  async: 0,
  sync: true,
  timedOut: false,
  pending: false,
  type: 'test',
  parent: '0672a26e1db608165aeed52db9e636ca',
  id: 'd7e52fb34ad10424e79941c32e39c6f5' }
  testee:reporter updating test +114ms { file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: 'AJS version test',
  async: 0,
  sync: true,
  timedOut: false,
  pending: false,
  type: 'test',
  parent: '0672a26e1db608165aeed52db9e636ca',
  id: 'd7e52fb34ad10424e79941c32e39c6f5',
  status: 'passed',
  duration: 1,
  state: 'passed',
  speed: 'fast' }

  ․  testee:reporter starting test +111ms { file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: 'alphanum',
  async: 0,
  sync: true,
  timedOut: false,
  pending: false,
  type: 'test',
  parent: '0672a26e1db608165aeed52db9e636ca',
  id: '2e06a629d2c5c11602d210b9546ace02' }
  testee:reporter updating test +121ms { file: 'http://localhost:3996/tests/index.html?__token=5nib71',
  title: 'alphanum',
  async: 0,
  sync: true,
  timedOut: false,
  pending: false,
  type: 'test',
  parent: '0672a26e1db608165aeed52db9e636ca',
  id: '2e06a629d2c5c11602d210b9546ace02',
  status: 'passed',
  duration: 1,
  state: 'passed',
  speed: 'fast' }
․  testee:html-injector injecting scripts into file +31s /tests/yellow.png
  testee:html-injector injecting scripts into file +144ms /tests/red.png
  testee:html-injector injecting scripts into file +146ms /tests/red.png

[daffl]

Yes, looks like the end event is never sent through. Are you getting any errors running it in an actual browser? Can you maybe send an example test suite that's failing (ZIP or GitHub repository? I can definitely have a look.

[treshugart]

Hey, just an update to let you know that I haven't forgotten about this. I just haven't had a chance yet to make any progress on the issue. Probably within the next couple weeks. Thanks again.

[daffl]

Ok, just let me know.

[treshugart]

Hey @daffl. The HTML runner I'm using is at: https://bitbucket.org/atlassian/aui/src/3cff935e663890d085482c93a13def16d938d36d/tests/index.html?at=es6-modules. The files around that - unit.js and bootstrap.js - are also worth looking at.

In the meantime I'll start debugging the issue again from my end. Cheers.

[treshugart]

So, it seems that the CLI reporter lags behind the browser reporter. When the browser encounters an error, failure or whatever, if the CLI is out of sync with the browser (within a few hundred milliseconds which is very likely when running lots of tests) then it hangs. I can reproduce this 100% of the time. I'll add some more info later.

[treshugart]

I also notice that the CLI reporter is really slow right up until the browser finishes. After that it prints everything out pretty quickly.

[daffl]

That it lags behind is probably a SocketIO buffering issue. I noticed that in non-Mocha reporters, too but it doesn't seem to cause any issues (since all events are coming in eventually and in the right order). Did you get a breaking example you could share?

[treshugart]

A complete example would be running our test suite:

1. Clone https://bitbucket.org/atlassian/aui
2. Checkout the AUI-3307 branch
3. Run npm install
4. Run npm test

Initially it will take awhile to compile the ES6 source in the browser and load everything. After the first run it should be pretty quick as it will be cached in local storage.

[treshugart]

So I've changed to not dynamically parsing ES6 and loading test files. The HTML file now loads a single compiled file and runs the tests from there. Startup is much quicker, however I've noticed that the tests now get to the point of spawning the browser window and then just hangs, even after the tests are finished running.

I've tried using Testee.init() and mocha.run() separately, but that only causes the tests to run twice since I'm not loading the tests async.

Here's the debug output:

  testee:main running test for +0ms [ './tests/index.html?grep=aui%2fformat' ] [ 'chrome' ] { browsers: 'chrome' }
  testee:main bootstrapping Testee +2ms
  testee:main starting Testee server +0ms { browsers: 'chrome',
  port: 3996,
  root: '/Users/tshugart/Sites/atlassian/aui',
  reporter: 'Dot',
  adapter: '/testee/',
  timeout: 120,
  delay: 1000,
  tunnel: { type: 'local', port: 3996 },
  launch: { type: 'local' } }
  testee:server initializing Feathers API +1ms
  testee:hosting intializing static file server +8ms /Users/tshugart/Sites/atlassian/aui
  testee:main testee server started and listening +5ms
  testee:main hooking up services to Mocha reporter +0ms
  testee:reporter setting up Mocha command line reporter +0ms
  testee:reporter start +1ms

    testee:main starting up localhost tunnel +0ms { type: 'local', port: 3996 }
  testee:main localhost tunnel started on +0ms http://localhost:3996
  testee:main using browser launcher +0ms local { type: 'local' }
  testee:main browser launcher initialized +1ms
  testee:main setting up test runner +0ms
  testee:main server bootstrapped, running tests. +0ms
  testee:runner running tests for +0ms [ './tests/index.html?grep=aui%2fformat' ] [ 'chrome' ]
  testee:runner initializing sequential test runs for browser +0ms chrome
  testee:runner running individual test +2ms http://localhost:3996/./tests/index.html?grep=aui%2Fformat&__token=2l4e0d { browser: 'chrome' }
  testee:runner browser instance started +28ms { browser: 'chrome' }
  testee:runner tracking test run +0ms http://localhost:3996/./tests/index.html?grep=aui%2Fformat&__token=2l4e0d { browser: 'chrome' }
  testee:html-injector injecting scripts into file +469ms /tests/index.html?grep=aui%2Fformat&__token=2l4e0d

...and it just stops there. It eventually times out. You can see the code at https://bitbucket.org/atlassian/aui/src/c64e5d665e9f15d169fd85b1c282ad59132f02f1/tests/?at=AUI-3307.

Sorry for the issues; I'm probably just doing something stupid.

[kevinbarabash]

I've had issues where the browser wasn't talking to the testee. The problem was that I wasn't starting mocha in a onload handler. I don't know what's inside "../.tmp/test.js" but try putting following in a <script> tag at the end of <body>:

onload = function(){
   mocha.run();
};

[treshugart]

That works, but unfortunately I still get the same issue as originally described. Have you guys tested this on really long running, large test suites? Not being snarky, legit question. I can't for the life of me figure out what's wrong.

[treshugart]

Maybe it's something at our test level, but I haven't been able to figure it out yet and Karma seems to work. I just noticed something odd, though. The "alignment" test gets reported on the CLI (sometimes it reports the pass / failure status and sometimes not), but it's not reported in the HTML runner.

EDIT

It also doesn't seem to matter what tests I run. If I comment out the first two tests then it still only gets a couple tests in and stops.

[kevinbarabash]

@treshugart I cloned your repo and checked out the AUI-3307 branch but there's no index.html in tests/. I would copy the index.html from the link you provided above but there's also no test.js in ../.tmp. I tried building it using the gulp command from the README.md, but I ended up with this error:

[07:56:16] 'js:build' errored after 14 s
[07:56:16] Error: ENOENT, no such file or directory 'dist-i18n/aui.properties.js'

[daffl]

@treshugart I will check the repository out and have a look, too. The CanJS tests run fairly long (~3 minutes each) and I didn't see those issues but they are also using QUnit. We have a client project with a Mocha FuncUnit test suite that runs at about 10 minutes as well.

What exactly is the process again to get the compiled tests running to reproduce the issue?

[treshugart]

Those instructions referred to an earlier commit, sorry guys. You got the errors because I since moved to back to Karma to get the tests running and CI back up. The tests require a build step for the i18n files (don't judge us :P) which need to be run before the tests are built which is why you got the i18n error.

At this stage, if the CanJS tests run fine in it I will assume that it's something having to do with our tests. There's a shit-ton of legacy code in the there (and elsewhere) and something may have gotten lost in translation when moving from Qunit to Mocha.

Thanks for all your help and sorry if some of my questions were a bit noob. It would be worth documenting the onload quirk, though, if that's intended behavior. I'll continue to try and spot the issue but not at the expense of your time. I'll update this if I find anything useful. Hopefully we can use this someday because the API and integration is worlds better than Karma's.

Cheers! On 20 Feb 2015 2:23 am, "David Luecke" notifications@github.com wrote:

@treshugart https://github.com/treshugart I will check the repository out and have a look, too. The CanJS tests run fairly long (~3 minutes each) and I didn't see those issues but they are also using QUnit. We have a client project with a Mocha FuncUnit test suite that runs at about 10 minutes as well.

What exactly is the process again to get the compiled tests running to reproduce the issue?

— Reply to this email directly or view it on GitHub https://github.com/bitovi/testee/issues/43#issuecomment-75070134.

[Macrofig]

Just wanted to add a note to this as I think we have the same problem with our test suite. We've traced it down to the use of a mock clock (jasmine's clock, in our case) which causes problems with Socket.io.

Basically, any time we have to do an ajax call, we create fixtures that mimic our REST server. To help our tests run quickly, we use Jasmine's clock to remove the delayed response from our fixtures. The clock hijacks the browser setTimeout which socket io uses to send updates to Feathers (which is what Testee uses to sync between the browser and the command line).

For example @treshugart, I saw this line in your code: https://bitbucket.org/atlassian/aui/src/c64e5d665e9f15d169fd85b1c282ad59132f02f1/tests/unit/aui/restful-table.js?at=AUI-3307&fileviewer=file-view-default#restful-table.js-133 I'm no Sinon expert but is it possible that creating a server here also hijacks the setTimeout? ¯(ツ)/¯

Anyway, I'm glad we're not the only ones running into this.

[andrejewski]

@Macrofig Sinon has a fake server with a clock mechanism however this is not what is used in a plain fakeServer.create() from what I can tell. Overrides of global behaviors are out of scope of Testee and should probably be raised in either Socket.io or Jasmine/Sinon if these are problematic.

@treshugart Were there any more developments on your end?

[treshugart]

Nah, I haven't worked on this for awhile. Sorry :(

[andrejewski]

@treshugart You, sir, are beautiful. That was a much faster reply than I could have expected. I am closing this as there is little we can do from inside of Testee to prevent misuse of JS globals, which I think is the problem here.