Open Bug 1926846 Opened 20 days ago Updated 15 days ago

Perma [tier 2] /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | cookieStore.subscribe with invalid url path in option - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe"

Categories

(Core :: DOM: Core & HTML, defect, P5)

defect

Tracking

()

ASSIGNED
Tracking Status
firefox-esr128 --- unaffected
firefox131 --- unaffected
firefox132 --- unaffected
firefox133 --- affected
firefox134 --- affected

People

(Reporter: intermittent-bug-filer, Assigned: asuth)

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression)

Filed by: agoloman [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=479643751&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/DP6fA2lwSH-TaXDQcrSt2w/runs/0/artifacts/public/logs/live_backing.log


[task 2024-10-24T11:33:07.069Z] 11:33:07     INFO - TEST-START | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html
[task 2024-10-24T11:33:07.087Z] 11:33:07     INFO - Closing window 69216ea7-ecaf-430f-b5bc-999feb14ba05
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - 
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-PASS | /cookie-store/cookieStore_special_names.https.any.serviceworker.html | cookieStore.set of expired __Host- cookie name on secure origin 
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-PASS | /cookie-store/cookieStore_special_names.https.any.serviceworker.html | cookieStore.delete with __Host- name on secure origin 
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-PASS | /cookie-store/cookieStore_special_names.https.any.serviceworker.html | cookieStore.set with __Host- prefix and a domain option 
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-PASS | /cookie-store/cookieStore_special_names.https.any.serviceworker.html | cookieStore.set with __Host- prefix a path option 
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-PASS | /cookie-store/cookieStore_special_names.https.any.serviceworker.html | cookieStore.set with malformed name. 
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.html | cookieStore.subscribe without url in option - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", self.registration.cookies is undefined"
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.html | cookieStore.subscribe with invalid url path in option - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", registration.cookies is undefined"
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.html | cookieStore.subscribe is idempotent - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", self.registration.cookies is undefined"
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.html | CookieStore.unsubscribe is idempotent - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", self.registration.cookies is undefined"
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | cookieStore.subscribe without url in option - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", self.registration.cookies is undefined"
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-UNEXPECTED-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | cookieStore.subscribe with invalid url path in option - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", registration.cookies is undefined"
[task 2024-10-24T11:33:07.711Z] 11:33:07     INFO - TEST-INFO | expected TIMEOUT
[task 2024-10-24T11:33:07.712Z] 11:33:07     INFO - 
[task 2024-10-24T11:33:07.712Z] 11:33:07     INFO - TEST-UNEXPECTED-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | cookieStore.subscribe is idempotent - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", self.registration.cookies is undefined"
[task 2024-10-24T11:33:07.712Z] 11:33:07     INFO - TEST-INFO | expected NOTRUN
[task 2024-10-24T11:33:07.712Z] 11:33:07     INFO - 
[task 2024-10-24T11:33:07.712Z] 11:33:07     INFO - TEST-UNEXPECTED-FAIL | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | CookieStore.unsubscribe is idempotent - promise_test: Unhandled rejection with value: object "TypeError: can't access property "subscribe", self.registration.cookies is undefined"
[task 2024-10-24T11:33:07.712Z] 11:33:07     INFO - TEST-INFO | expected NOTRUN
[task 2024-10-24T11:33:07.779Z] 11:33:07     INFO - TEST-UNEXPECTED-OK | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | expected TIMEOUT
[task 2024-10-24T11:33:07.779Z] 11:33:07     INFO - TEST-INFO expected TIMEOUT | took 710ms
[task 2024-10-24T11:33:08.329Z] 11:33:08     INFO - STDOUT: cleanup aborted: Unable to remount device
[task 2024-10-24T11:33:08.330Z] 11:33:08     INFO - Closing logging queue
[task 2024-10-24T11:33:08.330Z] 11:33:08     INFO - queue closed
[task 2024-10-24T11:33:08.341Z] 11:33:08     INFO - Setting up ssl
[task 2024-10-24T11:33:08.553Z] 11:33:08     INFO - certutil | b''
[task 2024-10-24T11:33:08.620Z] 11:33:08     INFO - certutil | b''
[task 2024-10-24T11:33:08.631Z] 11:33:08     INFO - certutil | b'\nCertificate Nickname                                         Trust Attributes\n                                                             SSL,S/MIME,JAR/XPI\n\nweb-platform-tests                                           CT,, \n'
[task 2024-10-24T11:33:09.177Z] 11:33:09     INFO - adb Granting important runtime permissions to org.mozilla.geckoview.test_runner
[task 2024-10-24T11:33:10.232Z] 11:33:10     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=1 --es env1 MOZ_CRASHREPORTER_NO_REPORT=1 --es env2 MOZ_CRASHREPORTER_SHUTDOWN=1 --es env3 MOZ_HIDE_RESULTS_TABLE=1 --es env4 MOZ_IN_AUTOMATION=1 --es env5 MOZ_LOG=signaling:3,mtransport:4,DataChannel:4,jsep:4 --es env6 R_LOG_LEVEL=6 --es env7 R_LOG_DESTINATION=stderr --es env8 R_LOG_VERBOSE=1 --es env9 MOZ_PROCESS_LOG=/tmp/tmpaspti_o3pidlog --es env10 MOZ_DISABLE_NONLOCAL_CONNECTIONS=1 --es arg0 -no-remote --es arg1 -profile --es arg2 /data/local/tmp/test_root/profile --es arg3 --marionette --es arg4 about:blank
[task 2024-10-24T11:33:11.691Z] 11:33:11     INFO - Starting runner
[task 2024-10-24T11:33:12.555Z] 11:33:12     INFO - TEST-START | /cookie-store/cookieStore_subscriptions_empty.https.window.html

Set release status flags based on info from the regressing bug 1900427

:asuth, since you are the author of the regressor, bug 1900427, could you take a look?

For more information, please visit BugBot documentation.

So looking at the previous run of test-android-em-7.0-x86_64-shippable-lite-qr/opt-geckoview-web-platform-tests-backlog-nofis-3 (note: backlog, these are W-b-nofis) (also note: fast emulator, it's x86_64) on m-c before the landing of my changes we see that the test just timed (~3sec) out without reporting any failures:

[task 2024-10-24T06:04:26.313Z] 06:04:26     INFO - TEST-START | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html
[task 2024-10-24T06:04:26.332Z] 06:04:26     INFO - Closing window 1085f1de-60de-4773-9819-c3380901f99e
[task 2024-10-24T06:04:29.325Z] 06:04:29     INFO - TEST-TIMEOUT | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | took 3011ms

Notably this also happens on linux64 as well:

[task 2024-10-24T06:31:09.636Z] 06:31:09     INFO - TEST-START | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html
[task 2024-10-24T06:31:09.639Z] 06:31:09     INFO - Closing window 5b04c854-fc73-466f-a49f-b5b7a4032d52
[task 2024-10-24T06:31:09.654Z] 06:31:09     INFO - PID 32094 | [Parent 32094, IPC I/O Parent] WARNING: process 3493 is a zombie: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:245
[task 2024-10-24T06:31:09.961Z] 06:31:09     INFO - PID 32094 | [Parent 32094, IPC I/O Parent] WARNING: process 3536 is a zombie: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:245
[task 2024-10-24T06:31:10.130Z] 06:31:10     INFO - PID 32094 | [Parent 32094, IPC I/O Parent] WARNING: process 3438 is a zombie: file /builds/worker/checkouts/gecko/ipc/chromium/src/base/process_util_posix.cc:245
[task 2024-10-24T06:31:12.486Z] 06:31:12     INFO - ....
[task 2024-10-24T06:31:12.486Z] 06:31:12     INFO - TEST-TIMEOUT | /cookie-store/cookieStore_subscribe_arguments.https.any.serviceworker.html | took 2849ms

If we look at wpt.fyi for the test we see that we do fail as expected in the first test and then we timeout in the 2nd second test. The 2nd test timeout is expected because before bug 1113522 landed in the regressing stack here, the idiom used in the test to wait for the activate event doesn't work without bug 1113522 because self.registration.active can never be non-null.

} else if (!self.registration.active) {
  // If service worker is not active yet, it must wait for it to enter the
  // 'activated' state before subscribing to cookiechange events.
  await new Promise(resolve => {
    self.addEventListener('activate', event => { resolve(); });
  });

This does raise the question of whether my patch changed the scheduling of the firing of the "activate" event relative to when the first test case adds an activate listener without checking if there already is an active worker. It appears that WPT ServiceWorker defer invoking add_on_loaded_callback callbacks to receipt of the "install" event or their first "message" event because that indicates the script evaluation has finished. So that would be a fine time for the tests to start, but as far as I can see, that is actually completely unrelated to when promise_tests kick off. The promise_tests operate as a promise chain that is a combination of calls made via the promise_setup infra and promise_test infra. It doesn't seem like the test uses promise_setup.

I'll look into understanding the change here a little bit more because there may be some interesting systemic things going on, but as things relate to this test specifically, I think we'll just be marking the test as an expected failure.

Assignee: nobody → bugmail
Status: NEW → ASSIGNED
Flags: needinfo?(bugmail)

Set release status flags based on info from the regressing bug 1900427

You need to log in before you can comment on or make changes to this bug.