console.* functions called outside tests are not output when singleRun is false

[tbhartman]

Expected behaviour

Using client.captureConsole = true, I expect all console.* calls to output to the terminal.

d:\karma_captureConsole_bug> karma start
Chrome 68.0.3440 (Windows 10 0.0.0) INFO: 'I am outside of test!'

LOG: 'I am inside of test!'
Chrome 68.0.3440 (Windows 10 0.0.0): Executed 1 of 1 SUCCESS (0.007 secs / 0.001 secs)
TOTAL: 1 SUCCESS

Actual behaviour

Only console.* calls occurring while running a test are output to the terminal

d:\karma_captureConsole_bug> karma start
LOG: 'I am inside of test!'
Chrome 68.0.3440 (Windows 10 0.0.0): Executed 1 of 1 SUCCESS (0.007 secs / 0.001 secs)
TOTAL: 1 SUCCESS

Environment Details

• Karma version (output of karma --version): 3.0.0

karma.conf.js:

module.exports = (config) => {
  config.set({
    client: {captureConsole: true},
    frameworks: ['jasmine', 'requirejs'],
    files: ['karma.test.js', 'script.js'],
    browsers: ['Chrome'],
    singleRun: false,
  })
};

karma.test.js:

require.config({
  deps: ['script'],
  callback: window.__karma__.start
});

script.js:

define('script', [], function(){
  console.info('I am outside of test!');
  it('test1', function(){
    console.log('I am inside of test!');
  });
});

Steps to reproduce the behaviour

1. put above karma.conf.js, karma.test.js, script.js in a directory
2. run karma start to see actual behavior
3. change karma.conf.js so that singleRun is true to observe expected behavior

[johnjbarton]

With your singleRun: false setup and no browser set to a karma server URL, issue the karma start command. Of course you should see no logging. Now open a new tab, and open the browser devtools. Then paste the karma server URL. Now you can debug the code path for the outside of the test call.

I guess this is an issue with karma-requirejs project or perhaps karma-jasmine.

[tbhartman]

I've confirmed the issue when removing karma-requirejs...I'll check with karma-jasmine.

[pascalpp]

fwiw I'm having this same issue when using karma-mocha as well. console.logs outside of it callbacks are only output when singleRun is true. This was working regardless of the singleRun value when we were using [email protected]. We recently made the jump to [email protected] as part of an upgrade to webpack@4, which is when I noticed this issue. I'm not convinced it has anything to do with the framework adapter (karma-jasmine or karma-mocha), but I'm not intimate with how karma works internally so that's just a hunch, need to dig some more. @tbhartman were you able to find a resolution?

[pascalpp]

using a test file with:

console.log('outside describe')
describe('describe block', function() {
    console.log('inside describe')
    it('it block', function() {
        console.log('inside it')
    })
})

and stepping through the karma versions, I've narrowed down this behavior change as occurring between v2.0.4 and v2.0.5.

in 2.0.4:

START:
PhantomJS 2.1.1 (Mac OS X 0.0.0) LOG: 'outside describe'
PhantomJS 2.1.1 (Mac OS X 0.0.0) LOG: 'inside describe'
LOG: 'inside it'

in 2.0.5:

START:
LOG: 'inside it'

I'll try to compare those releases to see if I can narrow it down further.

[pascalpp]

Narrowed it down to this commit: dc7265b which refactored the READY/CONNECTED state of the browser class.

[pascalpp]

Tinkering in that commit, if I disable the isConnected() check in Browser#onInfo, like so:

  onInfo (info) {
    // if (this.isConnected()) {
    //   return
    // }

...then the logs outside of it blocks are shown in my console even with singleRun: false. I see that in the most recent version, that check has changed to check if (this.isNotConnected()) {.

@johnjbarton can you tell me what purpose that check serves? My understanding is that it's ignoring logs generated during the 'configuring' state. That is, while the spec is being parsed, but before the tests actually start running, it's not emitting the browser_info event so those logs don't appear. It seems to me that those logs should be surfaced regardless of the singleRun setting. (First time really looking at karma source so forgive my naïveté.)

[johnjbarton]

Unfortunately isNotConnected() is confusing; we intended isNotInConnectedState() but I think we should have called it isClientActive().

The code you cite above, from Browser#onInfo, does not match what I see at HEAD:
https://github.com/karma-runner/karma/blob/master/lib/browser.js#L52

When I look at my own test case for global (pre-test) errors, I see events in browser.onKarmaError:
https://github.com/karma-runner/karma/blob/master/lib/browser.js#L43

The info vs error part is determined by the framework adapter code, eg karma-jasmine karma-runner/karma-jasmine#217

[johnjbarton]

Ok I looked into this with our setup and I found that I needed to change Browse.onKarmaError:

onKarmaError (error) {
    if (this.isNotConnected()) {
      this.lastResult.error = true
    }
    this.emitter.emit('browser_error', this, error)
    this.refreshNoActivityTimeout()
  }

I also had to change our reporter to log the error in this case. We have a custom reporter.

I will try to apply this change to karma-runner, but perhaps you can try it and see if it helps.

[pascalpp]

I made a little POC repo https://github.com/pascalpp/karma-console-test and modified that part of lib/browser in place (after installing node_modules). I'm still not seeing the logs after that modification.

[johnjbarton]

Thanks, I tried the repo but

 ./node_modules/karma/bin/karma start
07 11 2018 07:13:18.826:ERROR [karma-server]: Server start failed on port 9876: Error: Cannot find module 'mocha'

[johnjbarton]

install mocha fixes it.

[johnjbarton]

With --logLevel=debug I get

07 11 2018 07:16:54.955:DEBUG [web-server]: serving: /work/karma-console-test/node_modules/karma/static/context.js
07 11 2018 07:16:55.004:DEBUG [phantomjs.launcher]: I am outside of test!

07 11 2018 07:16:55.005:DEBUG [phantomjs.launcher]: I am inside of describe!

07 11 2018 07:16:55.010:DEBUG [phantomjs.launcher]: I am inside of it!

LOG: 'I am inside of it!'
PhantomJS 2.1.1 (Mac OS X 0.0.0): Executed 1 of 1 SUCCESS (0.004 secs / 0 secs)
TOTAL: 1 SUCCESS

[johnjbarton]

The phantomjs.launcher output is just stdout from chrome.

[johnjbarton]

Ok so the issue here is that with singleRun=false the logging arrives in browser.state==1; with singleRun=true the logging arrives in browser.state==2.

[pascalpp]

(oops sorry, forgot to include mocha in the deps, fixed now.)

so the issue here is that with singleRun=false the logging arrives in browser.state==1; with singleRun=true the logging arrives in browser.state==2.

Is that expected, or should it be browser.state == 2 in both cases?

[johnjbarton]

Under singleRun=false we don't call browser.execute():
https://github.com/karma-runner/karma/blob/master/lib/server.js#L248

So we don't enter browser.state=CONFIGURING. Unfortunately the state tracks what the server told the browser to do, rather than the state the browser reports to the server.

I don't see a reason to filter errors based on browser.state. Testing the singleRun=false is hard because the server has to be forced to exit by the test during the test. I'll take one more pass at that.