Testem Chrome Timeouts

This issue has been tracked since 2016-11-19.

Hey,

as I mention in #1015 we frequently get testem failures in CI when running against the Chrome (we use Testem through Ember CLI). Our test runs either fail to start (as if testem can't find the browser) or fail to finish (all tests have run and pass, but the browser window sits there and it eventually times out). It usually just tells us testem.js has not loaded.

As the issue is intermittent it can be hard to reproduce. I've tried to recreate it in a repo by simply forking Travis CI's web repo (uses Ember CLI) and adding ember-exam to it (Ember Exam just allows you to easily use Testem's parallel feature). If running a single test run it'd probably take some time to get a timeout, but if you run ember exam --split=9 --parallel you should start getting some timeouts in a few runs.

I've generated some (pretty verbose) logs here.

Generally on startup I've seen the following errors:

not ok 323 Chrome - error
    ---
        message: >
            Error: Browser failed to connect within 30s. testem.js not loaded?
            Stderr:
             2016-11-19 00:42:01.877 Google Chrome[28575:622538] NSWindow warning: adding an unknown subview: <FullSizeContentView: 0x7fa45b8022a0>. Break on NSLog to debug.
            2016-11-19 00:42:01.878 Google Chrome[28575:622538] Call stack:
            (
                "+callStackSymbols disabled for performance reasons"
            )


        Log: |
            { type: 'error',
              text: 'Error: Browser failed to connect within 30s. testem.js not loaded?' }
            { type: 'error',
              text: '2016-11-19 00:42:01.877 Google Chrome[28575:622538] NSWindow warning: adding an unknown subview: <FullSizeContentView: 0x7fa45b8022a0>. Break on NSLog to debug.\n2016-11-19 00:42:01.878 Google Chrome[28575:622538] Call stack:\n(\n    "+callStackSymbols disabled for performance reasons"\n)\n' }
    ...

On timeouts at the end I've seen

  engine:ws writing "3" +1ms
  engine:polling closing +649ms
  engine:polling transport not writable - buffering orderly close +0ms
  socket.io:client client close with reason ping timeout +0ms
  socket.io:socket closing socket - reason ping timeout +0ms
  engine:polling closing +8ms
  engine:polling transport not writable - buffering orderly close +1ms
  socket.io:client client close with reason ping timeout +0ms
  socket.io:socket closing socket - reason ping timeout +0ms
  engine:polling closing +654ms
  engine:polling transport not writable - buffering orderly close +0ms
  socket.io:client client close with reason ping timeout +0ms
  socket.io:socket closing socket - reason ping timeout +0ms
  engine:polling closing +78ms
  engine:polling transport not writable - buffering orderly close +0ms
  socket.io:client client close with reason ping timeout +0ms
  socket.io:socket closing socket - reason ping timeout +0ms
  engine:polling closing +5s
  engine:polling transport not writable - buffering orderly close +0ms
  socket.io:client client close with reason ping timeout +0ms
  socket.io:socket closing socket - reason ping timeout +0ms
  engine:polling closing +2s
  engine:polling transport not writable - buffering orderly close +0ms
  socket.io:client client close with reason ping timeout +0ms
  socket.io:socket closing socket - reason ping timeout +0ms
not ok 205 Chrome - error
    ---
        message: >
            Error: Browser disconnected
            Stderr:
             2016-11-19 00:49:10.060 Google Chrome[28965:629220] NSWindow warning: adding an unknown subview: <FullSizeContentView: 0x7fa7a07af8a0>. Break on NSLog to debug.
            2016-11-19 00:49:10.061 Google Chrome[28965:629220] Call stack:
            (
                "+callStackSymbols disabled for performance reasons"
            )


        Log: |
            { type: 'error', text: 'Error: Browser disconnected' }
            { type: 'error',
              text: '2016-11-19 00:49:10.060 Google Chrome[28965:629220] NSWindow warning: adding an unknown subview: <FullSizeContentView: 0x7fa7a07af8a0>. Break on NSLog to debug.\n2016-11-19 00:49:10.061 Google Chrome[28965:629220] Call stack:\n(\n    "+callStackSymbols disabled for performance reasons"\n)\n' }
    ...
  socket.io:client client close with reason transport close +8s
  socket.io:socket closing socket - reason transport close +0ms

Other things to note:

  • we've been experiencing this for a while now, through multiple versions of Chrome, Node and Testem. Currently running latest Chrome, Testem 1.13 and Node 7.
  • We have a large codebase (~150K LOC) so not sure if that amplifies the issue or not.

/cc @stefanpenner (as we chatted briefly about this)

johanneswuerbach wrote this answer on 2016-11-20

@patocallaghan first thing after looking into your repo, are you sure each browser instance starts in < 30s? This is the default start timeout and it was causing a bunch of browsers to fail for me.

You can tweak this in your config browser_start_timeout https://github.com/testem/testem/blob/master/docs/config_file.md#config-level-options

Depending on your code base and machine the default might be to small as this timeout is the time between spawn and the browser finished parsing and reconnects to the testem server.

johanneswuerbach wrote this answer on 2016-11-20

Once testem successfully started, it should always close and I would consider this a bug, but can't really reproduce it yet :-(

patocallaghan wrote this answer on 2016-11-24

@johanneswuerbach tried what you suggested with increasing the browser startup timeout but it didn't work. I'm still getting testem failing to start.

With regards this error here:

not ok 1 Browser "google-chrome --user-data-dir=/tmp/testem-2441 --no-default-browser-check --no-first-run --ignore-certificate-errors --test-type --disable-renderer-backgrounding --disable-background-timer-throttling http://localhost:7357/2441/tests/index.html?hidepassed&filter=team%20observe%20%7C" failed to connect. testem.js not loaded?

where would this be thrown from? I can't find any string in the codebase that matches failed to connect. testem.js not loaded?

patocallaghan wrote this answer on 2016-11-24

@johanneswuerbach so I tried to look a little bit more into it and I saw the below error

not ok 1 Chrome - error
    ---
        message: >
            Error: Browser failed to connect within 60s. testem.js not loaded? HELLO
            Stderr:
             [58095:58095:1124/113207:ERROR:browser_main_loop.cc(261)] Gtk: Locale not supported by C library.
                Using the fallback 'C' locale.
            Xlib:  extension "RANDR" missing on display ":99".
            Xlib:  extension "RANDR" missing on display ":99".
            [58095:58118:1124/113207:ERROR:proxy_service_factory.cc(128)] Cannot use V8 Proxy resolver in single process mode.
            [58095:58118:1124/113207:ERROR:proxy_service_factory.cc(128)] Cannot use V8 Proxy resolver in single process mode.


        Log: |
            { type: 'error',
              text: 'Error: Browser failed to connect within 60s. testem.js not loaded? HELLO' }
            { type: 'error',
              text: '[58095:58095:1124/113207:ERROR:browser_main_loop.cc(261)] Gtk: Locale not supported by C library.\n\tUsing the fallback \'C\' locale.\nXlib:  extension "RANDR"missing on display ":99".\nXlib:  extension "RANDR" missing on display ":99".\n[58095:58118:1124/113207:ERROR:proxy_service_factory.cc(128)] Cannot use V8 Proxy resolver in single process mode.\n[58095:58118:1124/113207:ERROR:proxy_service_factory.cc(128)] Cannot use V8 Proxy resolver in single process mode.\n' }
    ...

I'm not sure about the Chrome error itself but interestingly Testem hung after this was thrown and didn't automatically close. It stayed open indefinitely. I wonder is there some codepath being exercised when this type of error his hit where it doesn't close the process?

avdv wrote this answer on 2017-01-03

Hi.

We have the same problem. Chrome just open the window and the tab spinner is running, but it seems it cannot load the page from localhost:33062/921/tests/index.html. We're using ember-cli too.

We have set the timeout to 180 seconds, but still no dice. 😭

Firefox on the other hand just works, but Chrome starts only 1/50 times. Chrome only show the Xlib: extension "RANDR" missing on display warning message.

I used x11vnc to have a look at the Xvfb display via SSH, and now chrome immediately displays the "Aw Snap, something went wrong while loading the page" error message. I've tried version 54 and 55.

When I reload the page and open the devtools, I can see that loading the 10.6 MiB resources of the page takes 2.5 minutes to finish (whereas firefox only takes a few seconds). So, after setting the timeout to ridiculous 300 seconds, chrome actually starts to run the tests...

johanneswuerbach wrote this answer on 2017-01-03

Could you inspect the network traffic, whether some websocket traffic is done during that time? Maybe testem client / server are in an endless loop for some reason.

cs3b wrote this answer on 2017-03-01

I've the same issue with Firefox ... and it only is a problem in Travis CI (not sure why), locally works fine, here are the logs from Travis Ci

$ export DISPLAY=:99.0

$ sh -e /etc/init.d/xvfb start
Starting virtual X frame buffer: Xvfb.

$ sleep 3

$ firefox --version
Mozilla Firefox 53.0a2

$ node_modules/ember-cli/bin/ember test
Could not start watchman
Visit https://ember-cli.com/user-guide/#watchman for more info.
Building
cleaning up
cleaning up...
Built project successfully. Stored in "/home/travis/build/Selleo/selleo-mail-log/tmp/core_object-tests_dist-MidNYxQe.tmp".
not ok 1 Firefox - error
    ---
        message: >
            Error: Browser failed to connect within 300s. testem.js not loaded?
            Stderr: 
             ExceptionHandler::GenerateDump cloned child 3172
            ExceptionHandler::SendContinueSignalToChild sent continue signal to child
            ExceptionHandler::WaitForContinueSignal waiting for continue signal...
            
            
        Log: |
            { type: 'error',
              text: 'Error: Browser failed to connect within 300s. testem.js not loaded?' }
            { type: 'error',
              text: 'ExceptionHandler::GenerateDump cloned child 3172\nExceptionHandler::SendContinueSignalToChild sent continue signal to child\nExceptionHandler::WaitForContinueSignal waiting for continue signal...\n' }
    ...

and here is the travis ci config



{
  "language": "node_js",
  "node_js": "6",
  "env": "CXX=g++-4.8",
  "addons": {
    "apt": {
      "sources": [
        "ubuntu-toolchain-r-test"
      ],
      "packages": [
        "g++-4.8"
      ]
    },
    "firefox": "latest-dev"
  },
  "sudo": false,
  "cache": {
    "directories": [
      "$HOME/.npm",
      "$HOME/.yarn-cache",
      "$HOME/.cache"
    ]
  },
  "before_install": [
    "npm config set spin false",
    "npm install -g yarn"
  ],
  "install": [
    "yarn install",
    "node_modules/bower/bin/bower install"
  ],
  "before_script": [
    "export DISPLAY=:99.0",
    "sh -e /etc/init.d/xvfb start",
    "sleep 3",
    "firefox --version"
  ],
  "script": [
    "node_modules/ember-cli/bin/ember test"
  ],
  "group": "stable",
  "dist": "precise",
  "os": "linux"
}

might be that the problem is within travis ci itself - still hard to debug. So far the only solutions is to go back to PhantomJS.

YoranBrondsema wrote this answer on 2017-04-12

@patocallaghan Have you had any luck fixing this? Or any new information that came up? We're seeing the same issues (tests won't start about 1/2 of the time, on Chrome) and it's really hampering productivity as you can imagine.

  1. It happens more often that the test do not start all, with the Browser failed to connect within 30s. testem.js not loaded? message
  2. It happens that the tests hang at the end, despite having run them all. But this happens only occasionally so I'd rather focus on 1.

