TM: Crash [@ 0x341f850b] or [@ JS_CallTracer] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp" or "Assertion failure: thing, at ../jsgc.cpp" with gc

VERIFIED FIXED

Status

()

Core
JavaScript Engine
P1
critical
VERIFIED FIXED
9 years ago
4 years ago

People

(Reporter: gkw, Assigned: luke)

Tracking

(Blocks: 1 bug, 4 keywords)

Trunk
x86
Mac OS X
assertion, crash, regression, testcase
Points:
---
Dependency tree / graph
Bug Flags:
blocking1.9.2 +
in-testsuite +

Firefox Tracking Flags

(status1.9.2 beta3-fixed, status1.9.1 unaffected)

Details

(Whiteboard: [ccbr][sg:critical] fixed-in-tracemonkey, crash signature)

Attachments

(1 attachment)

(Reporter)

Description

9 years ago
for (let z = 0; z < 4; ++z) {
    var y = uneval({
        x: {
            a: 1
        }
    })
    gc()
}

crashes js opt shell at a scary memory location and asserts js debug shell at Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114 on TM tip with -j.

Security-sensitive because of scary location and that this concerns gc.


opt stack:

Exception Type:  EXC_BAD_ACCESS (SIGSEGV)
Exception Codes: KERN_INVALID_ADDRESS at 0x00000000341f850b
Crashed Thread:  0

Thread 0 Crashed:
0   ???                           	0x008107d3 0 + 8456147
1   js-opt-tm-darwin              	0x0006e0cf js_GetPropertyHelper + 959
2   js-opt-tm-darwin              	0x0006e1de js_GetProperty + 46
3   js-opt-tm-darwin              	0x00067b13 __ZL16MarkSharpObjectsP9JSContextP8JSObjectPP9JSIdArray + 387
4   js-opt-tm-darwin              	0x00067bf9 __ZL16MarkSharpObjectsP9JSContextP8JSObjectPP9JSIdArray + 617
5   js-opt-tm-darwin              	0x00067df7 js_EnterSharpObject + 311
6   js-opt-tm-darwin              	0x0006936c __ZL12obj_toSourceP9JSContextjPl + 220
7   js-opt-tm-darwin              	0x0005e876 js_Invoke + 1606
8   js-opt-tm-darwin              	0x0005efeb js_InternalInvoke + 139
9   js-opt-tm-darwin              	0x0006e36d js_TryMethod + 285
10  js-opt-tm-darwin              	0x000c84bc js_ValueToSource + 380
11  js-opt-tm-darwin              	0x000c8518 __ZL10str_unevalP9JSContextjPl + 40
12  ???                           	0x007d2ed4 0 + 8203988
13  js-opt-tm-darwin              	0x000f9ae3 __ZL11ExecuteTreeP9JSContextPN7nanojit8FragmentERjPP10VMSideExit + 947
14  js-opt-tm-darwin              	0x00116c78 js_MonitorLoopEdge(JSContext*, unsigned int&, MonitorReason) + 2088
15  js-opt-tm-darwin              	0x0005c2ba js_Interpret + 57610
16  js-opt-tm-darwin              	0x0005df2a js_Execute + 362
17  js-opt-tm-darwin              	0x0000d54c JS_ExecuteScript + 60
18  js-opt-tm-darwin              	0x000040d8 __ZL7ProcessP9JSContextP8JSObjectPci + 1336
19  js-opt-tm-darwin              	0x00008194 main + 2212
20  js-opt-tm-darwin              	0x0000206b _start + 209
21  js-opt-tm-darwin              	0x00001f99 start + 41
(Reporter)

Comment 1

9 years ago
autoBisect shows this is probably related to bug 517973:

The first bad revision is:
changeset:   32856:f3ea03af0e28
user:        Luke Wagner
date:        Wed Sep 23 18:21:41 2009 -0700
summary:     Bug 517973 - remove deep abort, fix blacklisting bug
Blocks: 517973
Whiteboard: [ccbr]

Comment 2

9 years ago
gary, which changeset are you testing?

Updated

9 years ago
Whiteboard: [ccbr] → [ccbr][sg:critical]
(Reporter)

Comment 3

9 years ago
I think I'm on http://hg.mozilla.org/tracemonkey/rev/102a83c28bd0

Possibly related testcase:

new Function
for (var x = 0; x < 22; ++x) {
    if (x % 2 == 1) {
        ({
            getter: function(){}
        });
        gc()
    }
}


This testcase crashes when passed in as a CLI argument to the js shell. The opt stack is similar:

Exception Type:  EXC_BAD_ACCESS (SIGBUS)
Exception Codes: KERN_PROTECTION_FAILURE at 0x0000000000000ff0
Crashed Thread:  0

Thread 0 Crashed:
0   js-opt-tm-darwin              	0x0004a9a5 JS_CallTracer + 117
1   js-opt-tm-darwin              	0x000bfe9d JSScopeProperty::trace(JSTracer*) + 109
2   js-opt-tm-darwin              	0x000ef974 JSTraceMonitor::mark(JSTracer*) + 180
3   js-opt-tm-darwin              	0x0004b8b6 js_TraceRuntime + 182
4   js-opt-tm-darwin              	0x0004bd7e js_GC + 1022
5   js-opt-tm-darwin              	0x0000f3b8 JS_GC + 72
6   js-opt-tm-darwin              	0x000056d2 __ZL2GCP9JSContextjPl + 50
7   ???                           	0x007d2f7a 0 + 8204154
8   js-opt-tm-darwin              	0x000f9ae3 __ZL11ExecuteTreeP9JSContextPN7nanojit8FragmentERjPP10VMSideExit + 947
9   js-opt-tm-darwin              	0x00116c78 js_MonitorLoopEdge(JSContext*, unsigned int&, MonitorReason) + 2088
10  js-opt-tm-darwin              	0x0005c2ba js_Interpret + 57610
11  js-opt-tm-darwin              	0x0005df2a js_Execute + 362
12  js-opt-tm-darwin              	0x0000d54c JS_ExecuteScript + 60
13  js-opt-tm-darwin              	0x000041e5 __ZL7ProcessP9JSContextP8JSObjectPci + 1605
14  js-opt-tm-darwin              	0x00008194 main + 2212
15  js-opt-tm-darwin              	0x0000206b _start + 209
16  js-opt-tm-darwin              	0x00001f99 start + 41


while it asserts at Assertion failure: thing, at ../jsgc.cpp:2657
Summary: TM: Crash [@ 0x341f850b] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114" with uneval, gc → TM: Crash [@ 0x341f850b] or [@ JS_CallTracer] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114" or "Assertion failure: thing, at ../jsgc.cpp:2657" with uneval, gc
(Reporter)

Comment 4

9 years ago
There seems to be many other related crashes (portions of the stacks look similar, but the testcase and crash locations vary wildly), I don't yet have time for many more but I'll test again when this bug is fixed.

How similar? I seem to see lines of "__ZL1.........." on the stacks, e.g. the one above in lines 8 and 13.
(Reporter)

Updated

9 years ago
Summary: TM: Crash [@ 0x341f850b] or [@ JS_CallTracer] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114" or "Assertion failure: thing, at ../jsgc.cpp:2657" with uneval, gc → TM: Crash [@ 0x341f850b] or [@ JS_CallTracer] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114" or "Assertion failure: thing, at ../jsgc.cpp:2657" with gc
(Assignee)

Comment 5

9 years ago
I was hoping this was simply bug 520311, which we found today, but it still crashes even with the fix.

The big thing about this patch is that, before this, the recorder would be aborted during GC.  This patch allows the recorder to continue (only later aborting if shapes were regenerated).

A little gdb-ing confirms that GC happens while recording, recording completes successfully, and the assert happens in the first trace execution.  Perhaps this is a rooting problem with the code to generate native calls (str_uneval)?

valgrind doesn't show any invalid memory reads/writes before the assertion.
(Assignee)

Comment 6

9 years ago
(In reply to comment #5)
> The big thing about this patch is that, before this, the recorder would be
> aborted during GC.  This patch allows the recorder to continue (only later
> aborting if shapes were regenerated).

To clarify, "this patch" = bug 517973, which was correctly fingered above.
Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114

is from an assertion Waldo presciently added just the other day. It means the live scope is pointing to a property tree node that has been swept by the GC. So it does seem that the trace-tree is not rooting enough.

/be
One way to debug is to get address reproducibility (of lastProp, e.g.) and find where it is being GC'ed. On that stack you should find some tree that has a ref to it still. At least, this is the drill for finding prematurely collected things in many other cases.

/be
(Assignee)

Comment 9

9 years ago
I think I found the source of the bug, but I don't know enough about scope properties to fix it; none of my naive attempts worked.

Loop in the crashing test case above contains a new object initialization.  This involves a JSOP_INITPROP which calls record_SetPropHit with the JSScopeProperty* that was just added.  This JSScopeProperty* is baked into the trace in TraeMonitor::setProp as an argument to the js_AddProperty called from trace.  Debugging confirms that this is indeed the JSScopeProperty involved in the failing assertion.

I tried to gcthings.addUnique() the object initialized during recoreding, to keep the JSScopeProperty alive, but that didn't work.  Clearly, I need to read up on GC and the scope chain.
You almost have it: you want treeInfo->sprops.addUnique(sprop), not ...gcthings...

/be

Updated

9 years ago
tracking-fennec: --- → ?
Flags: blocking1.9.2?
Priority: -- → P1
(Assignee)

Comment 11

9 years ago
Created attachment 404467 [details] [diff] [review]
fix

Well, I was too quick to blame it on lack-of-rooting.  Indeed, INS_CONSTSPROP already adds the sprop to treeInfo->ssprops.  The real problem was that JSTraceMonitor:mark() only marks TreeInfo objects for *completed* fragments, which ignores the TreeInfo held by the current recorder.  Simple enough fix.
Assignee: general → lw
Status: NEW → ASSIGNED
Comment on attachment 404467 [details] [diff] [review]
fix

Should've seen this... Thanks!

/be
Attachment #404467 - Flags: review+
(Assignee)

Comment 13

9 years ago
http://hg.mozilla.org/tracemonkey/rev/20a24e94817f
with trace-test
Whiteboard: [ccbr][sg:critical] → [ccbr][sg:critical] fixed-in-tracemonkey

Comment 14

9 years ago
the regressing bug didn't land on 1.9.2 yet, so I'm leaving this as ?
(Reporter)

Updated

9 years ago
Flags: in-testsuite?
(Assignee)

Updated

9 years ago
Flags: in-testsuite? → in-testsuite+
(Reporter)

Updated

9 years ago
Summary: TM: Crash [@ 0x341f850b] or [@ JS_CallTracer] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp:5114" or "Assertion failure: thing, at ../jsgc.cpp:2657" with gc → TM: Crash [@ 0x341f850b] or [@ JS_CallTracer] or "Assertion failure: !JSVAL_IS_NULL((scope)->lastProp->id), at ../jsobj.cpp" or "Assertion failure: thing, at ../jsgc.cpp" with gc

Comment 15

9 years ago
http://hg.mozilla.org/mozilla-central/rev/20a24e94817f
Status: ASSIGNED → RESOLVED
Last Resolved: 9 years ago
Resolution: --- → FIXED

Comment 16

9 years ago
js/src/trace-test/tests/basic/testGCWhileRecording.js
v 1.9.3
Status: RESOLVED → VERIFIED
(Assignee)

Comment 17

9 years ago
This absolutely must go on 1.9.2, as we now may GC on trace.

Updated

9 years ago
Flags: blocking1.9.2? → blocking1.9.2+
status1.9.1: --- → unaffected
Group: core-security
Crash Signature: [@ 0x341f850b] [@ JS_CallTracer]
tracking-fennec: ? → ---
You need to log in before you can comment on or make changes to this bug.