Closed Bug 1779729 Opened 3 years ago Closed 2 years ago

Intermittent SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/obj-build/dist/include/nsTArray.h:575:51 in Hdr

Categories

(Core :: Panning and Zooming, defect, P1)

defect

Tracking

()

RESOLVED FIXED
104 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox-esr102 --- unaffected
firefox102 --- unaffected
firefox103 --- unaffected
firefox104 --- fixed

People

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

References

(Blocks 1 open bug, Regression)

Details

(4 keywords)

Attachments

(2 files)

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


[task 2022-07-15T09:45:09.722Z] 09:45:09     INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html
[task 2022-07-15T09:45:10.730Z] 09:45:10     INFO - GECKO(6519) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2022-07-15T09:45:10.731Z] 09:45:10     INFO - GECKO(6519) | WaitUntilApzStable: APZ flush done in parent proc
[task 2022-07-15T09:45:10.755Z] 09:45:10     INFO - GECKO(6519) | helper_scroll_snap_no_valid_snap_position.html | WaitUntilApzStable: got apz-flush-done in child proc
[task 2022-07-15T09:45:10.787Z] 09:45:10     INFO - GECKO(6519) | helper_scroll_snap_no_valid_snap_position.html | WaitUntilApzStable: done promiseFocus
[task 2022-07-15T09:45:10.855Z] 09:45:10     INFO - GECKO(6519) | helper_scroll_snap_no_valid_snap_position.html | WaitUntilApzStable: done promiseAllPaintsDone
[task 2022-07-15T09:45:10.860Z] 09:45:10     INFO - GECKO(6519) | helper_scroll_snap_no_valid_snap_position.html | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2022-07-15T09:45:10.883Z] 09:45:10     INFO - GECKO(6519) | helper_scroll_snap_no_valid_snap_position.html | PromiseApzRepaintsFlushed: APZ flush done
[task 2022-07-15T09:45:10.887Z] 09:45:10     INFO - GECKO(6519) | helper_scroll_snap_no_valid_snap_position.html | WaitUntilApzStable: all done
[task 2022-07-15T09:45:10.944Z] 09:45:10     INFO - GECKO(6519) | JavaScript error: , line 0: TypeError: can't access dead object
[task 2022-07-15T09:45:11.795Z] 09:45:11     INFO - GECKO(6519) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2022-07-15T09:45:11.796Z] 09:45:11     INFO - GECKO(6519) | WaitUntilApzStable: APZ flush done in parent proc
[task 2022-07-15T09:45:11.823Z] 09:45:11     INFO - GECKO(6519) | helper_scroll_snap_resnap_after_async_scroll.html | WaitUntilApzStable: got apz-flush-done in child proc
[task 2022-07-15T09:45:11.848Z] 09:45:11     INFO - GECKO(6519) | helper_scroll_snap_resnap_after_async_scroll.html | WaitUntilApzStable: done promiseFocus
[task 2022-07-15T09:45:11.933Z] 09:45:11     INFO - GECKO(6519) | helper_scroll_snap_resnap_after_async_scroll.html | WaitUntilApzStable: done promiseAllPaintsDone
[task 2022-07-15T09:45:11.942Z] 09:45:11     INFO - GECKO(6519) | helper_scroll_snap_resnap_after_async_scroll.html | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2022-07-15T09:45:11.944Z] 09:45:11     INFO - GECKO(6519) | helper_scroll_snap_resnap_after_async_scroll.html | PromiseApzRepaintsFlushed: APZ flush done
[task 2022-07-15T09:45:11.949Z] 09:45:11     INFO - GECKO(6519) | helper_scroll_snap_resnap_after_async_scroll.html | WaitUntilApzStable: all done
[task 2022-07-15T09:45:14.500Z] 09:45:14     INFO - GECKO(6519) | JavaScript error: , line 0: TypeError: can't access dead object
<...>
[task 2022-07-15T09:45:20.521Z] 09:45:20     INFO - GECKO(6519) |     #19 _pt_root /builds/worker/checkouts/gecko/nsprpub/pr/src/pthreads/ptthread.c:201:5 (libnspr4.so+0x4615d) (BuildId: 519c9e8e4b9577ce9ad018ca02127e1f6a0a71f0)
[task 2022-07-15T09:45:20.522Z] 09:45:20     INFO - GECKO(6519) | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/obj-build/dist/include/nsTArray.h:575:51 in Hdr
[task 2022-07-15T09:45:20.522Z] 09:45:20     INFO - GECKO(6519) | ==================
[task 2022-07-15T09:45:20.523Z] 09:45:20     INFO - GECKO(6519) | Exiting due to channel error.
[task 2022-07-15T09:45:20.524Z] 09:45:20     INFO - GECKO(6519) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=237.419) Exiting due to channel error.
[task 2022-07-15T09:45:20.524Z] 09:45:20     INFO - GECKO(6519) | Exiting due to channel error.
[task 2022-07-15T09:45:20.524Z] 09:45:20     INFO - GECKO(6519) | Exiting due to channel error.
[task 2022-07-15T09:45:20.524Z] 09:45:20     INFO - GECKO(6519) | Exiting due to channel error.
[task 2022-07-15T09:45:20.525Z] 09:45:20     INFO - GECKO(6519) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=105.486) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=247.55) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=104.081) Exiting due to channel error.
[task 2022-07-15T09:45:21.476Z] 09:45:21     INFO - GECKO(6519) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=106.881)
[task 2022-07-15T09:45:21.476Z] 09:45:21     INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2022-07-15T09:45:21.476Z] 09:45:21     INFO - Buffered messages logged at 09:45:09
[task 2022-07-15T09:45:21.477Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | Starting subtest helper_scroll_snap_no_valid_snap_position.html 
[task 2022-07-15T09:45:21.477Z] 09:45:21     INFO - Buffered messages logged at 09:45:10
[task 2022-07-15T09:45:21.478Z] 09:45:21     INFO - must wait for load
[task 2022-07-15T09:45:21.478Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | helper_scroll_snap_no_valid_snap_position.html | Scroll should happen some amount 
[task 2022-07-15T09:45:21.479Z] 09:45:21     INFO - must wait for focus
[task 2022-07-15T09:45:21.479Z] 09:45:21     INFO - Buffered messages logged at 09:45:11
[task 2022-07-15T09:45:21.480Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | Starting subtest helper_scroll_snap_resnap_after_async_scroll.html 
[task 2022-07-15T09:45:21.480Z] 09:45:21     INFO - must wait for load
[task 2022-07-15T09:45:21.481Z] 09:45:21     INFO - Buffered messages logged at 09:45:14
[task 2022-07-15T09:45:21.481Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | helper_scroll_snap_resnap_after_async_scroll.html | snap to 200px 
[task 2022-07-15T09:45:21.482Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | helper_scroll_snap_resnap_after_async_scroll.html | re-snap to 400px 
[task 2022-07-15T09:45:21.482Z] 09:45:21     INFO - Buffered messages logged at 09:45:17
[task 2022-07-15T09:45:21.483Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | helper_scroll_snap_resnap_after_async_scroll.html | Do not re-snap to the original 400px point 
[task 2022-07-15T09:45:21.483Z] 09:45:21     INFO - must wait for focus
[task 2022-07-15T09:45:21.483Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | Starting subtest helper_scroll_snap_resnap_after_async_scroll.html 
[task 2022-07-15T09:45:21.484Z] 09:45:21     INFO - Buffered messages logged at 09:45:18
[task 2022-07-15T09:45:21.484Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | helper_scroll_snap_resnap_after_async_scroll.html | snap to 200px 
[task 2022-07-15T09:45:21.487Z] 09:45:21     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | helper_scroll_snap_resnap_after_async_scroll.html | re-snap to 400px 
[task 2022-07-15T09:45:21.488Z] 09:45:21     INFO - Buffered messages finished
[task 2022-07-15T09:45:21.488Z] 09:45:21    ERROR - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_scroll_snap.html | application terminated with exit code -6
[task 2022-07-15T09:45:21.488Z] 09:45:21     INFO - runtests.py | Application ran for: 0:04:14.949765
[task 2022-07-15T09:45:21.488Z] 09:45:21     INFO - zombiecheck | Reading PID log: /tmp/tmplnx9l7xwpidlog
[task 2022-07-15T09:45:21.489Z] 09:45:21     INFO - ==> process 6519 launched child process 6535
[task 2022-07-15T09:45:21.489Z] 09:45:21     INFO - ==> process 6519 launched child process 6598
[task 2022-07-15T09:45:21.489Z] 09:45:21     INFO - ==> process 6519 launched child process 6622
[task 2022-07-15T09:45:21.489Z] 09:45:21     INFO - ==> process 6519 launched child process 6672
[task 2022-07-15T09:45:21.489Z] 09:45:21     INFO - ==> process 6519 launched child process 6673
[task 2022-07-15T09:45:21.489Z] 09:45:21     INFO - ==> process 6519 launched child process 6708
[task 2022-07-15T09:45:21.490Z] 09:45:21     INFO - ==> process 6519 launched child process 6737
[task 2022-07-15T09:45:21.490Z] 09:45:21     INFO - ==> process 6519 launched child process 6743
[task 2022-07-15T09:45:21.490Z] 09:45:21     INFO - ==> process 6519 launched child process 6800
[task 2022-07-15T09:45:21.490Z] 09:45:21     INFO - ==> process 6519 launched child process 6827
[task 2022-07-15T09:45:21.491Z] 09:45:21     INFO - ==> process 6519 launched child process 6853
[task 2022-07-15T09:45:21.491Z] 09:45:21     INFO - ==> process 6519 launched child process 6879
[task 2022-07-15T09:45:21.491Z] 09:45:21     INFO - ==> process 6519 launched child process 6905
[task 2022-07-15T09:45:21.491Z] 09:45:21     INFO - ==> process 6519 launched child process 6930
[task 2022-07-15T09:45:21.492Z] 09:45:21     INFO - ==> process 6519 launched child process 6956
[task 2022-07-15T09:45:21.492Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6853
[task 2022-07-15T09:45:21.492Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6598
[task 2022-07-15T09:45:21.492Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6535
[task 2022-07-15T09:45:21.493Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6827
[task 2022-07-15T09:45:21.493Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6956
[task 2022-07-15T09:45:21.493Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6672
[task 2022-07-15T09:45:21.493Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6673
[task 2022-07-15T09:45:21.493Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6737
[task 2022-07-15T09:45:21.494Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6800
[task 2022-07-15T09:45:21.495Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6708
[task 2022-07-15T09:45:21.495Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6930
[task 2022-07-15T09:45:21.495Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6743
[task 2022-07-15T09:45:21.495Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6905
[task 2022-07-15T09:45:21.496Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6622
[task 2022-07-15T09:45:21.497Z] 09:45:21     INFO - zombiecheck | Checking for orphan process with PID: 6879
[task 2022-07-15T09:45:21.497Z] 09:45:21     INFO - Stopping web server
[task 2022-07-15T09:45:21.498Z] 09:45:21     INFO - Server shut down.
[task 2022-07-15T09:45:21.519Z] 09:45:21     INFO - Web server killed.
[task 2022-07-15T09:45:21.519Z] 09:45:21     INFO - Stopping web socket server
[task 2022-07-15T09:45:21.539Z] 09:45:21     INFO - Stopping ssltunnel
[task 2022-07-15T09:45:21.560Z] 09:45:21  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2022-07-15T09:45:21.561Z] 09:45:21     INFO - runtests.py | Running tests: end.
[task 2022-07-15T09:45:21.596Z] 09:45:21     INFO - Buffered messages finished
[task 2022-07-15T09:45:21.596Z] 09:45:21     INFO -  0 INFO TEST-START | Shutdown
[task 2022-07-15T09:45:21.597Z] 09:45:21     INFO -  1 INFO Passed:  53297
[task 2022-07-15T09:45:21.597Z] 09:45:21     INFO -  2 INFO Failed:  0
[task 2022-07-15T09:45:21.597Z] 09:45:21     INFO -  3 INFO Todo:    122
[task 2022-07-15T09:45:21.598Z] 09:45:21     INFO -  4 INFO Mode:    e10s
[task 2022-07-15T09:45:21.598Z] 09:45:21     INFO -  5 INFO SimpleTest FINISHED
[task 2022-07-15T09:45:21.598Z] 09:45:21     INFO - Buffered messages finished
[task 2022-07-15T09:45:21.599Z] 09:45:21     INFO - SUITE-END | took 1092s
[task 2022-07-15T09:45:21.640Z] 09:45:21    ERROR - Return code: 250
[task 2022-07-15T09:45:21.641Z] 09:45:21     INFO - TinderboxPrint: mochitest-mochitest-plain<br/>352/0/0
[task 2022-07-15T09:45:21.641Z] 09:45:21    ERROR - # TBPL FAILURE #
[task 2022-07-15T09:45:21.641Z] 09:45:21  WARNING - setting return code to 2
[task 2022-07-15T09:45:21.641Z] 09:45:21    ERROR - The mochitest suite: mochitest-plain ran with return status: FAILURE
[task 2022-07-15T09:45:21.641Z] 09:45:21     INFO - Running post-action listener: _package_coverage_data
[task 2022-07-15T09:45:21.641Z] 09:45:21     INFO - Running post-action listener: _resource_record_post_action
[task 2022-07-15T09:45:21.641Z] 09:45:21     INFO - Running post-action listener: process_java_coverage_data
[task 2022-07-15T09:45:21.641Z] 09:45:21     INFO - [mozharness: 2022-07-15 09:45:21.641602Z] Finished run-tests step (success)
[task 2022-07-15T09:45:21.641Z] 09:45:21     INFO - Running post-run listener: _resource_record_post_run
[task 2022-07-15T09:45:21.778Z] 09:45:21     INFO - Validating Perfherder data against /builds/worker/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-plain.overall", "extraOptions": ["e10s", "taskcluster-projects/887720501152/machineTypes/n2-standard-4"], "subtests": [{"name": "cpu_percent", "value": 53.55689655172415}, {"name": "io_write_bytes", "value": 3982237696}, {"name": "io.read_bytes", "value": 0}, {"name": "io_write_time", "value": 1956352}, {"name": "io_read_time", "value": 0}]}, {"name": "mochitest.mochitest-plain.start-pulseaudio", "subtests": [{"name": "time", "value": 0.022935152053833008}]}, {"name": "mochitest.mochitest-plain.install", "subtests": [{"name": "time", "value": 39.020299196243286}, {"name": "cpu_percent", "value": 25.47432432432432}]}, {"name": "mochitest.mochitest-plain.stage-files", "subtests": [{"name": "time", "value": 0.0003535747528076172}]}, {"name": "mochitest.mochitest-plain.run-tests", "subtests": [{"name": "time", "value": 1093.925918340683}, {"name": "cpu_percent", "value": 54.558791208791206}]}]}
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - Total resource usage - Wall time: 1133s; CPU: 55%; Read bytes: 0; Write bytes: 3982237696; Read time: 0; Write time: 1956352
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - TinderboxPrint: CPU usage<br/>54.6%
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - TinderboxPrint: I/O read bytes / time<br/>0 / 0
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - TinderboxPrint: I/O write bytes / time<br/>3,982,237,696 / 1,956,352
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - TinderboxPrint: CPU idle<br/>2,088.4 (46.4%)
[task 2022-07-15T09:45:21.781Z] 09:45:21     INFO - TinderboxPrint: CPU system<br/>267.9 (6.0%)
[task 2022-07-15T09:45:21.782Z] 09:45:21     INFO - TinderboxPrint: CPU user<br/>2,134.0 (47.4%)
[task 2022-07-15T09:45:21.782Z] 09:45:21     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2022-07-15T09:45:21.782Z] 09:45:21     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-15T09:45:21.783Z] 09:45:21     INFO - install - Wall time: 39s; CPU: 25%; Read bytes: 0; Write bytes: 1987416064; Read time: 0; Write time: 1893736
[task 2022-07-15T09:45:21.783Z] 09:45:21     INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-15T09:45:21.790Z] 09:45:21     INFO - run-tests - Wall time: 1094s; CPU: 55%; Read bytes: 0; Write bytes: 1994821632; Read time: 0; Write time: 62616
[task 2022-07-15T09:45:21.949Z] 09:45:21  WARNING - returning nonzero exit status 2
[task 2022-07-15T09:45:21.997Z] cleanup
[task 2022-07-15T09:45:21.997Z] + cleanup
[task 2022-07-15T09:45:21.997Z] + local rv=2
[task 2022-07-15T09:45:21.997Z] + [[ -s /builds/worker/.xsession-errors ]]
[task 2022-07-15T09:45:21.997Z] + cp /builds/worker/.xsession-errors /builds/worker/artifacts/public/xsession-errors.log
[task 2022-07-15T09:45:21.999Z] + '[' ']'
[task 2022-07-15T09:45:21.999Z] + true
[task 2022-07-15T09:45:21.999Z] + cleanup_xvfb
[task 2022-07-15T09:45:21.999Z] ++ pidof Xvfb
[task 2022-07-15T09:45:22.006Z] + local xvfb_pid=50
[task 2022-07-15T09:45:22.006Z] + local vnc=false
[task 2022-07-15T09:45:22.006Z] + local interactive=false
[task 2022-07-15T09:45:22.006Z] + '[' -n 50 ']'
[task 2022-07-15T09:45:22.006Z] + [[ false == false ]]
[task 2022-07-15T09:45:22.006Z] + [[ false == false ]]
[task 2022-07-15T09:45:22.006Z] + kill 50
[task 2022-07-15T09:45:22.006Z] + screen -XS xvfb quit
[task 2022-07-15T09:45:22.022Z] + exit 2
[taskcluster 2022-07-15 09:45:22.338Z] === Task Finished ===
[taskcluster 2022-07-15 09:45:25.258Z] Unsuccessful task run with exit code: 2 completed in 1259.122 seconds

Group: core-security → gfx-core-security
Keywords: csectype-race

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

Attached file TSan report

I think these APZ races are kind of sec-moderate-ish.

Blocks: tsan
Keywords: sec-moderate
Assignee: nobody → hikezoe.birchill
Status: NEW → ASSIGNED
Severity: -- → S2
Priority: -- → P1
Group: gfx-core-security → core-security-release
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 104 Branch
Group: core-security-release
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: