Closed Bug 1709888 Opened 4 years ago Closed 3 years ago

Intermittent widget/tests/browser/browser_test_swipe_gesture.js | Received all wheel events - Got 1, expected 3

Categories

(Core :: Widget, defect)

defect

Tracking

()

RESOLVED FIXED
102 Branch
Tracking Status
firefox102 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown][stockwell unknown])

Attachments

(1 file)

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


[task 2021-05-06T15:08:39.664Z] 15:08:39     INFO - TEST-START | widget/tests/browser/browser_test_swipe_gesture.js
[task 2021-05-06T15:08:40.120Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser to start load of about:about
[task 2021-05-06T15:08:40.122Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser state change of about:about
[task 2021-05-06T15:08:40.158Z] 15:08:40     INFO - GECKO(2098) | Saw state 10f0001 and status 0
[task 2021-05-06T15:08:40.191Z] 15:08:40     INFO - GECKO(2098) | Browser got expected state change about:about
[task 2021-05-06T15:08:40.211Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser load of about:about
[task 2021-05-06T15:08:40.212Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser state change of about:about
[task 2021-05-06T15:08:40.217Z] 15:08:40     INFO - GECKO(2098) | Saw state 10c0010 and status 0
[task 2021-05-06T15:08:40.217Z] 15:08:40     INFO - GECKO(2098) | Browser got expected state change about:about
[task 2021-05-06T15:08:40.218Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser to start load of about:mozilla
[task 2021-05-06T15:08:40.218Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser state change of about:mozilla
[task 2021-05-06T15:08:40.257Z] 15:08:40     INFO - GECKO(2098) | Saw state 10f0001 and status 0
[task 2021-05-06T15:08:40.257Z] 15:08:40     INFO - GECKO(2098) | Browser got expected state change about:mozilla
[task 2021-05-06T15:08:40.258Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser load of about:mozilla
[task 2021-05-06T15:08:40.259Z] 15:08:40     INFO - GECKO(2098) | Waiting for browser state change of about:mozilla
[task 2021-05-06T15:08:40.268Z] 15:08:40     INFO - GECKO(2098) | Saw state 10c0010 and status 0
[task 2021-05-06T15:08:40.269Z] 15:08:40     INFO - GECKO(2098) | Browser got expected state change about:mozilla
[task 2021-05-06T15:08:40.281Z] 15:08:40     INFO - TEST-INFO | started process screencapture
[task 2021-05-06T15:08:40.497Z] 15:08:40     INFO - TEST-INFO | screencapture: exit 0
[task 2021-05-06T15:08:40.498Z] 15:08:40     INFO - Buffered messages logged at 15:08:39
[task 2021-05-06T15:08:40.498Z] 15:08:40     INFO - Entering test bound 
[task 2021-05-06T15:08:40.499Z] 15:08:40     INFO - Buffered messages logged at 15:08:40
[task 2021-05-06T15:08:40.500Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - 
[task 2021-05-06T15:08:40.500Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - 
[task 2021-05-06T15:08:40.501Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | Received 3 wheel events - 
[task 2021-05-06T15:08:40.502Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - 
[task 2021-05-06T15:08:40.504Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | Received a wheel event - 
[task 2021-05-06T15:08:40.504Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - 
[task 2021-05-06T15:08:40.505Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | Received a wheel event - 
[task 2021-05-06T15:08:40.505Z] 15:08:40     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - 
[task 2021-05-06T15:08:40.505Z] 15:08:40     INFO - Buffered messages finished
[task 2021-05-06T15:08:40.506Z] 15:08:40     INFO - TEST-UNEXPECTED-FAIL | widget/tests/browser/browser_test_swipe_gesture.js | Received all wheel events - Got 1, expected 3
[task 2021-05-06T15:08:40.507Z] 15:08:40     INFO - Stack trace:
[task 2021-05-06T15:08:40.507Z] 15:08:40     INFO - chrome://mochikit/content/browser-test.js:test_is:1369
[task 2021-05-06T15:08:40.507Z] 15:08:40     INFO - chrome://mochitests/content/browser/widget/tests/browser/browser_test_swipe_gesture.js:null:170
[task 2021-05-06T15:08:40.508Z] 15:08:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-05-06T15:08:40.508Z] 15:08:40     INFO - TEST-UNEXPECTED-FAIL | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - Got "about:about", expected "about:mozilla"
[task 2021-05-06T15:08:40.509Z] 15:08:40     INFO - Stack trace:
[task 2021-05-06T15:08:40.509Z] 15:08:40     INFO - chrome://mochikit/content/browser-test.js:test_is:1369
[task 2021-05-06T15:08:40.509Z] 15:08:40     INFO - chrome://mochitests/content/browser/widget/tests/browser/browser_test_swipe_gesture.js:null:174
[task 2021-05-06T15:08:40.509Z] 15:08:40     INFO - Leaving test bound 
[task 2021-05-06T15:08:40.510Z] 15:08:40     INFO - GECKO(2098) | MEMORY STAT | vsize 8011MB | residentFast 451MB | heapAllocated 191MB
[task 2021-05-06T15:08:40.511Z] 15:08:40     INFO - TEST-OK | widget/tests/browser/browser_test_swipe_gesture.js | took 694ms
[task 2021-05-06T15:08:40.512Z] 15:08:40     INFO - checking window state
[task 2021-05-06T15:08:40.512Z] 15:08:40     INFO - GECKO(2098) | Completed ShutdownLeaks collections in process 2098
[task 2021-05-06T15:08:40.513Z] 15:08:40     INFO - TEST-START | Shutdown
[task 2021-05-06T15:08:40.514Z] 15:08:40     INFO - Browser Chrome Test Summary
[task 2021-05-06T15:08:40.514Z] 15:08:40     INFO - Passed:  16
[task 2021-05-06T15:08:40.515Z] 15:08:40     INFO - Failed:  2
[task 2021-05-06T15:08:40.516Z] 15:08:40     INFO - Todo:    0
[task 2021-05-06T15:08:40.516Z] 15:08:40     INFO - Mode:    e10s
[task 2021-05-06T15:08:40.517Z] 15:08:40     INFO - *** End BrowserChrome Test Results ***
[task 2021-05-06T15:08:40.518Z] 15:08:40     INFO - GECKO(2098) | Exiting due to channel error.
[task 2021-05-06T15:08:40.518Z] 15:08:40     INFO - GECKO(2098) | Exiting due to channel error.
[task 2021-05-06T15:08:40.518Z] 15:08:40     INFO - GECKO(2098) | Exiting due to channel error.
[task 2021-05-06T15:08:40.519Z] 15:08:40     INFO - GECKO(2098) | Exiting due to channel error.
[task 2021-05-06T15:08:40.519Z] 15:08:40     INFO - GECKO(2098) | Exiting due to channel error.
[task 2021-05-06T15:08:40.520Z] 15:08:40     INFO - GECKO(2098) | Exiting due to channel error.
[task 2021-05-06T15:08:40.664Z] 15:08:40     INFO - TEST-INFO | Main app process: exit 0
[task 2021-05-06T15:08:40.665Z] 15:08:40     INFO - runtests.py | Application ran for: 0:00:26.083467
[task 2021-05-06T15:08:40.665Z] 15:08:40     INFO - zombiecheck | Reading PID log: /var/folders/1h/6_tmz4vn6c99m62hkt1zpfpr000017/T/tmp8ovw6h6tpidlog
[task 2021-05-06T15:08:40.666Z] 15:08:40     INFO - ==> process 2098 launched child process 2099
[task 2021-05-06T15:08:40.666Z] 15:08:40     INFO - ==> process 2098 launched child process 2100
[task 2021-05-06T15:08:40.667Z] 15:08:40     INFO - ==> process 2098 launched child process 2101
[task 2021-05-06T15:08:40.667Z] 15:08:40     INFO - ==> process 2098 launched child process 2102
[task 2021-05-06T15:08:40.668Z] 15:08:40     INFO - ==> process 2098 launched child process 2103
[task 2021-05-06T15:08:40.668Z] 15:08:40     INFO - ==> process 2098 launched child process 2105
[task 2021-05-06T15:08:40.668Z] 15:08:40     INFO - zombiecheck | Checking for orphan process with PID: 2099
[task 2021-05-06T15:08:40.669Z] 15:08:40     INFO - zombiecheck | Checking for orphan process with PID: 2100
[task 2021-05-06T15:08:40.669Z] 15:08:40     INFO - zombiecheck | Checking for orphan process with PID: 2101
[task 2021-05-06T15:08:40.670Z] 15:08:40     INFO - zombiecheck | Checking for orphan process with PID: 2102
[task 2021-05-06T15:08:40.670Z] 15:08:40     INFO - zombiecheck | Checking for orphan process with PID: 2103
[task 2021-05-06T15:08:40.671Z] 15:08:40     INFO - zombiecheck | Checking for orphan process with PID: 2105
[task 2021-05-06T15:08:40.672Z] 15:08:40     INFO - Stopping web server
[task 2021-05-06T15:08:40.673Z] 15:08:40     INFO - Server shut down.
[task 2021-05-06T15:08:40.839Z] 15:08:40     INFO - Web server killed.
[task 2021-05-06T15:08:40.839Z] 15:08:40     INFO - Stopping web socket server
[task 2021-05-06T15:08:40.864Z] 15:08:40     INFO - Stopping ssltunnel
[task 2021-05-06T15:08:41.011Z] 15:08:41  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-05-06T15:08:41.011Z] 15:08:41     INFO - runtests.py | Running tests: end.
[task 2021-05-06T15:08:41.034Z] 15:08:41     INFO - Buffered messages finished
[task 2021-05-06T15:08:41.035Z] 15:08:41     INFO -  TEST-INFO | checking window state
[task 2021-05-06T15:08:41.035Z] 15:08:41     INFO -  Browser Chrome Test Summary
[task 2021-05-06T15:08:41.035Z] 15:08:41     INFO -  	Passed: 12476
[task 2021-05-06T15:08:41.035Z] 15:08:41     INFO -  	Failed: 2
[task 2021-05-06T15:08:41.036Z] 15:08:41     INFO -  	Todo: 15
[task 2021-05-06T15:08:41.036Z] 15:08:41     INFO -  	Mode: e10s
[task 2021-05-06T15:08:41.036Z] 15:08:41     INFO -  *** End BrowserChrome Test Results ***
[task 2021-05-06T15:08:41.036Z] 15:08:41     INFO - Buffered messages finished
[task 2021-05-06T15:08:41.037Z] 15:08:41     INFO - SUITE-END | took 1188s
[task 2021-05-06T15:08:41.090Z] 15:08:41    ERROR - Return code: 1
[task 2021-05-06T15:08:41.090Z] 15:08:41    ERROR - Got 2 unexpected statuses
[task 2021-05-06T15:08:41.090Z] 15:08:41     INFO - TinderboxPrint: mochitest-mochitest-browser-chrome<br/>905/<em class="testfail">2</em>/0
[task 2021-05-06T15:08:41.091Z] 15:08:41  WARNING - # TBPL WARNING #
[task 2021-05-06T15:08:41.091Z] 15:08:41  WARNING - setting return code to 1
[task 2021-05-06T15:08:41.091Z] 15:08:41  WARNING - The mochitest suite: mochitest-browser-chrome ran with return status: WARNING
[task 2021-05-06T15:08:41.091Z] 15:08:41     INFO - Running post-action listener: _package_coverage_data
[task 2021-05-06T15:08:41.091Z] 15:08:41     INFO - Running post-action listener: _resource_record_post_action
[task 2021-05-06T15:08:41.091Z] 15:08:41     INFO - Running post-action listener: process_java_coverage_data
[task 2021-05-06T15:08:41.092Z] 15:08:41     INFO - [mozharness: 2021-05-06 15:08:41.091875Z] Finished run-tests step (success)
[task 2021-05-06T15:08:41.092Z] 15:08:41     INFO - Running post-run listener: _resource_record_post_run
[task 2021-05-06T15:08:41.219Z] 15:08:41     INFO - instance_metadata.json not found; unable to determine instance type
[task 2021-05-06T15:08:41.222Z] 15:08:41     INFO - Validating Perfherder data against /Users/cltbld/tasks/task_1620312405/mozharness/external_tools/performance-artifact-schema.json
[task 2021-05-06T15:08:41.225Z] 15:08:41     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-browser-chrome.overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 17.71860918544195}, {"name": "io_write_bytes", "value": 3864356352}, {"name": "io.read_bytes", "value": 285061120}, {"name": "io_write_time", "value": 21980}, {"name": "io_read_time", "value": 4957}]}, {"name": "mochitest.mochitest-browser-chrome.start-pulseaudio", "subtests": [{"name": "time", "value": 0.0007469654083251953}]}, {"name": "mochitest.mochitest-browser-chrome.install", "subtests": [{"name": "time", "value": 20.005730152130127}, {"name": "cpu_percent", "value": 37.468421052631584}]}, {"name": "mochitest.mochitest-browser-chrome.stage-files", "subtests": [{"name": "time", "value": 0.0005340576171875}]}, {"name": "mochitest.mochitest-browser-chrome.run-tests", "subtests": [{"name": "time", "value": 1190.177740097046}, {"name": "cpu_percent", "value": 17.349537037037038}]}]}
[task 2021-05-06T15:08:41.225Z] 15:08:41     INFO - Total resource usage - Wall time: 1210s; CPU: 17%; Read bytes: 285061120; Write bytes: 3864356352; Read time: 4957; Write time: 21980
[task 2021-05-06T15:08:41.225Z] 15:08:41     INFO - TinderboxPrint: CPU usage<br/>17.3%
[task 2021-05-06T15:08:41.226Z] 15:08:41     INFO - TinderboxPrint: I/O read bytes / time<br/>285,061,120 / 4,957
[task 2021-05-06T15:08:41.226Z] 15:08:41     INFO - TinderboxPrint: I/O write bytes / time<br/>3,864,356,352 / 21,980
[task 2021-05-06T15:08:41.226Z] 15:08:41     INFO - TinderboxPrint: CPU idle<br/>3,669.8 (75.8%)
[task 2021-05-06T15:08:41.226Z] 15:08:41     INFO - TinderboxPrint: CPU system<br/>268.9 (5.6%)
[task 2021-05-06T15:08:41.226Z] 15:08:41     INFO - TinderboxPrint: CPU user<br/>900.8 (18.6%)
[task 2021-05-06T15:08:41.226Z] 15:08:41     INFO - TinderboxPrint: Swap in / out<br/>482,627,584 / 0
[task 2021-05-06T15:08:41.227Z] 15:08:41     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-05-06T15:08:41.227Z] 15:08:41     INFO - install - Wall time: 20s; CPU: 37%; Read bytes: 250091008; Write bytes: 235479040; Read time: 16731; Write time: 503
[task 2021-05-06T15:08:41.228Z] 15:08:41     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2021-05-06T15:08:41.236Z] 15:08:41     INFO - run-tests - Wall time: 1190s; CPU: 17%; Read bytes: 277291008; Write bytes: 3610404352; Read time: 4852; Write time: 21418
[task 2021-05-06T15:08:41.416Z] 15:08:41  WARNING - returning nonzero exit status 1
[taskcluster 2021-05-06T15:08:41.469Z]    Exit Code: 1
[taskcluster 2021-05-06T15:08:41.469Z]    User Time: 11m29.613476s
[taskcluster 2021-05-06T15:08:41.469Z]  Kernel Time: 2m17.536459s
[taskcluster 2021-05-06T15:08:41.469Z]    Wall Time: 21m52.97316166s
[taskcluster 2021-05-06T15:08:41.469Z]       Result: FAILED
[taskcluster 2021-05-06T15:08:41.469Z] === Task Finished ===
[taskcluster 2021-05-06T15:08:41.469Z] Task Duration: 21m52.977828749s
[taskcluster 2021-05-06T15:08:41.595Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:41.801Z] Uploading artifact public/test_info/manifests.list from file build/blobber_upload_dir/manifests.list with content encoding "gzip", mime type "text/plain; charset=utf-8" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:41.917Z] Uploading artifact public/test_info/mochitest-browser-chrome_errorsummary.log from file build/blobber_upload_dir/mochitest-browser-chrome_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:42.037Z] Uploading artifact public/test_info/mochitest-browser-chrome_raw.log from file build/blobber_upload_dir/mochitest-browser-chrome_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:42.240Z] Uploading artifact public/test_info/mozilla-test-fail-screenshot_39pp0wzu.png from file build/blobber_upload_dir/mozilla-test-fail-screenshot_39pp0wzu.png with content encoding "", mime type "image/png" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:42.395Z] Uploading artifact public/test_info/profile_backgroundtask_wait.json from file build/blobber_upload_dir/profile_backgroundtask_wait.json with content encoding "gzip", mime type "application/json" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:42.574Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:42.756Z] Uploading artifact public/test_info/system-info.log from file build/blobber_upload_dir/system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2022-05-06T13:50:05.454Z
[taskcluster 2021-05-06T15:08:42.883Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/a_mFmfyETAOSz6oQOLuEgw/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-05-06T13:50:05.454Z
[taskcluster:error] exit status 1```

There have been 30 total failures in the last 7 days, recent failure log.
Affected platforms are:

  • macosx1015-64-shippable-qr
  • windows10-32-2004-qr
  • windows10-64-2004-asan-qr
  • windows10-64-2004-qr
[task 2022-04-25T08:41:52.659Z] 08:41:52     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - 
[task 2022-04-25T08:41:52.659Z] 08:41:52     INFO - Buffered messages finished
[task 2022-04-25T08:41:52.660Z] 08:41:52     INFO - TEST-UNEXPECTED-FAIL | widget/tests/browser/browser_test_swipe_gesture.js | Received all wheel events - Got 1, expected 3
[task 2022-04-25T08:41:52.660Z] 08:41:52     INFO - Stack trace:
[task 2022-04-25T08:41:52.660Z] 08:41:52     INFO - chrome://mochikit/content/browser-test.js:test_is:1422
[task 2022-04-25T08:41:52.660Z] 08:41:52     INFO - chrome://mochitests/content/browser/widget/tests/browser/browser_test_swipe_gesture.js:null:221
[task 2022-04-25T08:41:52.660Z] 08:41:52     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-04-25T08:41:52.661Z] 08:41:52     INFO - TEST-UNEXPECTED-FAIL | widget/tests/browser/browser_test_swipe_gesture.js | undefined assertion name - Got "about:about", expected "about:mozilla"
[task 2022-04-25T08:41:52.661Z] 08:41:52     INFO - Stack trace:
[task 2022-04-25T08:41:52.661Z] 08:41:52     INFO - chrome://mochikit/content/browser-test.js:test_is:1422
[task 2022-04-25T08:41:52.661Z] 08:41:52     INFO - chrome://mochitests/content/browser/widget/tests/browser/browser_test_swipe_gesture.js:null:225
[task 2022-04-25T08:41:52.662Z] 08:41:52     INFO - TEST-PASS | widget/tests/browser/browser_test_swipe_gesture.js | Received all wheel events - 
Priority: -- → P4

The timeout in requestIdleCallback is a deadline, so we wait until the firrst time we are idle and then call the callback, or if we haven't gone idle before the timeout period then just call the callback. So it functions as a maximum, not a minimum. So if we are already idle it could callback right away.

So wait one frame to make sure any other potential events, input etc is flushed before we move on.

I haven't debugged this in detail but this seems to fix the problem and seems reasonable.

Assignee: nobody → tnikkel
Status: NEW → ASSIGNED
Pushed by tnikkel@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/dd7e11f8b419 Wait one from in browser_test_swipe_gesture.js to make sure all events/input are flushed. r=hiro
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 102 Branch

The failure can still be observed (once for autoland, 5x for beta or central-as-beta simulations). Do you want a new bug?

Flags: needinfo?(tnikkel)

Yeah please, file a new bug and we'll track it there. Easier to follow that way. Thanks!

Flags: needinfo?(tnikkel)
See Also: → 1772288
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: