https://treeherder.mozilla.org/logviewer.html#?job_id=134661451&repo=mozilla-inbound [task 2017-10-03T15:36:54.315Z] 15:36:54 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpTJJWlp.mozrunner [task 2017-10-03T15:36:54.336Z] 15:36:54 INFO - runtests.py | Application pid: 1633 [task 2017-10-03T15:36:54.336Z] 15:36:54 INFO - TEST-INFO | started process GECKO(1633) [task 2017-10-03T15:36:55.508Z] 15:36:55 INFO - GECKO(1633) | 1507045015503 Marionette INFO Enabled via --marionette [task 2017-10-03T15:36:56.840Z] 15:36:56 INFO - GECKO(1633) | 1507045016829 Marionette INFO Listening on port 2828 [task 2017-10-03T15:36:57.570Z] 15:36:57 INFO - SimpleTest START [task 2017-10-03T15:36:57.571Z] 15:36:57 INFO - TEST-START | accessible/tests/mochitest/treeupdate/test_ariaowns.html [task 2017-10-03T15:36:58.638Z] 15:36:58 INFO - GECKO(1633) | [1633, Main Thread] WARNING: g_type_add_interface_static: assertion 'g_type_parent (interface_type) == G_TYPE_INTERFACE' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 141 [task 2017-10-03T15:36:58.638Z] 15:36:58 INFO - GECKO(1633) | (firefox:1633): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion 'g_type_parent (interface_type) == G_TYPE_INTERFACE' failed [task 2017-10-03T15:36:58.639Z] 15:36:58 INFO - GECKO(1633) | [1633, Main Thread] WARNING: g_type_add_interface_static: assertion 'g_type_parent (interface_type) == G_TYPE_INTERFACE' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 141 [task 2017-10-03T15:36:58.640Z] 15:36:58 INFO - GECKO(1633) | (firefox:1633): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion 'g_type_parent (interface_type) == G_TYPE_INTERFACE' failed [task 2017-10-03T15:36:58.649Z] 15:36:58 INFO - GECKO(1633) | [1633, Main Thread] WARNING: g_type_add_interface_static: assertion 'g_type_parent (interface_type) == G_TYPE_INTERFACE' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 141 [task 2017-10-03T15:36:58.650Z] 15:36:58 INFO - GECKO(1633) | (firefox:1633): GLib-GObject-CRITICAL **: g_type_add_interface_static: assertion 'g_type_parent (interface_type) == G_TYPE_INTERFACE' failed [task 2017-10-03T15:36:59.677Z] 15:36:59 INFO - GECKO(1633) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration. [task 2017-10-03T15:36:59.677Z] 15:36:59 INFO - GECKO(1633) | MEMORY STAT | vsize 2011MB | residentFast 287MB | heapAllocated 132MB [task 2017-10-03T15:36:59.698Z] 15:36:59 INFO - TEST-OK | accessible/tests/mochitest/treeupdate/test_ariaowns.html | took 2125ms [task 2017-10-03T15:36:59.706Z] 15:36:59 INFO - TEST-START | Shutdown [task 2017-10-03T15:36:59.707Z] 15:36:59 INFO - Passed: 641 [task 2017-10-03T15:36:59.708Z] 15:36:59 INFO - Failed: 0 [task 2017-10-03T15:36:59.709Z] 15:36:59 INFO - Todo: 1 [task 2017-10-03T15:36:59.710Z] 15:36:59 INFO - Mode: non-e10s [task 2017-10-03T15:36:59.712Z] 15:36:59 INFO - Slowest: 2125ms - chrome://mochitests/content/a11y/accessible/tests/mochitest/treeupdate/test_ariaowns.html [task 2017-10-03T15:36:59.713Z] 15:36:59 INFO - SimpleTest FINISHED [task 2017-10-03T15:36:59.715Z] 15:36:59 INFO - TEST-INFO | Ran 1 Loops [task 2017-10-03T15:36:59.716Z] 15:36:59 INFO - SimpleTest FINISHED [task 2017-10-03T15:36:59.900Z] 15:36:59 INFO - GECKO(1633) | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: telemetry_modules_ping [task 2017-10-03T15:37:00.281Z] 15:37:00 INFO - TEST-INFO | Main app process: exit 0 [task 2017-10-03T15:37:00.281Z] 15:37:00 INFO - runtests.py | Application ran for: 0:00:05.958703 [task 2017-10-03T15:37:00.281Z] 15:37:00 INFO - zombiecheck | Reading PID log: /tmp/tmpnE5vJ2pidlog [task 2017-10-03T15:37:00.282Z] 15:37:00 INFO - ==> process 1633 launched child process 1657 [task 2017-10-03T15:37:00.283Z] 15:37:00 INFO - zombiecheck | Checking for orphan process with PID: 1657 [task 2017-10-03T15:37:00.284Z] 15:37:00 INFO - Stopping web server [task 2017-10-03T15:37:00.285Z] 15:37:00 INFO - Stopping web socket server [task 2017-10-03T15:37:00.301Z] 15:37:00 INFO - Stopping ssltunnel [task 2017-10-03T15:37:00.322Z] 15:37:00 WARNING - leakcheck | refcount logging is off, so leaks can't be detected! [task 2017-10-03T15:37:00.323Z] 15:37:00 INFO - runtests.py | Running tests: end. [task 2017-10-03T15:37:00.325Z] 15:37:00 INFO - Buffered messages finished [task 2017-10-03T15:37:00.326Z] 15:37:00 INFO - SUITE-END | took 6s [task 2017-10-03T15:37:00.327Z] 15:37:00 INFO - Checking for ssltunnel processes... [task 2017-10-03T15:37:00.332Z] 15:37:00 INFO - Checking for xpcshell processes... [task 2017-10-03T15:37:00.336Z] 15:37:00 INFO - NOT killing {'username': 'worker', 'ppid': 1041, 'pid': 1314, 'name': 'xpcshell'} (not an orphan?) [task 2017-10-03T15:37:00.338Z] 15:37:00 INFO - NOT killing {'username': 'worker', 'ppid': 1041, 'pid': 1471, 'name': 'xpcshell'} (not an orphan?) [task 2017-10-03T15:37:00.340Z] 15:37:00 INFO - NOT killing {'username': 'worker', 'ppid': 1041, 'pid': 1606, 'name': 'xpcshell'} (not an orphan?) [task 2017-10-03T15:37:00.341Z] 15:37:00 INFO - mozcrash Removed pending crash reports at '/builds/worker/.mozilla/firefox/Crash Reports' [task 2017-10-03T15:37:00.342Z] 15:37:00 INFO - SUITE-START | Running 1 tests [task 2017-10-03T15:37:00.366Z] 15:37:00 INFO - Setting pipeline to PAUSED ... [task 2017-10-03T15:37:00.367Z] 15:37:00 INFO - Pipeline is PREROLLING ... [task 2017-10-03T15:37:00.367Z] 15:37:00 INFO - Pipeline is PREROLLED ... [task 2017-10-03T15:37:00.368Z] 15:37:00 INFO - Setting pipeline to PLAYING ... [task 2017-10-03T15:37:00.368Z] 15:37:00 INFO - New clock: GstSystemClock [task 2017-10-03T15:37:00.405Z] 15:37:00 INFO - Got EOS from element "pipeline0". [task 2017-10-03T15:37:00.405Z] 15:37:00 INFO - Execution ended after 33473984 ns. [task 2017-10-03T15:37:00.405Z] 15:37:00 INFO - Setting pipeline to PAUSED ... [task 2017-10-03T15:37:00.406Z] 15:37:00 INFO - Setting pipeline to READY ... [task 2017-10-03T15:37:00.407Z] 15:37:00 INFO - Setting pipeline to NULL ... [task 2017-10-03T15:37:00.408Z] 15:37:00 INFO - Freeing pipeline ... [task 2017-10-03T15:37:00.450Z] 15:37:00 INFO - Traceback (most recent call last): [task 2017-10-03T15:37:00.452Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2985, in <module> [task 2017-10-03T15:37:00.453Z] 15:37:00 INFO - sys.exit(cli()) [task 2017-10-03T15:37:00.456Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2981, in cli [task 2017-10-03T15:37:00.458Z] 15:37:00 INFO - return run_test_harness(parser, options) [task 2017-10-03T15:37:00.459Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2948, in run_test_harness [task 2017-10-03T15:37:00.461Z] 15:37:00 INFO - result = runner.verifyTests(options) [task 2017-10-03T15:37:00.463Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2436, in verifyTests [task 2017-10-03T15:37:00.465Z] 15:37:00 INFO - result = step() [task 2017-10-03T15:37:00.466Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2377, in step2 [task 2017-10-03T15:37:00.468Z] 15:37:00 INFO - result = self.runTests(stepOptions) [task 2017-10-03T15:37:00.469Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2491, in runTests [task 2017-10-03T15:37:00.471Z] 15:37:00 INFO - return self.runMochitests(options, [t['path'] for t in tests]) [task 2017-10-03T15:37:00.473Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2316, in runMochitests [task 2017-10-03T15:37:00.475Z] 15:37:00 INFO - result = self.doTests(options, testsToRun) [task 2017-10-03T15:37:00.476Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2594, in doTests [task 2017-10-03T15:37:00.477Z] 15:37:00 INFO - self.manifest = self.buildProfile(options) [task 2017-10-03T15:37:00.479Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 1872, in buildProfile [task 2017-10-03T15:37:00.480Z] 15:37:00 INFO - manifest = self.addChromeToProfile(options) [task 2017-10-03T15:37:00.481Z] 15:37:00 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 1269, in addChromeToProfile [task 2017-10-03T15:37:00.482Z] 15:37:00 INFO - os.mkdir(chromedir) [task 2017-10-03T15:37:00.484Z] 15:37:00 INFO - OSError: [Errno 17] File exists: '/tmp/tmpTJJWlp.mozrunner/chrome' [task 2017-10-03T15:37:00.523Z] 15:37:00 ERROR - Return code: 1 [task 2017-10-03T15:37:00.524Z] 15:37:00 INFO - TinderboxPrint: mochitest-a11y<br/>13/0/0 [task 2017-10-03T15:37:00.525Z] 15:37:00 ERROR - # TBPL FAILURE # [task 2017-10-03T15:37:00.525Z] 15:37:00 WARNING - setting return code to 2 [task 2017-10-03T15:37:00.526Z] 15:37:00 ERROR - TinderboxPrint: Verification of .../treeupdate/test_ariaowns.html<br/>: FAILURE

This failed on the second iteration of step 2 of verification -- not related to --repeat, not related to chaos mode.

Test verification calls runTests() many times. runTests() normally creates a profile, runs tests against that profile, and then cleans up that profile. However, if options.profilePath is specified, that path is used, and it is not cleaned up after running tests. Unfortunately, runTests() also sets options.profilePath to the profile it creates. So in test verification, the second and later calls to runTests() do so with the same options.profilePath, and each one re-uses the old profile -- not what I intended at all. Re-use of existing profiles leads to the error in this bug, where a mkdir fails because the directory already exists. This patch resets profilePath to None before each test verification call to runTests() -- each instance creates and cleans up a new profile.

Comment on attachment 8915661 [details] [diff] [review] clear profilePath between runTests() calls Review of attachment 8915661 [details] [diff] [review]: ----------------------------------------------------------------- do we need to do this for xpcshell/reftest?

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #3) > do we need to do this for xpcshell/reftest? No. This seems to be a peculiarity of mochitest.

Pushed by gbrown@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/707a657002d6 Ensure new profile used throughout test verification; r=jmaher