Closed Bug 1005707 Opened 12 years ago Closed 12 years ago

Intermittent test suite failures, TypeError: Cannot read property 'deleteSession' of null

Categories

(Firefox OS Graveyard :: Gaia, defect, P1)

Product:
Firefox OS Graveyard
Component:
Gaia
Platform:
x86
macOS
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: kgrandon, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

Github pull request
60 bytes, text/x-github-pull-request
gaye
: review+
Details | Review
Node modules dance
46 bytes, text/x-github-pull-request
Details | Review
We are seeing this across every test which causes confusion when testing for intermittent failures. We need to track this down.
Here is an example of an error message: 05:34:45 INFO - Error: Not connected. To write data you must call connect first. 05:34:45 INFO - at TcpSync.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/drivers/tcp-sync.js:93:15) 05:34:45 INFO - at Object.send (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:455:36) 05:34:45 INFO - at Object.Client._sendCommand (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:501:19) 05:34:45 INFO - at Object.closeDriver (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:747:14) 05:34:45 INFO - at Object.executeHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:360:20) 05:34:45 INFO - at Object.Client.runHook (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:378:7) 05:34:45 INFO - at Object.destroySession [as deleteSession] (/builds/slave/test/gaia/node_modules/marionette-client/lib/marionette/client.js:757:12) 05:34:45 INFO - at Context.<anonymous> (/builds/slave/test/gaia/node_modules/marionette-js-runner/lib/runtime/hostmanager.js:102:14) 05:34:45 INFO - at Hook.Runnable.run (/builds/slave/test/gaia/node_modules/mocha/lib/runnable.js:194:15) 05:34:45 INFO - at next (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:257:10) 05:34:45 INFO - at Object._onImmediate (/builds/slave/test/gaia/node_modules/mocha/lib/runner.js:274:5) 05:34:45 INFO - at processImmediate [as _immediateCallback] (timers.js:330:15)
I'm not sure if this reproduces in every test, but I've seen this message in the following tests: 1) Camera app on call "before each" hook: 2) Camera app on call "after each" hook: 1) Dev Tools server "before each" hook: 2) Dev Tools server "after each" hook: 1) Search - App search "before each" hook: 2) Search - App search "after each" hook:
Gareth, James - Would you guys have any clues about what might be causing this? Any ideas about how to debug would be greatly appreciated. To keep our sheriffs sane, we really need to solve this as soon as possible. It seems we're seeing this both on travis and tbpl, I have not seen this locally yet. Thanks!
Flags: needinfo?(jlal)
Flags: needinfo?(gaye)
Priority: -- → P1
Also ni? on hub and aus as it appears this is coming from sockit-to-me and they might have some ideas: https://github.com/mozilla-b2g/sockit-to-me/blob/master/src/sockit.cc#L256 Sorry for the ni? party here - just want to make sure we get the right people looking at it :)
Flags: needinfo?(hub)
Flags: needinfo?(aus)
I would instead say that you have four problems. 1. The error reporting to tbpl is abysmal. When a test fails because of an "Error: timeout of 60000ms exceeded" it is reported to tbpl as "TEST-UNEXPECTED-FAIL | Contacts > Activities "before each" hook". When a test fails because of a "TypeError: Object #<Sockit> has no method 'setPollTimeout'" it is reported to tbpl as the same "TEST-UNEXPECTED-FAIL | Contacts > Activities "before each" hook". 2. There's some sort of failure that results in every test hitting that "TypeError: Object #<Sockit> has no method 'setPollTimeout'"/"TypeError: Cannot read property 'deleteSession' of null" failure pattern, which was apparently misstarred as a random assortment of existing bugs which were about individual tests timing out. 3. There are far too many tests hitting the "Error: timeout of 60000ms exceeded"/"TypeError: Cannot read property 'deleteSession' of null" pattern, with nobody looking at them to see whether they are making progress but running out of time, or hanging, or all failing from a single structural problem or each failing for their own reasons. 4. Now you've marked eleven bugs which were about two different things as duplicates of a single bug, which leaves us with two choices for starring: star failures (which will be from at least two different things, timeouts and lack of setPollTimeout) as closed bugs, which is a bad practice which leads to not noticing the emergence of new failures, or manually star every failure as being this bug. Neither one of those solutions will do anything to advance the dubious cause of sheriff sanity.
Hey Phil - I'm open to various ways of working, and if there is some compelling reason to re-open all of the bugs (which is now at 24), I'm more than happy to do so. I'm still trying to wrap my head around the various ways of TBPL reporting issues, but I don't think it makes sense to have multiple bugs for a single issue. It seems like we should probably have one bug for the "has no method 'setPollTimeout'" error, and another for the "deleteSession" error. We should also open another bug to improve reporting if that would help. My main reason for marking the bugs as duplicates were so we can focus our resources and illustrate how bad the problem is. Previously it seemed that the various tests were at fault when in fact it is likely the test framework. Perhaps I should've raised the issue with sheriffs first, and I apologize if I've made life hard. I'm hoping to come to a resolution on this quickly.
Ah, I see that the Sockit stuff was actually just misstarring of a bad push which was later backed out, so maybe this'll just be gathering up every single timeout in any test, and since I don't think anyone has ever looked at any of the timeouts, it's still anybody's guess whether that's actually one cause or multiple causes.
Keywords: intermittent-failure
Summary: Intermittent test suite failures, Cannot read property 'deleteSession' of null → Intermittent test suite failures, TypeError: Cannot read property 'deleteSession' of null
(In reply to Phil Ringnalda (:philor) from comment #29) > I would instead say that you have four problems. > > 1. The error reporting to tbpl is abysmal. When a test fails because of an > "Error: timeout of 60000ms exceeded" it is reported to tbpl as > "TEST-UNEXPECTED-FAIL | Contacts > Activities "before each" hook". When a > test fails because of a "TypeError: Object #<Sockit> has no method > 'setPollTimeout'" it is reported to tbpl as the same "TEST-UNEXPECTED-FAIL | > Contacts > Activities "before each" hook". This error "TypeError: Object #<Sockit> has no method 'setPollTimeout'" is that we have a "bad" binary for sockit.node NodeJS binary module. If you don't have 0.2.1 then you have the wrong one (0.2.0 is fine if compiled upon installation) > > 2. There's some sort of failure that results in every test hitting that > "TypeError: Object #<Sockit> has no method 'setPollTimeout'"/"TypeError: > Cannot read property 'deleteSession' of null" failure pattern, which was > apparently misstarred as a random assortment of existing bugs which were > about individual tests timing out. See 1. I have no idea what can cause the rest.
Flags: needinfo?(hub)
also concerning the timeout, the sockit timeout is slightly longer than the marionette timeout set by the test. The only difference is that before the sockit timeout existed, the marionette timeout didn't happen: sockit is synchronous and block the node main loop as well, therefor the marionette timeout never occur.
See Also: → 992295
I'll try and have a look at this as well this week, as time permits.
Flags: needinfo?(aus)
In my experience, I've correlated this with B2G crashing and our client sending marionette commands nowhere
Verbose log from Alex. It seems to get stuck on repeating the following: socket-retry-connect socket is not ready trying +24ms 9:31 socket-retry-connect attempt to open socket +2s 61712 localhost 9:31 marionette:tcp got socket starting command stream +0ms 9:31 TypeError: Cannot call method 'on' of undefined 9:31 at Object.CommandStream (/home/alex/gaia/node_modules/marionette-client/lib/marionette/command-stream.js:23:12)
Thanks for the logs! This line seems a bit suspicious: b2g-desktop stdout +36ms 1400524370182 Marionette ERROR exception: NS_ERROR_SOCKET_ADDRESS_IN_USE, Component returned failure code: 0x804b0036 (NS_ERROR_SOCKET_ADDRESS_IN_USE) [nsIServerSocket.initSpecialConnection]
Possibly relevant: http://mxr.mozilla.org/mozilla-central/source/netwerk/base/public/nsIServerSocket.idl#63 Hi Jim - I've seen your name around some code that might be relevant to the NS_ERROR_SOCKET_ADDRESS_IN_USE error that we've been seeing. We've been seeing this on some linux machines so far, with one person reproducing it every test run. I know this is a stretch, but I was wondering if you could send us any docs/tips on the best way of debugging this. (Should we run debug builds, what should we look for in the logs, known pitfalls, etc). Any tips are appreciated :)
Flags: needinfo?(jimb)
I'm not sure it is a platform issue. It looks like there is something messed up with marionette port. I can see some custom port being used in nodejs code, something different from 2828, but from the b2g desktop logs, I can see 2828, and I can successfully connect to 2828...
Also, in /tmp/tmp-6249qy90m4g/prefs.js, I can see: user_pref("marionette.defaultPrefs.port", 2828);
Flags: needinfo?(jimb)
Ok, so here is my issue, I had that in gaia/build/config/custom-prefs.js: user_pref("marionette.defaultPrefs.enabled", true); user_pref("marionette.defaultPrefs.port", 2828); That would be great if we can ensure marionette client overload these prefs no matter what! Also, it gives you a way to easily reproduce the "Cannot read property 'deleteSession' of null". If you do like me with custom-prefs, this exception will happen on the second failing test. See: https://pastebin.mozilla.org/5201397 About NS_ERROR_SOCKET_ADDRESS_IN_USE, I've seen it multiple times also, it was always because of some b2g-bin living in background for ages.
Marionette js does always write those two prefs to the created profile ftr... see https://github.com/mozilla-b2g/marionette-js-runner/blob/master/lib/childrunner.js#L43 We find our own open port and then write that to the profile.
We use this thing to pick an empty port also https://github.com/fnobi/emptyPort
We still need to figure this out, but it seems that reproduction rate has gone way down. I wonder if we fixed something recently??
Flags: needinfo?(jlal)
Flags: needinfo?(gaye)
Guys, since we're trying to turn on Gi again, this is becoming critical to fix. TBH - I'm not sure if we can turn them on without this. Could either of you find some time to help look into this or reach out to some more people?
Flags: needinfo?(jlal)
Flags: needinfo?(gaye)
I doubt this is a platform issue... more likely some test is reusing an object across multiple tests (i.e. a dead connection) or racing to do something while we are closing the connection. Should not be too hard to implement some code to uniquely identify the connections then when dead connections are used tie that back to some identifier </hand wave>.
Flags: needinfo?(jlal)
Blocks: 960072
Attached file Github pull request —
So since _hooks currently defaults to `null`, it appears that we never add one. The only place that adds the deleteSession hook appears to be the logger. Perhaps that's either failing, or the options array is not getting set as expected. For now I think I would just like to try safeguarding against a null _hooks definition. By defaulting it to an object, we should hit the early return case and not throw this error. If this doesn't work we can investigate further.
Attachment #8454124 - Flags: review?(jlal)
Attachment #8454124 - Flags: review?(gaye)
Comment on attachment 8454124 [details] [review] Github pull request Looks fine to me. One nit/preference on GH. Thanks kgrandon.
Attachment #8454124 - Flags: review?(gaye) → review+
Flags: needinfo?(gaye)
Comment on attachment 8454124 [details] [review] Github pull request Thanks, let's give this a shot and hope it clears up the problem. If not, back to the drawing board.
Attachment #8454124 - Flags: review?(jlal)
Attached file Node modules dance —
Updated master with new node_modules: https://github.com/mozilla-b2g/gaia/commit/8154cd4605bbdd64e59efa45b06b5d77032dc5c0 Going to try to verify this now by running ~20 jobs on travis/tbpl.
So good news is that I'm not seeing this failure anymore since the patch. Our next harness bug is being tracked in bug 1037924. Closing this, and will start tracking the next biggest fish.
We no longer see this in 2.0. Next biggest fish is bug 1037924.
Status: NEW → RESOLVED
Closed: 12 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: