Closed Bug 1615202 Opened 5 years ago Closed 5 years ago

Intermittent GECKO(1334) | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/js/src/gc/Cell.h:572:21 in lengthField

Categories

(Core :: JavaScript: GC, defect, P5)

Product:
Core
Component:
JavaScript: GC
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla75
Tracking Flags:
Tracking Status
firefox75 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1615202 - Suppression intermittent XDR race variation in TSan. r?froydnj
47 bytes, text/x-phabricator-request
Details | Review

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

[task 2020-02-13T07:23:36.956Z] 07:23:36 INFO - runtests.py | Running with socketprocess_e10s: False
[task 2020-02-13T07:23:36.956Z] 07:23:36 INFO - runtests.py | Running tests: start.
[task 2020-02-13T07:23:36.956Z] 07:23:36 INFO -
[task 2020-02-13T07:23:36.964Z] 07:23:36 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmpWGjyWO.mozrunner
[task 2020-02-13T07:23:36.967Z] 07:23:36 INFO - runtests.py | Application pid: 1334
[task 2020-02-13T07:23:36.968Z] 07:23:36 INFO - TEST-INFO | started process GECKO(1334)
[task 2020-02-13T07:23:40.591Z] 07:23:40 INFO - GECKO(1334) | 1581578620584 Marionette TRACE Received observer notification profile-after-change
[task 2020-02-13T07:23:40.773Z] 07:23:40 INFO - GECKO(1334) | 1581578620769 Marionette TRACE Received observer notification command-line-startup
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | ==================
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | WARNING: ThreadSanitizer: data race (pid=1334)
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | Read of size 8 at 0x0066bd1b9540 by thread T10:
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | #0 lengthField /builds/worker/workspace/build/src/js/src/gc/Cell.h:572:21 (libxul.so+0x679aafb)
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | #1 length /builds/worker/workspace/build/src/js/src/vm/StringType.h:387:34 (libxul.so+0x679aafb)
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | #2 IdIsIndex /builds/worker/workspace/build/src/js/src/builtin/Array.h:37:13 (libxul.so+0x679aafb)
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | #3 GetBaseShapeForNewShape /builds/worker/workspace/build/src/js/src/vm/Shape.cpp:563:18 (libxul.so+0x679aafb)
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | #4 js::NativeObject::addDataPropertyInternal(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::PropertyKey>, unsigned int, unsigned int, js::ShapeTable*, js::ShapeTable::Entry*, js::AutoKeepShapeCaches const&) /builds/worker/workspace/build/src/js/src/vm/Shape.cpp:725:41 (libxul.so+0x679aafb)
[task 2020-02-13T07:23:41.860Z] 07:23:41 INFO - GECKO(1334) | #5 addDataProperty /builds/worker/workspace/build/src/js/src/vm/Shape-inl.h:438:10 (libxul.so+0x6719c7d)
[task 2020-02-13T07:23:41.864Z] 07:23:41 INFO - GECKO(1334) | #6 AddOrChangeProperty<IsAddOrChange::Add> /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:1470:15 (libxul.so+0x6719c7d)
[task 2020-02-13T07:23:41.864Z] 07:23:41 INFO - GECKO(1334) | #7 js::NativeDefineProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::PropertyKey>, JS::Handle<JS::PropertyDescriptor>, JS::ObjectOpResult&) /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:1778:10 (libxul.so+0x6719c7d)
[task 2020-02-13T07:23:41.864Z] 07:23:41 INFO - GECKO(1334) | #8 NativeDefineDataProperty /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:1936:10 (libxul.so+0x673512d)
[task 2020-02-13T07:23:41.865Z] 07:23:41 INFO - GECKO(1334) | #9 NativeDefineDataProperty /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:1993:8 (libxul.so+0x673512d)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #10 AddPlainObjectProperties(JSContext*, JS::Handle<js::PlainObject*>, js::IdValuePair*, unsigned long) /builds/worker/workspace/build/src/js/src/vm/ObjectGroup.cpp:1104:10 (libxul.so+0x673512d)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #11 js::ObjectGroup::newPlainObject(JSContext*, js::IdValuePair*, unsigned long, js::NewObjectKind) /builds/worker/workspace/build/src/js/src/vm/ObjectGroup.cpp:1169:18 (libxul.so+0x6735c33)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #12 mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::XDRObjectLiteral<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>, JS::MutableHandle<JSObject>) /builds/worker/workspace/build/src/js/src/vm/JSObject.cpp:1690:13 (libxul.so+0x66cb888)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #13 mozilla::Result<mozilla::Ok, JS::TranscodeResult> XDRInnerObject<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>, js::PrivateScriptData, JS::Handle<js::ScriptSourceObject*>, JS::MutableHandle<JSObject*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:494:7 (libxul.so+0x6702941)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #14 XDRScriptGCThing<js::XDR_DECODE> /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:617:7 (libxul.so+0x66de2c4)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #15 mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::PrivateScriptData::XDR<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>, JS::Handle<JSScript>, JS::Handle<js::ScriptSourceObject*>, JS::Handle<js::Scope*>, JS::Handle<JSObject*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:764:5 (libxul.so+0x66de2c4)
[task 2020-02-13T07:23:41.868Z] 07:23:41 INFO - GECKO(1334) | #16 mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::XDRScript<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>, JS::Handle<js::Scope>, JS::Handle<js::ScriptSourceObject*>, JS::Handle<JSObject*>, JS::MutableHandle<JSScript*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:1270:3 (libxul.so+0x66aa2c5)
[task 2020-02-13T07:23:41.876Z] 07:23:41 INFO - GECKO(1334) | #17 js::XDRState<(js::XDRMode)1>::codeScript(JS::MutableHandle<JSScript*>) /builds/worker/workspace/build/src/js/src/vm/Xdr.cpp:341:3 (libxul.so+0x689b5d6)
[task 2020-02-13T07:23:41.876Z] 07:23:41 INFO - GECKO(1334) | #18 js::MultiScriptsDecodeTask::parse(JSContext*) /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:736:30 (libxul.so+0x65ea9fe)
[task 2020-02-13T07:23:41.876Z] 07:23:41 INFO - GECKO(1334) | #19 js::ParseTask::runTask() /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:561:3 (libxul.so+0x65e9a4e)
[task 2020-02-13T07:23:41.877Z] 07:23:41 INFO - GECKO(1334) | #20 js::HelperThread::handleParseWorkload(js::AutoLockHelperThreadState&) /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:2377:11 (libxul.so+0x65f3626)
[task 2020-02-13T07:23:41.877Z] 07:23:41 INFO - GECKO(1334) | #21 js::HelperThread::threadLoop() /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:2667:5 (libxul.so+0x65f2427)
[task 2020-02-13T07:23:41.877Z] 07:23:41 INFO - GECKO(1334) | #22 js::HelperThread::ThreadMain(void*) /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:2189:11 (libxul.so+0x65ed51d)
[task 2020-02-13T07:23:41.877Z] 07:23:41 INFO - GECKO(1334) | #23 callMain<0> /builds/worker/workspace/build/src/js/src/threading/Thread.h:218:5 (libxul.so+0x65fb2c0)
[task 2020-02-13T07:23:41.877Z] 07:23:41 INFO - GECKO(1334) | #24 js::detail::ThreadTrampoline<void (&)(void*), js::HelperThread*>::Start(void*) /builds/worker/workspace/build/src/js/src/threading/Thread.h:207:11 (libxul.so+0x65fb2c0)
[task 2020-02-13T07:23:41.878Z] 07:23:41 INFO - GECKO(1334) | Previous write of size 8 at 0x0066bd1b9540 by main thread:
[task 2020-02-13T07:23:41.878Z] 07:23:41 INFO - GECKO(1334) | [failed to restore the stack]
[task 2020-02-13T07:23:41.878Z] 07:23:41 INFO - GECKO(1334) | Thread T10 'JS Helper' (tid=1353, running) created by main thread at:
[task 2020-02-13T07:23:41.878Z] 07:23:41 INFO - GECKO(1334) | #0 pthread_create /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/tsan/rtl/tsan_interceptors.cc:967:3 (firefox+0x571ab)
[task 2020-02-13T07:23:41.878Z] 07:23:41 INFO - GECKO(1334) | #1 js::Thread::create(void* ()(void), void*) /builds/worker/workspace/build/src/js/src/threading/posix/PosixThread.cpp:52:7 (libxul.so+0x65572d1)
[task 2020-02-13T07:23:41.879Z] 07:23:41 INFO - GECKO(1334) | #2 bool js::Thread::init<void (&)(void*), js::HelperThread*>(void (&)(void*), js::HelperThread*&&) /builds/worker/workspace/build/src/js/src/threading/Thread.h:91:12 (libxul.so+0x65ed434)
[task 2020-02-13T07:23:41.879Z] 07:23:41 INFO - GECKO(1334) | #3 js::GlobalHelperThreadState::ensureInitialized() /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:1166:27 (libxul.so+0x65e81f1)
[task 2020-02-13T07:23:41.879Z] 07:23:41 INFO - GECKO(1334) | #4 js::EnsureHelperThreadsInitialized() /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:94:30 (libxul.so+0x65e7ed2)
[task 2020-02-13T07:23:41.879Z] 07:23:41 INFO - GECKO(1334) | #5 JSRuntime::init(JSContext*, unsigned int) /builds/worker/workspace/build/src/js/src/vm/Runtime.cpp:200:32 (libxul.so+0x6762113)
[task 2020-02-13T07:23:41.879Z] 07:23:41 INFO - GECKO(1334) | #6 js::NewContext(unsigned int, JSRuntime*) /builds/worker/workspace/build/src/js/src/vm/JSContext.cpp:170:17 (libxul.so+0x669132d)
[task 2020-02-13T07:23:41.879Z] 07:23:41 INFO - GECKO(1334) | #7 JS_NewContext(unsigned int, JSRuntime*) /builds/worker/workspace/build/src/js/src/jsapi.cpp:395:10 (libxul.so+0x64e32f4)
[task 2020-02-13T07:23:41.880Z] 07:23:41 INFO - GECKO(1334) | #8 mozilla::CycleCollectedJSContext::Initialize(JSRuntime*, unsigned int) /builds/worker/workspace/build/src/xpcom/base/CycleCollectedJSContext.cpp:128:16 (libxul.so+0x978acb)
[task 2020-02-13T07:23:41.880Z] 07:23:41 INFO - GECKO(1334) | #9 XPCJSContext::Initialize() /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp:1111:32 (libxul.so+0x184ffba)
[task 2020-02-13T07:23:41.881Z] 07:23:41 INFO - GECKO(1334) | #10 XPCJSContext::NewXPCJSContext() /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp:1307:23 (libxul.so+0x1850af7)
[task 2020-02-13T07:23:41.881Z] 07:23:41 INFO - GECKO(1334) | #11 nsXPConnect::InitJSContext() /builds/worker/workspace/build/src/js/xpconnect/src/nsXPConnect.cpp:74:25 (libxul.so+0x188b673)
[task 2020-02-13T07:23:41.882Z] 07:23:41 INFO - GECKO(1334) | #12 xpc::InitializeJSContext() /builds/worker/workspace/build/src/js/xpconnect/src/nsXPConnect.cpp:92:35 (libxul.so+0x188b72f)
[task 2020-02-13T07:23:41.882Z] 07:23:41 INFO - GECKO(1334) | #13 XREMain::XRE_mainRun() /builds/worker/workspace/build/src/toolkit/xre/nsAppRunner.cpp:4345:5 (libxul.so+0x630a53f)
[task 2020-02-13T07:23:41.884Z] 07:23:41 INFO - GECKO(1334) | #14 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/workspace/build/src/toolkit/xre/nsAppRunner.cpp:4701:8 (libxul.so+0x630b74d)
[task 2020-02-13T07:23:41.885Z] 07:23:41 INFO - GECKO(1334) | #15 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/workspace/build/src/toolkit/xre/nsAppRunner.cpp:4752:21 (libxul.so+0x630bb14)
[task 2020-02-13T07:23:41.886Z] 07:23:41 INFO - GECKO(1334) | #16 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/workspace/build/src/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0x6314822)
[task 2020-02-13T07:23:41.887Z] 07:23:41 INFO - GECKO(1334) | #17 do_main /builds/worker/workspace/build/src/browser/app/nsBrowserApp.cpp:217:22 (firefox+0xc8a57)
[task 2020-02-13T07:23:41.887Z] 07:23:41 INFO - GECKO(1334) | #18 main /builds/worker/workspace/build/src/browser/app/nsBrowserApp.cpp:331:16 (firefox+0xc8a57)
[task 2020-02-13T07:23:41.888Z] 07:23:41 INFO - GECKO(1334) | SUMMARY: ThreadSanitizer: data race /builds/worker/workspace/build/src/js/src/gc/Cell.h:572:21 in lengthField
[task 2020-02-13T07:23:41.889Z] 07:23:41 INFO - GECKO(1334) | ==================
[task 2020-02-13T07:26:37.027Z] 07:26:37 INFO - runtests.py | Waiting for browser...
[task 2020-02-13T07:26:37.027Z] 07:26:37 INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2020-02-13T07:26:37.028Z] 07:26:37 INFO - Buffered messages finished
[task 2020-02-13T07:26:37.035Z] 07:26:37 ERROR - TEST-UNEXPECTED-FAIL | automation.py | application terminated with exit code -6
[task 2020-02-13T07:26:37.035Z] 07:26:37 INFO - runtests.py | Application ran for: 0:03:00.063280
[task 2020-02-13T07:26:37.036Z] 07:26:37 INFO - zombiecheck | Reading PID log: /tmp/tmp45suDtpidlog
[task 2020-02-13T07:26:37.036Z] 07:26:37 INFO - ==> process 1334 launched child process 1351
[task 2020-02-13T07:26:37.037Z] 07:26:37 INFO - zombiecheck | Checking for orphan process with PID: 1351
[task 2020-02-13T07:26:37.038Z] 07:26:37 INFO - Traceback (most recent call last):
[task 2020-02-13T07:26:37.038Z] 07:26:37 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2852, in doTests
[task 2020-02-13T07:26:37.039Z] 07:26:37 INFO - e10s=options.e10s
[task 2020-02-13T07:26:37.039Z] 07:26:37 INFO - File "/builds/worker/workspace/build/tests/mochitest/runtests.py", line 2371, in runApp
[task 2020-02-13T07:26:37.040Z] 07:26:37 INFO - raise exc(value).with_traceback(tb)
[task 2020-02-13T07:26:37.041Z] 07:26:37 INFO - AttributeError: 'timeout' object has no attribute 'with_traceback'
[task 2020-02-13T07:26:37.041Z] 07:26:37 ERROR - Automation Error: Received unexpected exception while running application
[task 2020-02-13T07:26:37.042Z] 07:26:37 ERROR -
[task 2020-02-13T07:26:37.042Z] 07:26:37 INFO - Stopping web server
[task 2020-02-13T07:26:37.049Z] 07:26:37 INFO - Stopping web socket server
[task 2020-02-13T07:26:37.070Z] 07:26:37 INFO - Stopping ssltunnel
[task 2020-02-13T07:26:37.090Z] 07:26:37 WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2020-02-13T07:26:37.091Z] 07:26:37 INFO - runtests.py | Running tests: end.
[task 2020-02-13T07:26:37.093Z] 07:26:37 INFO - Buffered messages finished
[task 2020-02-13T07:26:37.094Z] 07:26:37 INFO - 0 INFO TEST-START | Shutdown
[task 2020-02-13T07:26:37.095Z] 07:26:37 INFO - 1 INFO Passed: 889
[task 2020-02-13T07:26:37.096Z] 07:26:37 INFO - 2 INFO Failed: 0
[task 2020-02-13T07:26:37.097Z] 07:26:37 INFO - 3 INFO Todo: 42
[task 2020-02-13T07:26:37.098Z] 07:26:37 INFO - 4 INFO Mode: e10s
[task 2020-02-13T07:26:37.099Z] 07:26:37 INFO - 5 INFO SimpleTest FINISHED
[task 2020-02-13T07:26:37.100Z] 07:26:37 INFO - Buffered messages finished
[task 2020-02-13T07:26:37.101Z] 07:26:37 INFO - SUITE-END | took 433s
[task 2020-02-13T07:26:37.189Z] 07:26:37 ERROR - Return code: 1
[task 2020-02-13T07:26:37.190Z] 07:26:37 INFO - TinderboxPrint: mochitest-mochitest-plain<br/>43/0/0
[task 2020-02-13T07:26:37.191Z] 07:26:37 ERROR - # TBPL FAILURE #
[task 2020-02-13T07:26:37.192Z] 07:26:37 WARNING - setting return code to 2
[task 2020-02-13T07:26:37.193Z] 07:26:37 ERROR - The mochitest suite: mochitest-plain ran with return status: FAILURE

