Closed Bug 1582020 Opened 5 years ago Closed 5 years ago

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)

defect

Tracking

(firefox-esr68 fixed, firefox67 wontfix, firefox68 wontfix, firefox69 wontfix, firefox70 wontfix, firefox71 fixed, firefox72 fixed)

RESOLVED FIXED
Firefox 72
Tracking Status
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

[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 - async
testTrackDevices@/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 - <<<<<<<

Summary: Intermittent devtools/shared/adb/test/test_adb.js | xpcshell return code: 0 → Intermittent devtools/shared/adb/test/test_adb.js | testTrackDevices - [testTrackDevices : 326] Extension left running at test shutdown - "running" == "unloaded"

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 - async
testTrackDevices@/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!

Blocks: 1510636

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:

  1. adb.py starts server.
  2. adb-process.js sends a "host:kill" message.
  3. adb.py responds and initiates the shutdown sequence.
  4. The client receives the OKAY to the message and resumes the test.
  5. The test attempts to spawn a new adb.py, before the previous one has exited.
  6. 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: nobody → rob
Status: NEW → ASSIGNED
Regressed by: 1469054

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

Pushed by rob@robwu.nl:
https://hg.mozilla.org/integration/autoland/rev/bbb0e70939ab
Minimize time between adb.py's OKAY and exit r=jdescottes
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 72
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.