1680322 - Intermittent No tests run or test summary not found for dom/presentation/tests/mochitest/mochitest.ini despite existence of TEST-PASS

Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)

Reporter

Description

•

5 years ago

This is a special instance of bug 1669432

The Android mochitests from this push only scheduled the tests in dom/presentation/tests/mochitest/mochitest.ini. Most of them are being skipped but some have TEST-START and TEST-OK but no passing steps except the last one

https://searchfox.org/mozilla-central/rev/de782976bf97669f1e8edee59e7a2398154efe06/dom/presentation/tests/mochitest/test_presentation_reconnect.html doesn't show any code for an early exit.

Log: https://treeherder.mozilla.org/logviewer?job_id=323321318&repo=autoland

[task 2020-12-02T15:36:28.890Z] 15:36:28     INFO -  5 INFO TEST-START | dom/presentation/tests/mochitest/test_presentation_reconnect.html
[task 2020-12-02T15:36:38.997Z] 15:36:38     INFO -  6 INFO TEST-OK | dom/presentation/tests/mochitest/test_presentation_reconnect.html | took 149ms
[task 2020-12-02T15:36:38.997Z] 15:36:38     INFO -  7 INFO TEST-START | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html
[task 2020-12-02T15:36:59.222Z] 15:36:59     INFO -  wait for org.mozilla.geckoview.test complete; top activity=com.android.launcher3
[task 2020-12-02T15:36:59.252Z] 15:36:59     INFO -  remoteautomation.py | Application ran for: 0:00:43.698919
[task 2020-12-02T15:36:59.365Z] 15:36:59     INFO -  Stopping web server
[task 2020-12-02T15:36:59.371Z] 15:36:59     INFO -  Stopping web socket server
[task 2020-12-02T15:36:59.392Z] 15:36:59     INFO -  Stopping ssltunnel
[task 2020-12-02T15:36:59.413Z] 15:36:59     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
[task 2020-12-02T15:36:59.413Z] 15:36:59     INFO -  runtests.py | Running tests: end.
[task 2020-12-02T15:36:59.699Z] 15:36:59     INFO -  Buffered messages logged at 15:36:28
[task 2020-12-02T15:36:59.700Z] 15:36:59     INFO -  8 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | PresentationRequest should be available.
[task 2020-12-02T15:36:59.700Z] 15:36:59     INFO -  9 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | Sender: should have no available device after setup
[task 2020-12-02T15:36:59.700Z] 15:36:59     INFO -  10 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | Device should be available.
[task 2020-12-02T15:36:59.700Z] 15:36:59     INFO -  11 INFO Device prompt is triggered.
[task 2020-12-02T15:36:59.700Z] 15:36:59     INFO -  12 INFO A control channel is established.
[task 2020-12-02T15:36:59.701Z] 15:36:59     INFO -  13 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | Connection should be available.
[task 2020-12-02T15:36:59.701Z] 15:36:59     INFO -  14 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | Connection ID should be set.
[task 2020-12-02T15:36:59.701Z] 15:36:59     INFO -  15 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | The initial state should be connecting.
[task 2020-12-02T15:36:59.701Z] 15:36:59     INFO -  16 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | |connectionavailable| event is fired with a connection.
[task 2020-12-02T15:36:59.702Z] 15:36:59     INFO -  17 INFO TEST-PASS | dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html | The connection from promise and the one from |connectionavailable| event should be the same.
[task 2020-12-02T15:36:59.702Z] 15:36:59     INFO -  18 INFO The control channel is opened.
[task 2020-12-02T15:36:59.702Z] 15:36:59     INFO -  Buffered messages finished
[task 2020-12-02T15:37:00.020Z] 15:37:00     INFO -  0 INFO TEST-START | Shutdown
[task 2020-12-02T15:37:00.021Z] 15:37:00     INFO -  1 INFO Passed:  0
[task 2020-12-02T15:37:00.021Z] 15:37:00     INFO -  2 INFO Failed:  0
[task 2020-12-02T15:37:00.021Z] 15:37:00     INFO -  3 INFO Todo:    0
[task 2020-12-02T15:37:00.021Z] 15:37:00     INFO -  4 INFO Mode:    e10s
[task 2020-12-02T15:37:00.021Z] 15:37:00     INFO -  5 INFO SimpleTest FINISHED

4/4 runs hit this issue. Are we always not storing the results for the steps and only miss this for other runs because we ran it together with other test manifests?

Geoff Brown [:gbrown]

Assignee

Comment 1

•

5 years ago

I think what happened here is that Android killed the browser:
https://treeherder.mozilla.org/logviewer?job_id=323321318&repo=autoland&lineNumber=2437-2453

[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): FATAL EXCEPTION: main
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): Process: org.mozilla.geckoview.test, PID: 2966
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): java.lang.SecurityException: WifiService: Neither user 10062 nor current process has android.permission.ACCESS_WIFI_STATE.
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.os.Parcel.readException(Parcel.java:1683)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.os.Parcel.readException(Parcel.java:1636)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.net.wifi.IWifiManager$Stub$Proxy.getConnectionInfo(IWifiManager.java:1158)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.net.wifi.WifiManager.getConnectionInfo(WifiManager.java:1286)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at org.mozilla.gecko.GeckoNetworkManager.getWifiIPAddress(GeckoNetworkManager.java:456)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at org.mozilla.gecko.GeckoNetworkManager.handleMessage(GeckoNetworkManager.java:442)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at org.mozilla.gecko.EventDispatcher$2.run(EventDispatcher.java:301)
[task 2020-12-02T15:37:00.117Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.os.Handler.handleCallback(Handler.java:751)
[task 2020-12-02T15:37:00.118Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.os.Handler.dispatchMessage(Handler.java:95)
[task 2020-12-02T15:37:00.118Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.os.Looper.loop(Looper.java:154)
[task 2020-12-02T15:37:00.118Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at android.app.ActivityThread.main(ActivityThread.java:6077)
[task 2020-12-02T15:37:00.118Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at java.lang.reflect.Method.invoke(Native Method)
[task 2020-12-02T15:37:00.118Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
[task 2020-12-02T15:37:00.118Z] 15:37:00     INFO -  12-02 15:36:28.985 E/AndroidRuntime( 2966): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)

Bob Clary [:bc] (inactive)

Comment 2

•

5 years ago

What's up with java.lang.SecurityException: WifiService: Neither user 10062 nor current process has android.permission.ACCESS_WIFI_STATE. ?

Geoff Brown [:gbrown]

Assignee

Comment 3

•

5 years ago

I think we should probably add ACCESS_WIFI_STATE to
https://searchfox.org/mozilla-central/rev/de782976bf97669f1e8edee59e7a2398154efe06/testing/mozbase/mozdevice/mozdevice/adb.py#3557

"Probably" only because I have a nagging feeling we have come across this before (but I can't find the bug) and decided not to...

Geoff Brown [:gbrown]

Assignee

Comment 4

•

5 years ago

(In reply to Geoff Brown [:gbrown] from comment #3)

"Probably" only because I have a nagging feeling we have come across this before (but I can't find the bug) and decided not to...

Bug 1643448!

Updated

•

5 years ago

Assignee: nobody → whole.grains

Geoff Brown [:gbrown]

Assignee

Comment 5

•

5 years ago

Test results for dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html on mozilla-central,autoland between 2020-11-25 and 2020-12-02
android-em-7-0-x86_64-qr/debug:             142 failures (     0 skipped) in    142 runs
android-em-7-0-x86_64-qr/opt:               104 failures (     0 skipped) in    104 runs
android-em-7-0-x86_64-shippable-qr/opt:      15 failures (     0 skipped) in     15 runs
android-em-7-0-x86_64-shippable/opt:         15 failures (     0 skipped) in     15 runs
android-em-7-0-x86_64/debug:                107 failures (     0 skipped) in    107 runs
android-em-7-0-x86_64/opt:                   57 failures (     0 skipped) in     57 runs
linux1804-64-asan/opt:                        0 failures (     0 skipped) in     92 runs
linux1804-64-qr/fis-debug:                    0 failures (     0 skipped) in    123 runs
linux1804-64-qr/opt:                          0 failures (     0 skipped) in     53 runs
... (good results on all desktop platforms)

Note that -- other than this bug -- there are no bugs open for test_presentation_sender_on_terminate_request.html failures. The android mochitest tasks running this test are consistently green, even though the test fails.

Geoff Brown [:gbrown]

Assignee

Comment 6

•

5 years ago

Failure reproduced on try, and tasks fail since only the one manifest is run ("No tests run..."):
https://treeherder.mozilla.org/jobs?repo=try&revision=0e8762e90b538cf7e173db013cf1c88e6b99efe1
Continues failing with ACCESS_WIFI_STATE added to manifest, as in bug 1643448:
https://treeherder.mozilla.org/jobs?repo=try&revision=b00f4a18250498d29e8b7115a54f05230fe48c8a
test_presentation_sender_on_terminate_request.html times out.
Continues failing with ACCESS_WIFI_STATE added both to manifest and to the adb.py grant list:
https://treeherder.mozilla.org/jobs?repo=try&revision=db10fa7c2a447ad9ca1798cba78620ad17240a0d
test_presentation_sender_on_terminate_request.html times out.

In both cases 2 and 3, the SecurityException is effectively avoided, but the test hangs. This seems typical:
https://firefoxci.taskcluster-artifacts.net/Eber3O9RR2CQyStX34uWCw/0/public/test_info//logcat-emulator-5554.log

12-02 23:21:56.252  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316250,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"PresentationRequest should be available.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.257  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316256,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"Sender: should have no available device after setup","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.261  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316260,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"Device should be available.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.270  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"log","time":1606951316270,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"Device prompt is triggered.","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.275  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"log","time":1606951316275,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"A control channel is established.","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.278  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316278,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"Connection should be available.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.279  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316278,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"Connection ID should be set.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.279  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316279,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"The initial state should be connecting.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.282  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316281,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"|connectionavailable| event is fired with a connection.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.282  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951316282,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"The connection from promise and the one from |connectionavailable| event should be the same.","status":"PASS","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.285  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"log","time":1606951316284,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"The control channel is opened.","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:21:56.732  2972  2987 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
12-02 23:22:04.737  1614  1614 I ActivityManager: Killing 2135:com.android.keychain/1000 (adj 906): empty #17
12-02 23:22:04.780  1614  1948 D ActivityManager: cleanUpApplicationRecord -- 2135
12-02 23:26:13.864  1614  1627 I GnssLocationProvider: WakeLock acquired by handleInjectNtpTime()
12-02 23:26:14.107  1614  3476 D SntpClient: round trip: 58ms, clock offset: 890ms
12-02 23:26:14.107  1614  3476 I GnssLocationProvider: WakeLock acquired by sendMessage(10, 0, null)
12-02 23:26:14.107  1614  3476 I GnssLocationProvider: WakeLock released by handleInjectNtpTime()
12-02 23:26:14.107  1614  1627 I GnssLocationProvider: WakeLock released by handleMessage(10, 0, null)
12-02 23:27:15.070  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_status","time":1606951635067,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","subtest":"Test timed out.","status":"FAIL","expected":"PASS","stack":"    SimpleTest.ok@SimpleTest/SimpleTest.js:417:16\n    reportError@SimpleTest/TestRunner.js:143:22\n    TestRunner._checkForHangs@SimpleTest/TestRunner.js:165:18\n","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:27:16.095  3004  3019 I GeckoDump: MEMORY STAT | vsize 4141MB | residentFast 124MB | heapAllocated 12MB
12-02 23:27:16.112  3004  3019 I Gecko   : [Child 3004, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
12-02 23:27:16.118  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"test_end","time":1606951636118,"thread":null,"pid":null,"source":"mochitest","test":"/tests/dom/presentation/tests/mochitest/test_presentation_sender_on_terminate_request.html","status":"OK","message":"Finished in 319977ms","stack":{"runtime":319977},"js_source":"TestRunner.js"}î…µî¸±â°²ê²¿
12-02 23:27:16.127  2972  2987 I Gecko   : [Parent 2972, Main Thread] WARNING: 'NS_FAILED(aReason) || !mIsResponderReady', file /builds/worker/checkouts/gecko/dom/presentation/PresentationSessionInfo.cpp:817
12-02 23:27:16.130  3004  3019 I GeckoDump: î…µî¸±â°²ê²¿{"action":"log","time":1606951636130,"thread":null,"pid":null,"source":"mochitest","level":"INFO","message":"The control channel is closed. 0","js_source":"TestRunner.js"}î…µî¸±â°²ê²¿

Geoff Brown [:gbrown]

Assignee

Updated

•

5 years ago

Status: NEW → RESOLVED

Closed: 5 years ago

Resolution: --- → DUPLICATE

Bugzilla

Intermittent No tests run or test summary not found for dom/presentation/tests/mochitest/mochitest.ini despite existence of TEST-PASS

Categories

(Testing :: Mochitest, defect)

Tracking

(Not tracked)

People

(Reporter: aryx, Assigned: gbrown)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 4

Updated

Comment 5

Comment 6

Updated