I'm really trying to get this fixed but it's not easy as we use Codeship as CI so we don't control the environment, and it doesn't always happen. Most fun bugs... :( So anything new that you discovered would be welcome!

ghempton wrote this answer on 2017-04-12

This same issue happens for us on CircleCI. About 1/10 builds fail to launch with Browser failed to connect within 30s. testem.js not loaded.

johanneswuerbach wrote this answer on 2017-04-13

I didn't had any luck tracking this down yet, especially as this mainly happens only on CI and isn't really reliable reproducable.

Hopefully chrome headless https://www.chromestatus.com/features/5678767817097216 will bring together with remote debugging better debugging in those environments

mani-mishra wrote this answer on 2017-04-19

We are using ember exam and also seeing similar issues with our Team City build server.
The error message is slightly different though.

[Chrome - error] Error: Browser failed to connect within 30s. testem.js not loaded?
Stderr: 
 [0419/061938.039012:WARNING:audio_manager.cc(321)] Multiple instances of AudioManager detected
[0419/061938.039065:WARNING:audio_manager.cc(278)] Multiple instances of AudioManager detected
[0419/061938.371223:ERROR:socket_posix.cc(126)] bind() returned an error, errno=98: Address already in use
[0419/061938.371271:ERROR:devtools_http_handler.cc(221)] Cannot start http server for devtools. Stop devtools.
johanneswuerbach wrote this answer on 2017-04-19

It would be great to get the chrome debug console output in those cases, maybe using the remote debugger are somehow manually.

Looks like in some cases the initial connect takes >30s with can have multiple reasons: unparsable js, slow js parsing, failed websocket, testem client bug, etc.

Sadly there isn't much, which can be done before connecting (as there is obviously no connection), but maybe the remote debug protocol could provide some access to the console output

YoranBrondsema wrote this answer on 2017-04-19

@manimis902 Are you running headless Chrome? In that case, your error might be an issue in Chrome itself (see https://bugs.chromium.org/p/chromium/issues/detail?id=678948).

mani-mishra wrote this answer on 2017-04-19

@YoranBrondsema Yes we are using chrome headless. I landed on the chromium issue while debugging , although for time being, we solved the failures by increasing browser_start_timeout to 150s.

FYI, our test suite runs in 24 partitions.

johanneswuerbach wrote this answer on 2017-04-19

@YoranBrondsema do you also run all 24 partitions in parallel? That might be explaining why spawning the 24 instances is taking >30s.

YoranBrondsema wrote this answer on 2017-04-20

@johanneswuerbach I run 2 partitions in parallel but they are run on 2 separate VMs on Codeship. So only one instance is started on each VM.

knownasilya wrote this answer on 2017-05-19

Having a similar issue, if I increase the browser timeout, I get this error.

Error: Browser exited unexpectedlyNon-zero exit code: 1[eval("(function(undefined) {window.jasmine && (JSTestingReport
erSL = (function(undefined) {\n\n return function() {\n return {\n failedCount: jasmine.currentEnv_.currentRu
nner_.results().failedCount\n };\n }\n\n})());\n\nwindow.mocha && (JSTestingReporterSL = (function(undefined) {\n
n function hasArray(obj, nameArray) {\n return obj && obj[nameArray] && obj[nameArray].length > 0;\n }\n\n funct
ion hasSuite(obj) {\n return hasArray(obj, "suites");\n }\n\n function hasSpec(obj){\n return hasArray(obj,
"tests");\n }\n\n function reporterSpec(test) {\n var isPassed = test.state === "passed";\n return {\n
description : test.title,\n durationSec : test.duration/1000,\n passed : isPassed,\n passedCount
: isPassed ? 1 : 0,\n failedCount : isPassed ? 0 : 1,\n totalCount : 1\n };\n }\n\n function emptyRep
orter() {\n return {\n description : "",\n durationSec : 0,\n passed : true,\n totalCoun
t : 0\n };\n }\n\n function reporterObjects(objs, fn) {\n var reporter = emptyReporter();\n reporter.resul
t = [];\n\n for (var i=0; i<objs.length; i++) {\n var obj = fn(objs[i]);\n reporter.durationSec += obj.du
rationSec ? obj.durationSec : 0;\n reporter.totalCount += obj.totalCount;\n reporter.passed = reporter.pass
ed && obj.passed;\n reporter.result.push(obj);\n }\n\n return reporter;\n }\n\n function reporterSpecs(te
sts) {\n return reporterObjects(tests, reporterSpec);\n }\n\n function reporterSuites(suites) {\n return repor
terObjects(suites, reporterSuite);\n }\n\n function reporterSuite(suite) {\n var specs = hasSpec(suite) ? repor
terSpecs(suite.tests) : emptyReporter(),\n suites = hasSuite(suite) ? reporterSuites(suite.suites) : emptyRep
orter();\n\n return {\n description : suite.title,\n specs : specs.result || [],\n suites
: suites.result || [],\n durationSec : specs.durationSec + suites.durationSec,\n totalCount : specs.totalC
ount + suites.totalCount,\n passed : specs.passed && suites.passed\n };\n }\n\n return function() {\n

I'm using ember-cli-sauce.

derekdowling wrote this answer on 2017-06-16

Seeing similar output to: #1021 (comment) running Chrome 59 headless with the following config:

launch_in_ci: [ 'Chrome' ],
browser_args: {
  Chrome: [ '--headless', '--disable-gpu', '--remote-debugging-port=9222', '--no-sandbox'] 
}
briangonzalez wrote this answer on 2017-06-30

@derekdowling @knownasilya Any luck on your end? We're seeing this, too.

knownasilya wrote this answer on 2017-06-30

No improvements here, unfortunately.

lolmaus wrote this answer on 2017-07-03

@vitkhab has discovered that migrating to this Docker container resolves the issue. Notice this item on their methodology:

  1. Traps SIGTERM and relays the signal to the browser and Xvfb so that they will not continue to run once the test runner is finished. This is mostly required to deal with Karma's insistence that the browser process be terminated before it can exit. Without this relaying, Karma would hang indefinitely.
jonathanong wrote this answer on 2017-07-07

a bigger issue for me is that when i get this error, testem does not exit the process. my CI build ends up hanging. is this a known issue? i don't mind retrying my test if i get this type of error

bricss wrote this answer on 2017-07-13
14

This is how I fixed timeout issue with Chrome 59+:

{
    "framework": "qunit",
    "test_page": "tests/index.html?hidepassed",
    "disable_watching": true,
    "launch_in_ci": [
        "Chrome"
    ],
    "launch_in_dev": [
        "Chrome"
    ],
    "browser_start_timeout": 60,
    "browser_args": {
        "Chrome": [
            "--disable-gpu",
            "--disable-web-security", // optional, since chrome 60+
            "--headless",
            "--incognito", // optional
            "--no-sandbox", // optional, since chrome 60+
            "--remote-debugging-address=0.0.0.0",
            "--remote-debugging-port=9222"
        ]
    }
}
lolmaus wrote this answer on 2017-07-25

We're seeing Error: Browser disconnected in our Ember tests and the above does not help. 😭 Different issue?

bricss wrote this answer on 2017-07-26

@lolmaus Chrome 60 was released today, try it. 🤓

lolmaus wrote this answer on 2017-07-27

Our erros were caused by our Ember app leaving /tests after an Ember Data upgrade. There's still something fishy, but at least it's not related to Testem.

avdv wrote this answer on 2017-07-28

Using Chome 59 in headless mode works for us too. Our config:

"browser_args": {
      "Chrome": [
        "--headless",
        "--disable-gpu",
        "--remote-debugging-port=0"
      ]
    }
quantuminformation wrote this answer on 2017-08-03

@avdv no luck with that in chrome 59 or 60

josemarluedke wrote this answer on 2017-08-09

Hey @lolmaus. What did you do to solve the errors in Ember Data you mentioned?

briangonzalez wrote this answer on 2017-08-10

You can set your router location to none in testing. I've done this before with success.

More Details About Repo
Owner Name testem
Repo Name testem
Full Name testem/testem
Language JavaScript
Created Date 2011-07-12
Updated Date 2022-11-22
Star Count 2953
Watcher Count 71
Fork Count 409
Issue Count 127

YOU MAY BE INTERESTED

Issue Title Created Date Updated Date