Closed Bug 1892522 Opened 1 year ago Closed 11 months ago

Intermittent SUMMARY: AddressSanitizer: use-after-poison /builds/worker/workspace/obj-build/dist/include/js/Proxy.h:384 in js::IsProxy

Categories

(Core :: DLL Services, defect)

defect

Tracking

()

RESOLVED FIXED
130 Branch
Tracking Status
firefox130 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2024-04-19T20:08:41.388Z] 20:08:41     INFO -  TEST-START | UntrustedModulesFixture.Serialize
[task 2024-04-19T20:08:41.502Z] 20:08:41     INFO -  Received data. (attempts=1)
[task 2024-04-19T20:08:41.565Z] 20:08:41     INFO -  Received data. (attempts=2)
[task 2024-04-19T20:08:41.643Z] 20:08:41     INFO -  Received data. (attempts=2)
[task 2024-04-19T20:08:41.659Z] 20:08:41     INFO -  Received data. (attempts=2)
[task 2024-04-19T20:08:41.676Z] 20:08:41     INFO -  Received data. (attempts=2)
[task 2024-04-19T20:08:41.684Z] 20:08:41     INFO -  =================================================================
[task 2024-04-19T20:08:41.800Z] 20:08:41    ERROR -  ==3272==ERROR: AddressSanitizer: use-after-poison on address 0x2b653fbe5088 at pc 0x7ff9af20f64f bp 0x0051767fb3d0 sp 0x0051767fb418
[task 2024-04-19T20:08:41.803Z] 20:08:41     INFO -  READ of size 8 at 0x2b653fbe5088 thread T0
[task 2024-04-19T20:08:42.443Z] 20:08:42     INFO -      #0 0x7ff9af20f64e in js::IsProxy /builds/worker/workspace/obj-build/dist/include/js/Proxy.h:384
[task 2024-04-19T20:08:42.452Z] 20:08:42     INFO -      #1 0x7ff9af20f64e in js::IsWrapper /builds/worker/workspace/obj-build/dist/include/js/Wrapper.h:393
[task 2024-04-19T20:08:42.452Z] 20:08:42     INFO -      #2 0x7ff9af20f64e in js::IsCrossCompartmentWrapper /builds/worker/workspace/obj-build/dist/include/js/Wrapper.h:397
[task 2024-04-19T20:08:42.452Z] 20:08:42     INFO -      #3 0x7ff9af20f64e in JS::GetNonCCWObjectGlobal(class JSObject *) /builds/worker/checkouts/gecko/js/src/jsapi.cpp:1194
[task 2024-04-19T20:08:42.453Z] 20:08:42     INFO -      #4 0x7ff9a2109f4a in xpc::NativeGlobal(class JSObject *) /builds/worker/checkouts/gecko/js/xpconnect/wrappers/WrapperFactory.cpp:787
[task 2024-04-19T20:08:42.453Z] 20:08:42     INFO -      #5 0x7ff9aa1d2aba in mozilla::dom::AutoJSAPI::Init(class JSObject *) /builds/worker/checkouts/gecko/dom/script/ScriptSettings.cpp:431
[task 2024-04-19T20:08:42.454Z] 20:08:42     INFO -      #6 0x7ff99f82f23b in AutoJSContextWithGlobal::AutoJSContextWithGlobal(class JSObject *) /builds/worker/checkouts/gecko/toolkit/components/telemetry/tests/gtest/TelemetryFixture.cpp:26
[task 2024-04-19T20:08:42.454Z] 20:08:42     INFO -      #7 0x7ff99f9ca21c in UntrustedModulesFixture::ValidateJSValue /builds/worker/checkouts/gecko/toolkit/xre/dllservices/tests/gtest/TestUntrustedModules.cpp:220
[task 2024-04-19T20:08:42.455Z] 20:08:42     INFO -      #8 0x7ff99f9ca21c in UntrustedModulesFixture_Serialize_Test::TestBody(void) /builds/worker/checkouts/gecko/toolkit/xre/dllservices/tests/gtest/TestUntrustedModules.cpp:437
[task 2024-04-19T20:08:42.456Z] 20:08:42     INFO -      #9 0x7ff99d7a5fd6 in testing::internal::HandleSehExceptionsInMethodIfSupported<class testing::TestSuite, void>(class testing::TestSuite *, void (__cdecl testing::TestSuite::*)(void), char const *) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:2606
[task 2024-04-19T20:08:42.456Z] 20:08:42     INFO -      #10 0x7ff99d738738 in testing::Test::Run(void) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:2688
[task 2024-04-19T20:08:42.457Z] 20:08:42     INFO -      #11 0x7ff99d73c98e in testing::TestInfo::Run(void) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:2837
[task 2024-04-19T20:08:42.457Z] 20:08:42     INFO -      #12 0x7ff99d73f738 in testing::TestSuite::Run(void) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:3016
[task 2024-04-19T20:08:42.458Z] 20:08:42     INFO -      #13 0x7ff99d7856af in testing::internal::UnitTestImpl::RunAllTests(void) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:5922
[task 2024-04-19T20:08:42.458Z] 20:08:42     INFO -      #14 0x7ff99d7a6016 in testing::internal::HandleSehExceptionsInMethodIfSupported<class testing::internal::UnitTestImpl, bool>(class testing::internal::UnitTestImpl *, bool (__cdecl testing::internal::UnitTestImpl::*)(void), char const *) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:2606
[task 2024-04-19T20:08:42.459Z] 20:08:42     INFO -      #15 0x7ff99d78490e in testing::UnitTest::Run(void) /builds/worker/checkouts/gecko/third_party/googletest/googletest/src/gtest.cc:5486
[task 2024-04-19T20:08:42.459Z] 20:08:42     INFO -      #16 0x7ff99d6aebe0 in RUN_ALL_TESTS /builds/worker/workspace/obj-build/dist/include/gtest/gtest.h:2319
[task 2024-04-19T20:08:42.460Z] 20:08:42     INFO -      #17 0x7ff99d6aebe0 in mozilla::RunGTestFunc(int *, char **) /builds/worker/checkouts/gecko/testing/gtest/mozilla/GTestRunner.cpp:167
[task 2024-04-19T20:08:42.460Z] 20:08:42     INFO -      #18 0x7ff9aebcb8fa in XREMain::XRE_mainStartup(bool *) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:4686
[task 2024-04-19T20:08:42.460Z] 20:08:42     INFO -      #19 0x7ff9aebe3c4e in XREMain::XRE_main(int, char **const, struct mozilla::BootstrapConfig const &) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5946
[task 2024-04-19T20:08:42.461Z] 20:08:42     INFO -      #20 0x7ff9aebe4e2f in XRE_main(int, char **const, struct mozilla::BootstrapConfig const &) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:6015
[task 2024-04-19T20:08:42.461Z] 20:08:42     INFO -      #21 0x7ff72a592258 in do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:227
[task 2024-04-19T20:08:42.462Z] 20:08:42     INFO -      #22 0x7ff72a592258 in NS_internal_main(int, char **, char **) /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:445
[task 2024-04-19T20:08:42.462Z] 20:08:42     INFO -      #23 0x7ff72a59161a in wmain /builds/worker/checkouts/gecko/toolkit/xre/nsWindowsWMain.cpp:174
[task 2024-04-19T20:08:42.462Z] 20:08:42     INFO -      #24 0x7ff72a67fae7 in invoke_main D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:90
[task 2024-04-19T20:08:42.462Z] 20:08:42     INFO -      #25 0x7ff72a67fae7 in __scrt_common_main_seh D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl:288
[task 2024-04-19T20:08:42.463Z] 20:08:42     INFO -      #26 0x7ff9efe7257c  (C:\Windows\System32\KERNEL32.DLL+0x18001257c)
[task 2024-04-19T20:08:42.463Z] 20:08:42     INFO -      #27 0x7ff9f14eaa47  (C:\Windows\SYSTEM32\ntdll.dll+0x18005aa47)
[task 2024-04-19T20:08:42.464Z] 20:08:42     INFO -  Address 0x2b653fbe5088 is a wild pointer inside of access range of size 0x000000000008.
[task 2024-04-19T20:08:42.464Z] 20:08:42     INFO -  SUMMARY: AddressSanitizer: use-after-poison /builds/worker/workspace/obj-build/dist/include/js/Proxy.h:384 in js::IsProxy
[task 2024-04-19T20:08:42.464Z] 20:08:42     INFO -  Shadow bytes around the buggy address:
[task 2024-04-19T20:08:42.465Z] 20:08:42     INFO -    0x2b653fbe4e00: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.465Z] 20:08:42     INFO -    0x2b653fbe4e80: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.465Z] 20:08:42     INFO -    0x2b653fbe4f00: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.465Z] 20:08:42     INFO -    0x2b653fbe4f80: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.466Z] 20:08:42     INFO -    0x2b653fbe5000: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.466Z] 20:08:42     INFO -  =>0x2b653fbe5080: f7[f7]f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.466Z] 20:08:42     INFO -    0x2b653fbe5100: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.466Z] 20:08:42     INFO -    0x2b653fbe5180: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.467Z] 20:08:42     INFO -    0x2b653fbe5200: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.467Z] 20:08:42     INFO -    0x2b653fbe5280: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.467Z] 20:08:42     INFO -    0x2b653fbe5300: f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7 f7
[task 2024-04-19T20:08:42.468Z] 20:08:42     INFO -  Shadow byte legend (one shadow byte represents 8 application bytes):
[task 2024-04-19T20:08:42.468Z] 20:08:42     INFO -    Addressable:           00
[task 2024-04-19T20:08:42.468Z] 20:08:42     INFO -    Partially addressable: 01 02 03 04 05 06 07
[task 2024-04-19T20:08:42.468Z] 20:08:42     INFO -    Heap left redzone:       fa
[task 2024-04-19T20:08:42.468Z] 20:08:42     INFO -    Freed heap region:       fd
[task 2024-04-19T20:08:42.468Z] 20:08:42     INFO -    Stack left redzone:      f1
[task 2024-04-19T20:08:42.469Z] 20:08:42     INFO -    Stack mid redzone:       f2
[task 2024-04-19T20:08:42.469Z] 20:08:42     INFO -    Stack right redzone:     f3
[task 2024-04-19T20:08:42.469Z] 20:08:42     INFO -    Stack after return:      f5
[task 2024-04-19T20:08:42.470Z] 20:08:42     INFO -    Stack use after scope:   f8
[task 2024-04-19T20:08:42.470Z] 20:08:42     INFO -    Global redzone:          f9
[task 2024-04-19T20:08:42.470Z] 20:08:42     INFO -    Global init order:       f6
[task 2024-04-19T20:08:42.470Z] 20:08:42     INFO -    Poisoned by user:        f7
[task 2024-04-19T20:08:42.470Z] 20:08:42     INFO -    Container overflow:      fc
[task 2024-04-19T20:08:42.470Z] 20:08:42     INFO -    Array cookie:            ac
[task 2024-04-19T20:08:42.471Z] 20:08:42     INFO -    Intra object redzone:    bb
[task 2024-04-19T20:08:42.471Z] 20:08:42     INFO -    ASan internal:           fe
[task 2024-04-19T20:08:42.471Z] 20:08:42     INFO -    Left alloca redzone:     ca
[task 2024-04-19T20:08:42.471Z] 20:08:42     INFO -    Right alloca redzone:    cb
[task 2024-04-19T20:08:42.471Z] 20:08:42     INFO -  ==3272==ABORTING
[task 2024-04-19T20:08:44.303Z] 20:08:44     INFO -  gtest INFO | gtest | process wait complete, returncode=1
[task 2024-04-19T20:08:44.310Z] 20:08:44     INFO -  mozcrash checking D:\task_171355331131192\build\tests\gtest for minidumps...
[task 2024-04-19T20:08:44.313Z] 20:08:44  WARNING -  gtest TEST-UNEXPECTED-FAIL | gtest | test failed with return code 1
[task 2024-04-19T20:08:44.313Z] 20:08:44     INFO -  gtest INFO | rungtests.py exits with code 1
[task 2024-04-19T20:08:44.366Z] 20:08:44     INFO - Return code: 1
[task 2024-04-19T20:08:44.378Z] 20:08:44    ERROR - No tests run or test summary not found
[task 2024-04-19T20:08:44.378Z] 20:08:44     INFO - TinderboxPrint: gtest-gtest<br/><em class="testfail">T-FAIL</em>
[task 2024-04-19T20:08:44.379Z] 20:08:44  WARNING - setting return code to 2
[task 2024-04-19T20:08:44.379Z] 20:08:44     INFO - The gtest suite: gtest ran with return status: FAILURE
[task 2024-04-19T20:08:44.381Z] 20:08:44     INFO - Running post-action listener: _package_coverage_data
[task 2024-04-19T20:08:44.381Z] 20:08:44     INFO - Running post-action listener: _resource_record_post_action
[task 2024-04-19T20:08:44.381Z] 20:08:44     INFO - Running post-action listener: process_java_coverage_data
[task 2024-04-19T20:08:44.381Z] 20:08:44     INFO - [mozharness: 2024-04-19 20:08:44.381948Z] Finished run-tests step (success)
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - [mozharness: 2024-04-19 20:08:44.381948Z] Running uninstall step.
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - Running pre-action listener: _resource_record_pre_action
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - Running main action method: uninstall
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - Skipping uninstall for non-MSIX test
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - Running post-action listener: _resource_record_post_action
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - [mozharness: 2024-04-19 20:08:44.382456Z] Finished uninstall step (success)
[task 2024-04-19T20:08:44.382Z] 20:08:44     INFO - Running post-run listener: _resource_record_post_run
[task 2024-04-19T20:08:45.241Z] 20:08:45     INFO - instance_metadata.json not found; unable to determine instance type
[task 2024-04-19T20:08:45.261Z] 20:08:45     INFO - Validating Perfherder data against D:\task_171355331131192\mozharness\external_tools\performance-artifact-schema.json
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "gtest.gtest.overall", "extraOptions": ["buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 47.4762838915471}, {"name": "io_write_bytes", "value": 3419855360}, {"name": "io.read_bytes", "value": 1848259584}, {"name": "io_write_time", "value": 8}, {"name": "io_read_time", "value": 360}]}, {"name": "gtest.gtest.start-pulseaudio", "subtests": [{"name": "time", "value": 0.0}, {"name": "cpu_percent", "value": 0}]}, {"name": "gtest.gtest.install", "subtests": [{"name": "time", "value": 10.656000000000006}, {"name": "cpu_percent", "value": 44.615965346534644}]}, {"name": "gtest.gtest.stage-files", "subtests": [{"name": "time", "value": 1.0}, {"name": "cpu_percent", "value": 43.51944444444444}]}, {"name": "gtest.gtest.run-tests", "subtests": [{"name": "time", "value": 929.3439999999999}, {"name": "cpu_percent", "value": 47.5123116862155}]}, {"name": "gtest.gtest.uninstall", "subtests": [{"name": "time", "value": 0.0}, {"name": "cpu_percent", "value": 0}]}]}
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - Total resource usage - Wall time: 942s; CPU: Can't collect data; Read bytes: 1848259584; Write bytes: 3419855360; Read time: 360; Write time: 8
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - TinderboxPrint: I/O read bytes / time<br/>1,848,259,584 / 360
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - TinderboxPrint: I/O write bytes / time<br/>3,419,855,360 / 8
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - TinderboxPrint: CPU idle<br/>3,974.0 (52.6%)
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - TinderboxPrint: CPU system<br/>1,370.7 (18.1%)
[task 2024-04-19T20:08:45.273Z] 20:08:45     INFO - TinderboxPrint: CPU user<br/>2,179.2 (28.8%)
[task 2024-04-19T20:08:45.277Z] 20:08:45     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-04-19T20:08:45.280Z] 20:08:45     INFO - install - Wall time: 11s; CPU: 45%; Read bytes: 291328; Write bytes: 380932096; Read time: 0; Write time: 1
[task 2024-04-19T20:08:45.282Z] 20:08:45     INFO - stage-files - Wall time: 1s; CPU: 44%; Read bytes: 0; Write bytes: 142630912; Read time: 0; Write time: 0
[task 2024-04-19T20:08:45.335Z] 20:08:45     INFO - run-tests - Wall time: 929s; CPU: 48%; Read bytes: 1847968256; Write bytes: 2896275968; Read time: 360; Write time: 7
[task 2024-04-19T20:08:45.347Z] 20:08:45     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2024-04-19T20:08:48.728Z] 20:08:48  WARNING - returning nonzero exit status 2
[taskcluster 2024-04-19T20:08:48.888Z]    Exit Code: 2
[taskcluster 2024-04-19T20:08:48.888Z]    User Time: 31.25ms
[taskcluster 2024-04-19T20:08:48.888Z]  Kernel Time: 0s
[taskcluster 2024-04-19T20:08:48.888Z]    Wall Time: 18m7.3541395s
[taskcluster 2024-04-19T20:08:48.888Z]       Result: FAILED
[taskcluster 2024-04-19T20:08:48.888Z] === Task Finished ===
[taskcluster 2024-04-19T20:08:48.888Z] Task Duration: 18m7.355189s
[taskcluster 2024-04-19T20:08:49.406Z] Uploading artifact public/logs/localconfig.json from file D:\task_171355331131192\logs\localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2025-04-19T18:53:04.107Z
[taskcluster 2024-04-19T20:08:49.784Z] Uploading artifact public/test_info/profile_resource-usage.json from file D:\task_171355331131192\build\blobber_upload_dir\profile_resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-04-19T18:53:04.107Z
[taskcluster 2024-04-19T20:08:50.220Z] Uploading artifact public/test_info/resource-usage.json from file D:\task_171355331131192\build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2025-04-19T18:53:04.107Z
[taskcluster 2024-04-19T20:08:50.915Z] Uploading artifact public/test_info/system-info.log from file D:\task_171355331131192\build\blobber_upload_dir\system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2025-04-19T18:53:04.107Z
[taskcluster 2024-04-19T20:08:51.185Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2025-04-19T18:53:04.107Z
[taskcluster:error] exit status 2

Looks like a possible bug in the JSAPI written for a gtest, so I'm going to unhide this.

Group: core-security
Severity: -- → S3

Possibly related to bug 1889839

See Also: → 1889839

I think this use-after-poison when accessing a field on a JSObject* means that the mClean object has been garbage collected before we even reached UntrustedModulesFixture::ValidateJSValue. UntrustedModuleFixtures::Serialize appears to be the only test where we initialize the AutoJSContextWithGlobal from within a subfunction rather than at the top of the TestBody, even though the following comment above the AutoJSContextWithGlobal declaration explicitly states that the AutoJSContextWithGlobal should be put at the beginning of the test:

// AutoJSAPI is annotated with MOZ_STACK_CLASS and thus cannot be
// used as a member of TelemetryTestFixture, since gtest instantiates
// that on the heap. To work around the problem, use the following class
// at the beginning of each Telemetry test.

:willyelm, could someone familiar with AutoJSContext and JS::Rooted review UntrustedModuleFixtures::Serialize to confirm if the difference noted above can explain the issue here?

Flags: needinfo?(wmedina)

We are pushing a potential fix with bug 1889839 comment 37 but happy to hear more detailed explanations.

Flags: needinfo?(wmedina) → needinfo?(jdemooij)

(In reply to Yannis Juglaret [:yannis] from comment #12)

:willyelm, could someone familiar with AutoJSContext and JS::Rooted review UntrustedModuleFixtures::Serialize to confirm if the difference noted above can explain the issue here?

That seems plausible because mCleanGlobal isn't rooted, so if a GC happens before the AutoJSContext is instantiated, the global can be collected.

Flags: needinfo?(jdemooij)

Thanks! The fix :yannis mentioned above does seem to have addressed this (there has been one failure of the test since then but it looks unrelated to this poison problem), so I'm going to close this.

Status: NEW → RESOLVED
Closed: 11 months ago
Resolution: --- → FIXED
Depends on: 1889839
See Also: 1889839
Target Milestone: --- → 130 Branch
You need to log in before you can comment on or make changes to this bug.