1877892 - test_ext_browserSettings_overrideDocumentColors.html doesn't show up as a failure on treeherder

Status: RESOLVED WONTFIX

(Testing :: Mochitest, defect, P2)

Description

[Hiroyuki Ikezoe (:hiro)]

I am not sure this is the right component for this kind of issues though.

Today I realized that test_ext_browserSettings_overrideDocumentColors.html failed (it crashed) on my try runs, but the failure never appeared as orange on treeherder. For example; https://treeherder.mozilla.org/jobs?repo=try&revision=55c0899c65ea452264a8e38e5408269ba63f7027

A more annoying thing is, any subsequent tests in the same directory didn't run at all.

Comment 1

[Daniel Holbert [:dholbert]]

This is Android-specific, right? (Possibly related to the special android-specific test harness setup.)

Comment 2

[Hiroyuki Ikezoe (:hiro)]

I am not sure, the only one case I noticed is this Android one. Even if it's not Android specific, it's hard to notice right?

Comment 3

[Daniel Holbert [:dholbert]]

It's definitely hard to notice in the push that you linked, yeah. It seems the log shows us starting that test, and then some runtestsremote.py logging, and then moving on to another test with no indication that anything went wrong:

[task 2024-02-01T02:29:41.324Z] 02:29:41     INFO -  TEST-START | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html
[task 2024-02-01T02:30:01.467Z] 02:30:01     INFO -  wait for org.mozilla.geckoview.test_runner complete; top activity=com.android.launcher3
[task 2024-02-01T02:30:01.467Z] 02:30:01     INFO -  runtestsremote.py | Application ran for: 0:00:44.828966
[task 2024-02-01T02:30:01.737Z] 02:30:01     INFO -  runtests.py | Running with scheme: https
[task 2024-02-01T02:30:01.737Z] 02:30:01     INFO -  runtests.py | Running with e10s: True
[task 2024-02-01T02:30:01.737Z] 02:30:01     INFO -  runtests.py | Running with fission: True
[task 2024-02-01T02:30:01.737Z] 02:30:01     INFO -  runtests.py | Running with cross-origin iframes: False
[task 2024-02-01T02:30:01.738Z] 02:30:01     INFO -  runtests.py | Running with serviceworker_e10s: True
[task 2024-02-01T02:30:01.738Z] 02:30:01     INFO -  runtests.py | Running with socketprocess_e10s: False
[task 2024-02-01T02:30:01.738Z] 02:30:01     INFO -  runtests.py | Running tests: start.
[task 2024-02-01T02:30:01.820Z] 02:30:01     INFO -  deleted remote log /data/local/tmp/test_root/logs/mochitest.log
[task 2024-02-01T02:30:01.835Z] 02:30:01     INFO -  org.mozilla.geckoview.test_runner is already running. Stopping...
[task 2024-02-01T02:30:02.071Z] 02:30:02     INFO -  adb Granting important runtime permissions to org.mozilla.geckoview.test_runner
[task 2024-02-01T02:30:03.274Z] 02:30:03     INFO -  adb launch_application: am start -W -n org.mozilla.geckoview.test_runner/org.mozilla.geckoview.test_runner.TestRunnerActivity -a android.intent.action.MAIN --es env0 MOZ_CRASHREPORTER_NO_REPORT=1 --es env1 MOZ_CRASHREPORTER=1 --es env2 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env3 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es env4 MOZ_IN_AUTOMATION=1 --es env5 R_LOG_LEVEL=6 --es env6 R_LOG_DESTINATION=stderr --es env7 R_LOG_VERBOSE=1 --es env8 XPCOM_DEBUG_BREAK=stack --es env9 MOZ_UPLOAD_DIR=/data/local/tmp/test_root/mozlog --es env10 MOZ_HIDE_RESULTS_TABLE=1 --es arg0 -no-remote --es arg1 -profile --es arg2 /data/local/tmp/test_root/profile/ --ez use_multiprocess True -d 'https://example.com:443/tests/toolkit/components/extensions/test/mochitest?autorun=1&closeWhenDone=1&logFile=%2Fdata%2Flocal%2Ftmp%2Ftest_root%2Flogs%2Fmochitest.log&fileLevel=INFO&consoleLevel=INFO&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fdata%2Flocal%2Ftmp%2Ftest_root&ignorePrefsFile=ignorePrefs.json'
[task 2024-02-01T02:30:04.351Z] 02:30:04     INFO -  runtestsremote.py | Application pid: 4552
[task 2024-02-01T02:30:07.529Z] 02:30:07     INFO -  TEST-START | toolkit/components/extensions/test/mochitest/test_ext_storage_manager_capabilities.html
[task 2024-02-01T02:30:17.593Z] 02:30:17     INFO -  TEST-OK | toolkit/components/extensions/test/mochitest/test_ext_storage_manager_capabilities.html | took 3562ms
[task 2024-02-01T02:30:17.594Z] 02:30:17     INFO -  TEST-START | Shutdown

https://firefoxci.taskcluster-artifacts.net/KpGVQYEOSVOn3k7VwechNA/0/public/logs/live_backing.log

I don't know why that's happening, but I'm guessing it's related to the runtestsremote.py stuff which I think (?) is how we manage collecting the logging/etc. from the Android device when we're running mochitests.

(I was asking about Android-specificness both to narrow down where the bug/fix would be, and also because if this somehow were not not Android-specific, this would be quite surprising and substantially more concerning, since it'd mean we could be spuriously skipping tests enirely, without realizing.)

Comment 4

[Daniel Holbert [:dholbert]]

From looking at a few of the logs, it looks like there's exactly a 20-second delay between the TEST-START line and the wait for org.mozilla.geckoview.test_runner complete; top activity=com.android.launcher3 etc. logging that follows it. Not sure if that's an indication of some special timeout or what.

This log is a little different from the one I linked in comment 3; it shows some logging coming from subtests in this test:

[task 2024-02-01T02:29:38.268Z] 02:29:38     INFO -  TEST-START | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html
[task 2024-02-01T02:29:58.394Z] 02:29:58     INFO -  wait for org.mozilla.geckoview.test_runner complete; top activity=com.android.launcher3
[task 2024-02-01T02:29:58.394Z] 02:29:58     INFO -  runtestsremote.py | Application ran for: 0:00:44.485354
[task 2024-02-01T02:29:58.453Z] 02:29:58     INFO -  Stopping web server
[task 2024-02-01T02:29:58.455Z] 02:29:58     INFO -  Server shut down.
[task 2024-02-01T02:29:58.455Z] 02:29:58     INFO -  Web server killed.
[task 2024-02-01T02:29:58.455Z] 02:29:58     INFO -  Stopping web socket server
[task 2024-02-01T02:29:58.455Z] 02:29:58     INFO -  Stopping ssltunnel
[task 2024-02-01T02:29:58.455Z] 02:29:58     INFO -  leakcheck | refcount logging is off, so leaks can't be detected!
[task 2024-02-01T02:29:58.456Z] 02:29:58     INFO -  runtests.py | Running tests: end.
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  Buffered messages logged at 02:29:32
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  add_setup | Entering
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  add_setup | Leaving
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  add_task | Entering overrideDocumentColors_always
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  Extension loaded
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  Buffered messages logged at 02:29:33
[task 2024-02-01T02:29:58.619Z] 02:29:58     INFO -  Extension loaded
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | Bg color from user
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | Fg color from user
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  TEST-PASS | toolkit/components/extensions/test/mochitest/test_ext_browserSettings_overrideDocumentColors.html | Default fg color from user
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  add_task | Leaving overrideDocumentColors_always
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  add_task | Entering overrideDocumentColors_never
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  Extension loaded
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  Buffered messages logged at 02:29:34
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  Extension loaded
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  Buffered messages finished
[task 2024-02-01T02:29:58.620Z] 02:29:58     INFO -  Running manifest: toolkit/components/extensions/test/mochitest/mochitest-serviceworker.toml

https://firefoxci.taskcluster-artifacts.net/eHPTNBUkQRy5sWrDgwIyOg/0/public/logs/live_backing.log

It looks like we get as far as the Entering overrideDocumentColors_never subtest, and we load two extensions (as part of the test) but then we suddenly move on to the next test directory with no failure or indication as to what happened.

Comment 5

[Hiroyuki Ikezoe (:hiro)]

Yeah, It's concerning even if it happens on Android, if it could happen on desktop it would be worse.

CCing a couple of people who recently touched runtestsremote.py.

Comment 6

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

Treeherder gets the result (if the task failed) from Taskcluster which gets it from the task and its test suite.

Comment 7

[BugBot [:suhaib / :marco]]

The severity field is not set for this bug.
:jmaher, could you have a look please?

For more information, please visit BugBot documentation.

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

I looked on linux/mac/windows- this test runs ok. I looked on many runs of android- we always fail to complete this specific test.

I see in this log on m-c a crash (emulator.log):

--------- beginning of crash
02-27 10:44:15.897 11551 11551 E AndroidRuntime: FATAL EXCEPTION: main
02-27 10:44:15.897 11551 11551 E AndroidRuntime: Process: org.mozilla.geckoview.test_runner, PID: 11551
02-27 10:44:15.897 11551 11551 E AndroidRuntime: org.mozilla.geckoview.GeckoResult$UncaughtException: java.lang.NullPointerException: Attempt to read from field 'java.util.HashMap org.mozilla.geckoview.test_runner.TestRunnerActivity$ExtensionWrapper.browserActions' on a null object reference
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult.dispatchLocked(GeckoResult.java:777)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult.completeExceptionally(GeckoResult.java:920)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult.lambda$thenInternal$6(GeckoResult.java:601)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult.$r8$lambda$nsAzyhhKgAo0Ha3SEAUSdsKADo8(GeckoResult.java)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult$$ExternalSyntheticLambda5.run(D8$$SyntheticClass)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at android.os.Handler.handleCallback(Handler.java:751)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at android.os.Handler.dispatchMessage(Handler.java:95)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at android.os.Looper.loop(Looper.java:154)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at android.app.ActivityThread.main(ActivityThread.java:6077)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at java.lang.reflect.Method.invoke(Native Method)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:756)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: Caused by: java.lang.NullPointerException: Attempt to read from field 'java.util.HashMap org.mozilla.geckoview.test_runner.TestRunnerActivity$ExtensionWrapper.browserActions' on a null object reference
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.test_runner.TestRunnerActivity$6.onBrowserAction(TestRunnerActivity.java:280)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.WebExtensionController.actionUpdate(WebExtensionController.java:1728)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.WebExtensionController.lambda$handleMessage$8(WebExtensionController.java:1019)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.WebExtensionController.$r8$lambda$VtjwD-V2s3a_efltYOQGsfRcMMQ(WebExtensionController.java)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.WebExtensionController$$ExternalSyntheticLambda7.accept(D8$$SyntheticClass)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult.lambda$accept$2(GeckoResult.java:485)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult$$ExternalSyntheticLambda6.onValue(D8$$SyntheticClass)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	at org.mozilla.geckoview.GeckoResult.lambda$thenInternal$6(GeckoResult.java:588)
02-27 10:44:15.897 11551 11551 E AndroidRuntime: 	... 9 more

the question is why are we not detecting the crash and reporting it? I don't see crash dumps as artifacts.

from what I can tell based on log output, we are doing the normal flow of detecting the process exited:
https://searchfox.org/mozilla-central/source/testing/mochitest/runtestsremote.py#385

so then why are we not finding crashes in check_for_crashes ? a couple try pushes might help point out where the root cause is.

:owlish, can you look into the null pointer ^^^ ? maybe redirect to the right person?

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

I added some print debugging around the runtestsremote.py code and we are checking for crashes and not finding anything in the crash directory /data/local/tmp/test_root/profile/minidumps on the device.

I am not sure there is more to do on the harness side without getting access to a crash dump.

Comment 10

[Hiroyuki Ikezoe (:hiro)]

I opened bug 1882622 to fix (or disable) test_ext_browserSettings_overrideDocumentColors.html on Android.

A big problem here is that we are not sure whether there's any other similar test failures or not. If there it is, we should fix the underlying root cause anyway.