Closed Bug 1161702 Opened 9 years ago Closed 9 years ago

Intermittent luciddream AssertionError: Timed out waiting for port!

Categories

(Testing :: General, defect)

Unspecified
Linux
defect
Not set
normal

Tracking

(firefox39 fixed, firefox40 fixed, firefox41 fixed, firefox-esr38 unaffected)

RESOLVED FIXED
mozilla41
Tracking Status
firefox39 --- fixed
firefox40 --- fixed
firefox41 --- fixed
firefox-esr38 --- unaffected

People

(Reporter: KWierso, Assigned: jgriffin)

References

Details

(Keywords: intermittent-failure)

Attachments

(2 files)

10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x18db79ee
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0xffdaf1d4
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x8000ffff
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x618fd860
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x5c0726b8
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x5f9d46a0
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0xd
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x5ac2e2b8
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x5c0d3120
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0xffdaf0a8
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0xffda0008
10:15:41 INFO - 2015-05-05 10:15:41: basic_code_modules.cc:88: INFO: No module at 0x5
10:15:48 INFO - [OK] rjs optimize
10:15:52 INFO - Finished: test ui config file: ./dev_apps/test-agent/config.json
10:15:52 INFO - Finished: Generating extensions
10:15:52 INFO - test -d .git && cp tools/pre-commit .git/hooks/pre-commit && chmod +x .git/hooks/pre-commit || true
10:15:53 INFO - Profile Ready: please run [b2g|firefox] -profile /builds/slave/test/gaia/profile
10:15:53 INFO - Return code: 0
10:15:53 INFO - Running command: ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/tests/luciddream/luciddream/runluciddream.py', '--log-raw=/builds/slave/test/build/luciddream_raw.log', '--b2g-desktop-path', '/builds/slave/test/build/b2gdesktop/b2g/b2g', '--browser-path', '/builds/slave/test/build/application/firefox/firefox', '--gaia-profile', '/builds/slave/test/gaia/profile', '/builds/slave/test/build/tests/luciddream/example-tests/luciddream.ini']
10:15:53 INFO - Copy/paste: /builds/slave/test/build/venv/bin/python /builds/slave/test/build/tests/luciddream/luciddream/runluciddream.py --log-raw=/builds/slave/test/build/luciddream_raw.log --b2g-desktop-path /builds/slave/test/build/b2gdesktop/b2g/b2g --browser-path /builds/slave/test/build/application/firefox/firefox --gaia-profile /builds/slave/test/gaia/profile /builds/slave/test/build/tests/luciddream/example-tests/luciddream.ini
10:15:53 INFO - Using env: {'CCACHE_DIR': '/builds/ccache',
10:15:53 INFO - 'CCACHE_UMASK': '002',
10:15:53 INFO - 'DISPLAY': ':0',
10:15:53 INFO - 'HOME': '/home/cltbld',
10:15:53 INFO - 'LANG': 'en_US.UTF-8',
10:15:53 INFO - 'LOGNAME': 'cltbld',
10:15:53 INFO - 'MAIL': '/var/mail/cltbld',
10:15:53 INFO - 'MOZ_HIDE_RESULTS_TABLE': '1',
10:15:53 INFO - 'MOZ_NODE_PATH': '/usr/bin/node',
10:15:53 INFO - 'MOZ_NO_REMOTE': '1',
10:15:53 INFO - 'NODE_PATH': '/usr/lib/nodejs:/usr/lib/node_modules:/usr/share/javascript',
10:15:53 INFO - 'NO_FAIL_ON_TEST_ERRORS': '1',
10:15:53 INFO - 'PATH': '/builds/slave/test/build/venv/bin:/usr/local/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games',
10:15:53 INFO - 'PROPERTIES_FILE': '/builds/slave/test/buildprops.json',
10:15:53 INFO - 'PWD': '/builds/slave/test',
10:15:53 INFO - 'SHELL': '/bin/bash',
10:15:53 INFO - 'SHLVL': '1',
10:15:53 INFO - 'TERM': 'linux',
10:15:53 INFO - 'TMOUT': '86400',
10:15:53 INFO - 'USER': 'cltbld',
10:15:53 INFO - 'XDG_SESSION_COOKIE': '9ca12473fbb1d023794ffd180000023c-1430845571.290996-1195966919',
10:15:53 INFO - '_': '/tools/buildbot/bin/python'}
10:15:53 INFO - Calling ['/builds/slave/test/build/venv/bin/python', '/builds/slave/test/build/tests/luciddream/luciddream/runluciddream.py', '--log-raw=/builds/slave/test/build/luciddream_raw.log', '--b2g-desktop-path', '/builds/slave/test/build/b2gdesktop/b2g/b2g', '--browser-path', '/builds/slave/test/build/application/firefox/firefox', '--gaia-profile', '/builds/slave/test/gaia/profile', '/builds/slave/test/build/tests/luciddream/example-tests/luciddream.ini'] with output_timeout 1000
10:16:59 INFO - Traceback (most recent call last):
10:16:59 INFO - File "/builds/slave/test/build/tests/luciddream/luciddream/runluciddream.py", line 151, in <module>
10:16:59 INFO - main()
10:16:59 INFO - File "/builds/slave/test/build/tests/luciddream/luciddream/runluciddream.py", line 148, in main
10:16:59 INFO - run(**vars(args))
10:16:59 INFO - File "/builds/slave/test/build/tests/luciddream/luciddream/runluciddream.py", line 141, in run
10:16:59 INFO - runner.run_tests([manifest])
10:16:59 INFO - File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py", line 755, in run_tests
10:16:59 INFO - self.start_marionette()
10:16:59 INFO - File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette/runner/base.py", line 700, in start_marionette
10:16:59 INFO - self.marionette = self.driverclass(**self._build_kwargs())
10:16:59 INFO - File "/builds/slave/test/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 602, in __init__
10:16:59 INFO - assert(self.wait_for_port()), "Timed out waiting for port!"
10:16:59 INFO - AssertionError: Timed out waiting for port!
10:17:06 ERROR - Return code: 1
10:17:06 INFO - TinderboxPrint: luciddream: <em class="testfail">T-FAIL</em>
10:17:06 ERROR - Luciddream exited with return code 1: harness failures
10:17:06 ERROR - # TBPL FAILURE #
10:17:06 INFO - Running post-action listener: _resource_record_post_action
10:17:06 INFO - Running post-run listener: _resource_record_post_run
10:17:07 INFO - Total resource usage - Wall time: 262s; CPU: 99.0%; Read bytes: 80424960; Write bytes: 762126336; Read time: 248564; Write time: 7611684
10:17:07 INFO - install - Wall time: 60s; CPU: 100.0%; Read bytes: 0; Write bytes: 144629760; Read time: 0; Write time: 664100
10:17:07 INFO - run-tests - Wall time: 203s; CPU: 99.0%; Read bytes: 79753216; Write bytes: 607846400; Read time: 248308; Write time: 6923528
10:17:07 INFO - Running post-run listener: _upload_blobber_files
10:17:07 INFO - Blob upload gear active.
Jonathan, any idea what's going on here?
Flags: needinfo?(jgriffin)
I'll add some more logging here; nothing jumps out.
Depends on: 1177789
Have landed some additional logging; will look again if this recurs.
Flags: needinfo?(jgriffin)
These tests are completely CPU bound on the low-end AWS instances we currently use.  The second binary we're launching seems to be hanging, but it may just be temporary.  I'm going to increase the timeout and see if this resolves the problem.
Assignee: nobody → jgriffin
Status: NEW → ASSIGNED
I'm fixing this in two parts.  One, I'm adding a --startup-timeout parameter to Marionette.  Currently, there's no way to set this programatically.  Two, in order to use this, I'm adding an in-tree config to luciddream.  Green try run:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0c3045ca5a1c
Bug 1161702 - Add --startup-timeout arg for Marionette; add in-tree config for luciddream
Attachment #8629072 - Flags: review?(ahalberstadt)
Comment on attachment 8629074 [details]
MozReview Request: Bug 1161702 - Add --startup-timeout arg for Marionette; add in-tree config for luciddream

Bug 1161702 - Add --startup-timeout arg for Marionette; add in-tree config for luciddream
Attachment #8629074 - Flags: review?(ahalberstadt)
Comment on attachment 8629072 [details] [diff] [review]
Make luciddream mozharness script use in-tree config,

Review of attachment 8629072 [details] [diff] [review]:
-----------------------------------------------------------------

Lgtm! In-tree configs will be merged into regular configs once mozharness is live in-tree, but we can land this as an intermediate step and merge luciddream along with everything else.

::: scripts/luciddream_unittest.py
@@ +228,4 @@
>          ld_parser = self.parser_class(config=self.config,
>                                        log_obj=self.log_obj,
>                                        error_list=BaseErrorList)
> + 

nit: whitespace
Attachment #8629072 - Flags: review?(ahalberstadt) → review+
Comment on attachment 8629074 [details]
MozReview Request: Bug 1161702 - Add --startup-timeout arg for Marionette; add in-tree config for luciddream

https://reviewboard.mozilla.org/r/12523/#review11307

Ship It!
Attachment #8629074 - Flags: review?(ahalberstadt) → review+
(In reply to Pulsebot from comment #30)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/6aa0c715afce

I'll land the mozharness change after this gets merged around (and I guess to the in-tree mozharness copy as well?)
Keywords: leave-open
No occurrences in a couple of weeks; I'm calling this fixed.
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Keywords: leave-open
Target Milestone: --- → mozilla41
You need to log in before you can comment on or make changes to this bug.