This is bug 1601286 and the suppression does not seem to be sufficient. I'll add another frame to the already existing ones in this bug.

Assignee: nobody → choller
Status: NEW → ASSIGNED
Pushed by choller@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/6d51cbf7e4ec Suppression intermittent XDR race variation in TSan. r=froydnj

https://hg.mozilla.org/mozilla-central/rev/6d51cbf7e4ec

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox75: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla75

I think this is not fixed.
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=288859643&repo=autoland&lineNumber=5548
happened ~6 hours ago.
Should i make a new bug?

Flags: needinfo?(choller)

Jason, can you take a look at comment 5? That is the same bug, isn't it? One of the stacks is missing, because TSan failed to symbolize it (happens sometimes, and that can cause suppressions to fail, too).

This bug is getting really annoying to suppress because it seems to have many forms and I already suspect we are suppressing more than just that one bug with the amount of suppressions we have now.

Flags: needinfo?(choller) → needinfo?(jorendorff)

(In reply to Christian Holler (:decoder) from comment #6)

Jason, can you take a look at comment 5? That is the same bug, isn't it? One of the stacks is missing, because TSan failed to symbolize it (happens sometimes, and that can cause suppressions to fail, too).

Comment 5 log is no longer available.
I will remove jason need-info for now, and we can probably open a new bug if this shows up.

Flags: needinfo?(jorendorff)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: