Closed Bug 1037924 Opened 6 years ago Closed 5 years ago

Harness failure: Error: Not connected. To write data you must call connect first

Categories

(Testing Graveyard :: JSMarionette, defect)

x86
macOS
defect
Not set

Tracking

(Not tracked)

RESOLVED INVALID

People

(Reporter: kgrandon, Assigned: daleharvey)

References

Details

(Whiteboard: [systemsfe])

We see a failure along these lines for a variety of different tests. Opening a bug to gather some datapoints to see if there is a common pattern, and if it's a problem with the harness.
One example: 

1) Music player tests "before each" hook:
18:35:59     INFO -    Error: timeout of 60000ms exceeded
18:35:59     INFO -        at null.<anonymous> (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:139:19)
18:35:59     INFO -        at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
18:35:59     INFO -    2) Music player tests "after each" hook:
18:35:59     INFO -    Error: Not connected. To write data you must call connect first.
18:35:59     INFO -        at TcpSync.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/drivers/tcp-sync.js:99:15)
18:35:59     INFO -        at Object.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:457:36)
18:35:59     INFO -        at Object.Client._sendCommand (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:503:19)
18:35:59     INFO -        at Object.closeDriver (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:751:14)
18:35:59     INFO -        at Object.executeHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:359:20)
18:35:59     INFO -        at Object.Client.runHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:377:7)
18:35:59     INFO -        at Object.destroySession [as deleteSession] (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:761:12)
18:35:59     INFO -        at Context.<anonymous> (/builds/slave/test/gaia/node_modules/marionette-js-runner/lib/runtime/hostmanager.js:102:14)
18:35:59     INFO -        at Hook.Runnable.run (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:196:15)
18:35:59     INFO -        at next (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:258:10)
18:35:59     INFO -        at Object._onImmediate (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:275:5)
18:35:59     INFO -        at processImmediate [as _immediateCallback] (timers.js:330:15)

https://tbpl.mozilla.org/php/getParsedLog.php?id=43697863&tree=Gaia-Try
Blocks: 960072
Failure in calendar:

 1) creating events "before each" hook:
01:15:21     INFO -    Error: timeout of 60000ms exceeded
01:15:21     INFO -        at null.<anonymous> (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:139:19)
01:15:21     INFO -        at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
01:15:21     INFO -    2) creating events "after each" hook:
01:15:21     INFO -    Error: Not connected. To write data you must call connect first.
01:15:21     INFO -        at TcpSync.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/drivers/tcp-sync.js:99:15)
01:15:21     INFO -        at Object.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:457:36)
01:15:21     INFO -        at Object.Client._sendCommand (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:503:19)
01:15:21     INFO -        at Object.closeDriver (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:751:14)
01:15:21     INFO -        at Object.executeHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:359:20)
01:15:21     INFO -        at Object.Client.runHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:377:7)
01:15:21     INFO -        at Object.destroySession [as deleteSession] (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:761:12)
01:15:21     INFO -        at Context.<anonymous> (/builds/slave/test/gaia/node_modules/marionette-js-runner/lib/runtime/hostmanager.js:102:14)
01:15:21     INFO -        at Hook.Runnable.run (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:196:15)
01:15:21     INFO -        at next (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:258:10)
01:15:21     INFO -        at Object._onImmediate (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:275:5)
01:15:21     INFO -        at processImmediate [as _immediateCallback] (timers.js:330:15)

https://tbpl.mozilla.org/php/getParsedLog.php?id=43676682&tree=Gaia-Try
Failure in settings: 

 1) check root panel settings "before each" hook:
18:38:07     INFO -    Error: timeout of 60000ms exceeded
18:38:07     INFO -        at null.<anonymous> (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:139:19)
18:38:07     INFO -        at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
18:38:07     INFO -    2) check root panel settings "after each" hook:
18:38:07     INFO -    Error: Not connected. To write data you must call connect first.
18:38:07     INFO -        at TcpSync.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/drivers/tcp-sync.js:99:15)
18:38:07     INFO -        at Object.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:457:36)
18:38:07     INFO -        at Object.Client._sendCommand (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:503:19)
18:38:07     INFO -        at Object.closeDriver (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:751:14)
18:38:07     INFO -        at Object.executeHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:359:20)
18:38:07     INFO -        at Object.Client.runHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:377:7)
18:38:07     INFO -        at Object.destroySession [as deleteSession] (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:761:12)
18:38:07     INFO -        at Context.<anonymous> (/builds/slave/test/gaia/node_modules/marionette-js-runner/lib/runtime/hostmanager.js:102:14)
18:38:07     INFO -        at Hook.Runnable.run (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:196:15)
18:38:07     INFO -        at next (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:258:10)
18:38:07     INFO -        at Object._onImmediate (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:275:5)
18:38:07     INFO -        at processImmediate [as _immediateCallback] (timers.js:330:15)
18:38:07     INFO -  make: *** [test-integration-test] Error 2
18:38:07    ERROR - Return code: 2
18:38:07     INFO - TinderboxPrint: gaia-integration-tests: 251/<em class="testfail">2</em>/43
18:38:07    ERROR - Tests exited with return code 2: harness failures
18:38:07    ERROR - # TBPL FAILURE #

https://tbpl.mozilla.org/php/getParsedLog.php?id=43697893&tree=Gaia-Try#error5
Additionally there is another harness failure going on that has roughly the same "before each" hook stack, bug a different "after each" failure:

 1) Vertical Home - Packaged App Failed Download "before each" hook:
02:02:29     INFO -    Error: timeout of 60000ms exceeded
02:02:29     INFO -        at null.<anonymous> (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:139:19)
02:02:29     INFO -        at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
02:02:29     INFO -    2) Vertical Home - Packaged App Failed Download "after each" hook:
02:02:29     INFO -       Uncaught
02:02:29     INFO -    TypeError: Cannot call method 'send' of undefined
02:02:29     INFO -        at Object.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:457:36)
02:02:29     INFO -        at Object.Client._sendCommand (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:503:19)
02:02:29     INFO -        at Object.closeDriver (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:751:14)
02:02:29     INFO -        at process._tickCallback (node.js:415:13)
02:02:29     INFO -  make: *** [test-integration-test] Error 2
02:02:29    ERROR - Return code: 2
02:02:29     INFO - TinderboxPrint: gaia-integration-tests: 15/<em class="testfail">2</em>/0
02:02:29    ERROR - Tests exited with return code 2: harness failures
02:02:29    ERROR - # TBPL FAILURE #

