Intermittent devtools/shared/adb/test/test_adb.js | testTrackDevices - [testTrackDevices : 326] Extension left running at test shutdown - "running" == "unloaded"
Categories
(DevTools :: about:debugging, defect, P5)
Tracking
(firefox-esr68 fixed, firefox67 wontfix, firefox68 wontfix, firefox69 wontfix, firefox70 wontfix, firefox71 fixed, firefox72 fixed)
People
(Reporter: intermittent-bug-filer, Assigned: robwu)
References
(Regression)
Details
(Keywords: intermittent-failure, regression)
Attachments
(1 file)
Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=267119500&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/aU8QgG4mSQW1xODxERtQNA/runs/0/artifacts/public/logs/live_backing.log
TEST-START | devtools/shared/adb/test/test_adb.js
[task 2019-09-17T20:55:17.575Z] 20:55:17 WARNING - TEST-UNEXPECTED-FAIL | devtools/shared/adb/test/test_adb.js | xpcshell return code: 0
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - TEST-INFO took 3680ms
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - >>>>>>>
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - PID 16968 | JavaScript strict warning: resource://devtools/shared/Loader.jsm, line 178: ReferenceError: reference to undefined property "name"
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - running event loop
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "name"" {file: "resource://devtools/shared/Loader.jsm" line: 178}]"
[task 2019-09-17T20:55:17.577Z] 20:55:17 INFO - devtools/shared/adb/test/test_adb.js | Starting setup
[task 2019-09-17T20:55:17.578Z] 20:55:17 INFO - (xpcshell/head.js) | test setup pending (2)
[task 2019-09-17T20:55:17.578Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2019-09-17T20:55:17.578Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2019-09-17T20:55:17.579Z] 20:55:17 INFO - (xpcshell/head.js) | test setup finished (2)
[task 2019-09-17T20:55:17.579Z] 20:55:17 INFO - devtools/shared/adb/test/test_adb.js | Starting testAdbIsNotRunningInitially
[task 2019-09-17T20:55:17.579Z] 20:55:17 INFO - (xpcshell/head.js) | test testAdbIsNotRunningInitially pending (2)
[task 2019-09-17T20:55:17.579Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2019-09-17T20:55:17.579Z] 20:55:17 INFO - TEST-PASS | devtools/shared/adb/test/test_adb.js | testAdbIsNotRunningInitially - [testAdbIsNotRunningInitially : 55] adb is not running initially - true == true
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - (xpcshell/head.js) | test testAdbIsNotRunningInitially finished (2)
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - devtools/shared/adb/test/test_adb.js | Starting testNoAdbExtension
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - (xpcshell/head.js) | test testNoAdbExtension pending (2)
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - "Extension attached"
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2019-09-17T20:55:17.580Z] 20:55:17 INFO - TEST-PASS | devtools/shared/adb/test/test_adb.js | testNoAdbExtension - [testNoAdbExtension : 71] null == null
Comment 1•5 years ago
|
||
[task 2019-09-17T20:55:17.593Z] 20:55:17 INFO - TEST-PASS | devtools/shared/adb/test/test_adb.js | testStartAndStop - [testStartAndStop : 185] true == true
[task 2019-09-17T20:55:17.593Z] 20:55:17 INFO - TEST-PASS | devtools/shared/adb/test/test_adb.js | testStartAndStop - [testStartAndStop : 186] adb is no longer running - true == true
[task 2019-09-17T20:55:17.593Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 7 pending (2)
[task 2019-09-17T20:55:17.593Z] 20:55:17 INFO - (xpcshell/head.js) | test testStartAndStop finished (2)
[task 2019-09-17T20:55:17.594Z] 20:55:17 INFO - devtools/shared/adb/test/test_adb.js | Starting testTrackDevices
[task 2019-09-17T20:55:17.594Z] 20:55:17 INFO - (xpcshell/head.js) | test testTrackDevices pending (2)
[task 2019-09-17T20:55:17.594Z] 20:55:17 INFO - "Extension attached"
[task 2019-09-17T20:55:17.595Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 7 finished (2)
[task 2019-09-17T20:55:17.595Z] 20:55:17 INFO - PID 16968 | Traceback (most recent call last):
[task 2019-09-17T20:55:17.596Z] 20:55:17 INFO - PID 16968 | File "/tmp/xpc-profile-gnUkp1/adb/adb", line 78, in <module>
[task 2019-09-17T20:55:17.597Z] 20:55:17 INFO - PID 16968 | server.server_bind()
[task 2019-09-17T20:55:17.598Z] 20:55:17 INFO - PID 16968 | File "/usr/lib/python2.7/SocketServer.py", line 431, in server_bind
[task 2019-09-17T20:55:17.598Z] 20:55:17 INFO - PID 16968 | self.socket.bind(self.server_address)
[task 2019-09-17T20:55:17.599Z] 20:55:17 INFO - PID 16968 | File "/usr/lib/python2.7/socket.py", line 228, in meth
[task 2019-09-17T20:55:17.599Z] 20:55:17 INFO - PID 16968 | return getattr(self._sock,name)(args)
[task 2019-09-17T20:55:17.600Z] 20:55:17 INFO - PID 16968 | socket.error: [Errno 98] Address already in use
[task 2019-09-17T20:55:17.600Z] 20:55:17 INFO - PID 16968 | Unhandled exception in thread started by
[task 2019-09-17T20:55:17.600Z] 20:55:17 INFO - PID 16968 | sys.excepthook is missing
[task 2019-09-17T20:55:17.601Z] 20:55:17 INFO - PID 16968 | lost sys.stderr
[task 2019-09-17T20:55:17.601Z] 20:55:17 INFO - Unexpected exception Error: ADB Process didn't start at resource://devtools/shared/adb/adb-process.js:122
[task 2019-09-17T20:55:17.602Z] 20:55:17 INFO - start@resource://devtools/shared/adb/adb-process.js:122:13
[task 2019-09-17T20:55:17.602Z] 20:55:17 INFO - asynctestTrackDevices@/builds/worker/workspace/build/tests/xpcshell/tests/devtools/shared/adb/test/test_adb.js:217:22
[task 2019-09-17T20:55:17.603Z] 20:55:17 INFO - async*run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1565:22
[task 2019-09-17T20:55:17.603Z] 20:55:17 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1565:38
[task 2019-09-17T20:55:17.603Z] 20:55:17 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:733:9
[task 2019-09-17T20:55:17.604Z] 20:55:17 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:246:6
[task 2019-09-17T20:55:17.604Z] 20:55:17 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:573:5
[task 2019-09-17T20:55:17.605Z] 20:55:17 INFO - @-e:1:1
[task 2019-09-17T20:55:17.605Z] 20:55:17 INFO - exiting test
[task 2019-09-17T20:55:17.606Z] 20:55:17 WARNING - TEST-UNEXPECTED-FAIL | devtools/shared/adb/test/test_adb.js | testTrackDevices - [testTrackDevices : 326] Extension left running at test shutdown - "running" == "unloaded"
[task 2019-09-17T20:55:17.606Z] 20:55:17 INFO - resource://testing-common/ExtensionXPCShellUtils.jsm:ExtensionWrapper/<:326
[task 2019-09-17T20:55:17.606Z] 20:55:17 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test/<:636
[task 2019-09-17T20:55:17.607Z] 20:55:17 INFO - /builds/worker/workspace/build/tests/xpcshell/head.js:_execute_test:645
[task 2019-09-17T20:55:17.607Z] 20:55:17 INFO - -e:null:1
[task 2019-09-17T20:55:17.608Z] 20:55:17 INFO - exiting test
[task 2019-09-17T20:55:17.608Z] 20:55:17 INFO - NS_ERROR_ABORT:
[task 2019-09-17T20:55:17.609Z] 20:55:17 INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:789:20
[task 2019-09-17T20:55:17.609Z] 20:55:17 INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:890:5
[task 2019-09-17T20:55:17.610Z] 20:55:17 INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:67:21
[task 2019-09-17T20:55:17.610Z] 20:55:17 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2019-09-17T20:55:17.611Z] 20:55:17 INFO - equal@resource://testing-common/Assert.jsm:275:8
[task 2019-09-17T20:55:17.611Z] 20:55:17 INFO - ExtensionWrapper/<@resource://testing-common/ExtensionXPCShellUtils.jsm:326:24
[task 2019-09-17T20:55:17.612Z] 20:55:17 INFO - _execute_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:636:28
[task 2019-09-17T20:55:17.612Z] 20:55:17 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:645:5
[task 2019-09-17T20:55:17.613Z] 20:55:17 INFO - @-e:1:1
[task 2019-09-17T20:55:17.613Z] 20:55:17 INFO - <<<<<<<
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 7•5 years ago
|
||
The error message in this bug's summary is not the real issue. It appears because the test is interrupted earlier by a different failure.
comment 1 and the log from bug 1510636 show a similar entry: "Address already in use" by the adb program.
Extract from log linked from first comment:
[task 2019-09-17T20:55:17.594Z] 20:55:17 INFO - devtools/shared/adb/test/test_adb.js | Starting testTrackDevices
[task 2019-09-17T20:55:17.594Z] 20:55:17 INFO - (xpcshell/head.js) | test testTrackDevices pending (2)
[task 2019-09-17T20:55:17.594Z] 20:55:17 INFO - "Extension attached"
[task 2019-09-17T20:55:17.595Z] 20:55:17 INFO - (xpcshell/head.js) | test run_next_test 7 finished (2)
[task 2019-09-17T20:55:17.595Z] 20:55:17 INFO - PID 16968 | Traceback (most recent call last):
[task 2019-09-17T20:55:17.596Z] 20:55:17 INFO - PID 16968 | File "/tmp/xpc-profile-gnUkp1/adb/adb", line 78, in <module>
[task 2019-09-17T20:55:17.597Z] 20:55:17 INFO - PID 16968 | server.server_bind()
[task 2019-09-17T20:55:17.598Z] 20:55:17 INFO - PID 16968 | File "/usr/lib/python2.7/SocketServer.py", line 431, in server_bind
[task 2019-09-17T20:55:17.598Z] 20:55:17 INFO - PID 16968 | self.socket.bind(self.server_address)
[task 2019-09-17T20:55:17.599Z] 20:55:17 INFO - PID 16968 | File "/usr/lib/python2.7/socket.py", line 228, in meth
[task 2019-09-17T20:55:17.599Z] 20:55:17 INFO - PID 16968 | return getattr(self._sock,name)(args)
[task 2019-09-17T20:55:17.600Z] 20:55:17 INFO - PID 16968 | socket.error: [Errno 98] Address already in use
[task 2019-09-17T20:55:17.600Z] 20:55:17 INFO - PID 16968 | Unhandled exception in thread started by
[task 2019-09-17T20:55:17.600Z] 20:55:17 INFO - PID 16968 | sys.excepthook is missing
[task 2019-09-17T20:55:17.601Z] 20:55:17 INFO - PID 16968 | lost sys.stderr
[task 2019-09-17T20:55:17.601Z] 20:55:17 INFO - Unexpected exception Error: ADB Process didn't start at resource://devtools/shared/adb/adb-process.js:122
[task 2019-09-17T20:55:17.602Z] 20:55:17 INFO - start@resource://devtools/shared/adb/adb-process.js:122:13
[task 2019-09-17T20:55:17.602Z] 20:55:17 INFO - asynctestTrackDevices@/builds/worker/workspace/build/tests/xpcshell/tests/devtools/shared/adb/test/test_adb.js:217:22
[task 2019-09-17T20:55:17.603Z] 20:55:17 INFO - async*run_next_test/_run_next_test/<@/builds/worker/workspace/build/tests/xpcshell/head.js:1565:22
[task 2019-09-17T20:55:17.603Z] 20:55:17 INFO - _run_next_test@/builds/worker/workspace/build/tests/xpcshell/head.js:1565:38
[task 2019-09-17T20:55:17.603Z] 20:55:17 INFO - run@/builds/worker/workspace/build/tests/xpcshell/head.js:733:9
[task 2019-09-17T20:55:17.604Z] 20:55:17 INFO - _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:246:6
[task 2019-09-17T20:55:17.604Z] 20:55:17 INFO - _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:573:5
[task 2019-09-17T20:55:17.605Z] 20:55:17 INFO - @-e:1:1
[task 2019-09-17T20:55:17.605Z] 20:55:17 INFO - exiting test
Extract from report in bug 1510636 :
[task 2018-11-28T10:53:51.385Z] 10:53:51 INFO - TEST-PASS | devtools/shared/adb/test/test_adb.js | testStartAndStop - [testStartAndStop : 185] adb is no longer running - true == true
[task 2018-11-28T10:53:51.386Z] 10:53:51 INFO - PID 11735 | Traceback (most recent call last):
[task 2018-11-28T10:53:51.387Z] 10:53:51 INFO - PID 11735 | File "/tmp/xpc-profile-8eqVD0/adb/adb", line 78, in <module>
[task 2018-11-28T10:53:51.388Z] 10:53:51 INFO - PID 11735 | server.server_bind()
[task 2018-11-28T10:53:51.388Z] 10:53:51 INFO - PID 11735 | File "/usr/lib/python2.7/SocketServer.py", line 431, in server_bind
[task 2018-11-28T10:53:51.389Z] 10:53:51 INFO - PID 11735 | self.socket.bind(self.server_address)
[task 2018-11-28T10:53:51.391Z] 10:53:51 INFO - PID 11735 | File "/usr/lib/python2.7/socket.py", line 228, in meth
[task 2018-11-28T10:53:51.392Z] 10:53:51 INFO - PID 11735 | return getattr(self._sock,name)(*args)
[task 2018-11-28T10:53:51.393Z] 10:53:51 INFO - PID 11735 | socket.error: [Errno 98] Address already in use
[task 2018-11-28T10:53:51.394Z] 10:53:51 INFO - PID 11735 | Unhandled exception in thread started by <function shutdown at 0x7fb1720e41b8>
[task 2018-11-28T10:53:51.395Z] 10:53:51 INFO - PID 11735 | Traceback (most recent call last):
[task 2018-11-28T10:53:51.395Z] 10:53:51 INFO - PID 11735 | File "/tmp/xpc-profile-8eqVD0/adb/adb", line 44, in shutdown
[task 2018-11-28T10:53:51.396Z] 10:53:51 INFO - PID 11735 | thread.exit()
[task 2018-11-28T10:53:51.397Z] 10:53:51 INFO - PID 11735 | AttributeError: 'NoneType' object has no attribute 'exit'
[task 2018-11-28T10:53:51.397Z] 10:53:51 INFO - <<<<<<<
[task 2018-11-28T10:53:51.398Z] 10:53:51 INFO - xpcshell return code: None
[task 2018-11-28T10:53:51.399Z] 10:53:51 INFO - devtools/shared/adb/test/test_adb.js | Process still running after test!
Assignee | ||
Comment 8•5 years ago
|
||
adb.py
uses a fixed port, which may fail if the port is already in use.
When that fails, adb-process.js
throws, and the test is going to fail.
This is likely caused by the custom abd.py
from bug 1469054 (it matches with the timings of bug 1510636).
What could happen is:
- adb.py starts server.
adb-process.js
sends a "host:kill" message.- adb.py responds and initiates the shutdown sequence.
- The client receives the OKAY to the message and resumes the test.
- The test attempts to spawn a new
adb.py
, before the previous one has exited. - The shutdown sequence at step 3 finishes, and the socket is released at this point.
When this sequence happens, at step 5 the port cannot be claimed because step 6 hasn't run yet.
adb.py
currently allows for too much time to elapse, I suggest to ungracefully shut down adb.py, so that the socket is freed as soon as possible.
Assignee | ||
Comment 9•5 years ago
|
||
test_adb.js is likely failing because the socket is still in use.
Refactor the code to exit ASAP, by ungracefully exiting adb.py.
This logic is also used by the actual adb binary:
https://android.googlesource.com/platform/system/core/+/727b07b2607c712cfa14808de7fcd0d18f5e4923/adb/adb.cpp#1039
Comment hidden (Intermittent Failures Robot) |
Comment 11•5 years ago
|
||
Pushed by rob@robwu.nl: https://hg.mozilla.org/integration/autoland/rev/bbb0e70939ab Minimize time between adb.py's OKAY and exit r=jdescottes
Comment 12•5 years ago
|
||
bugherder |
Updated•5 years ago
|
Comment 13•5 years ago
|
||
bugherder uplift |
Comment 14•5 years ago
|
||
bugherder uplift |
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Description
•