https://tbpl.mozilla.org/php/getParsedLog.php?id=43702803&tree=Gaia-Try#error2
Ni? on a few people. Any chance you guys could look at this, or give advice about where to start looking (Hand-wavy answers also appreciated). This is one of our last issues preventing re-enabling Gi on TBPL. The failure rate of this alone is between 5 and 10%.
Flags: needinfo?(jlal)
Flags: needinfo?(gaye)
Flags: needinfo?(evanxd)
Could this bug related to bug 1033229?
(In reply to Julien Wajsberg [:julienw] (PTO Monday 14th July) from comment #6)
> Could this bug related to bug 1033229?

It's possible. Does that one also reproduce on TBPL? I believe this one reproduces on both Travis and TBPL.
Hey Zac, have you seen bug 1033229 on TBPL too?
Flags: needinfo?(zcampbell)
(In reply to Julien Wajsberg [:julienw] (PTO Monday 14th July) from comment #8)
> Hey Zac, have you seen bug 1033229 on TBPL too?

Yes we see it on TBPL too.
Flags: needinfo?(zcampbell)
Needinfo? on you guys thanks to Gareth ;-)
Flags: needinfo?(hub)
Flags: needinfo?(aus)
It is possible that solving bug 1033402 at the marionette-js-client could help. It is about waiting for marionette socket to be up and answer.
Flags: needinfo?(hub)
(In reply to Hubert Figuiere [:hub] from comment #11)
> It is possible that solving bug 1033402 at the marionette-js-client could
> help. It is about waiting for marionette socket to be up and answer.

Thanks hub. I'm going to add a dependency if you don't mind. We should also continue to do some investigation here to verify that that bug will actually fix this.
Depends on: 1033402
My guess is that there's a race condition which occurs in which we end up trying to write to the socket before it's opened. The exception being thrown would seem to indicate exactly that. Based on hub's comment, and the patch for bug 1033402 it would seem to support my jedi like intuition.
Flags: needinfo?(aus)
Thanks guys! Let's get bug 1033402 in asap so we can verify and get these tests turned on.
Flags: needinfo?(jlal)
Flags: needinfo?(evanxd)
Flags: needinfo?(gaye)
With bug 1033402 now landed, we should watch if we still see that issue.
(In reply to Hubert Figuiere [:hub] from comment #15)
> With bug 1033402 now landed, we should watch if we still see that issue.

I'll do a large test run soon to check. Thanks Hub!
Sorry for another ping. We're still seeing intermittent failures across all test suites preventing us from re-enabling this suite on TBPL. This is probably the *most important* test suite we have as gaia, so re-enabling it should be one of our top priorities. 

Would you guys be interesting in meeting over Vidyo to peer-program and debug this? I think having some recurring meeting might be useful to try to figure this out. Is there anyone else that would be good to help with this?
Flags: needinfo?(jlal)
Flags: needinfo?(hub)
Flags: needinfo?(gaye)
Flags: needinfo?(evanxd)
(In reply to Kevin Grandon :kgrandon from comment #19)
> across all test suites

I meant to say across all tests.
Maybe :aus too?
Flags: needinfo?(hub)
No action :( What are we waiting for?
(In reply to Alexandre LISSY :gerard-majax from comment #22)
> No action :( What are we waiting for?

We are waiting for people to confirm action =( I think people might be slammed with 2.1 work right now. Perhaps after we hit FL people might have some more time.
No longer blocks: 1048138
See Also: → 1065501
See Also: → 831010
Assignee: nobody → dale
So there is some not errors getting passed though unhandled in the marionette-client, and buming the timeout may help, but can I get a dummys guide to testing updates to node_modules deps without publishing a version? Ive been told a few times to just point to a different branch etc but I dont havent seen the exact steps, I tried just pushing gaia with node_modules committed, but need to be smarter about the build files
Flags: needinfo?(kgrandon)
* first run "make node_modules" to be sure this is current and won't run overwriting what you do next
* run "npm link" in your module
* run "npm link <module name>" in gaia

=> you'll see that node_modules now has a link to your module.

This works only at the top level module; if you want to change a nested module, you need to do the same in the module that depends on that module.

Take care that next time "make node_modules" downloads and installs node_modules from github, this will overwrite your link.
Flags: needinfo?(kgrandon)
Thanks Julien. I think this only works if you are testing this locally? Dale - if you are pushing to try, then you'll need to update this path I believe: https://github.com/mozilla-b2g/gaia/blob/master/Makefile#L686

TBH - it's been a while and I never documented this. Perhaps we should add some comments to the Makefile.
Whiteboard: [systemsfe]
(In reply to Kevin Grandon :kgrandon from comment #26)
> Thanks Julien. I think this only works if you are testing this locally?

Ah yeah, clearly :)
Clearing request flags, and will probably file new bugs with the current problems.
Flags: needinfo?(jlal)
Flags: needinfo?(gaye)
Flags: needinfo?(evanxd)
See Also: → 1091680
Filed bug 1091680 to clean things up a bit.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INVALID
Product: Testing → Testing Graveyard
You need to log in before you can comment on or make changes to this bug.