1231170 - Crash [@ js::TraceLoggerThread::eventText] or Assertion failure: lastEntryId < events.size(), at js/src/vm/TraceLogging.h:239

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect, critical)

Description

[Gary Kwong [:gkw] [:nth10sd]]

The following testcase crashes on mozilla-central revision cc9c6cd756cb (build with --enable-debug --enable-more-deterministic, run with --fuzzing-safe --no-threads --no-ion --no-baseline):

Debugger().drainTraceLogger();


Backtrace:

Program received signal SIGSEGV, Segmentation fault.
js::TraceLoggerThread::lostEvents (lastEntryId=<optimized out>, lastIteration=<optimized out>, this=0x7ffff69291e0) at js/src/vm/TraceLogging.h:239
239	            MOZ_ASSERT(lastEntryId < events.size());
#0  js::TraceLoggerThread::lostEvents (lastEntryId=<optimized out>, lastIteration=<optimized out>, this=0x7ffff69291e0) at js/src/vm/TraceLogging.h:239
#1  js::Debugger::drainTraceLogger (cx=cx@entry=0x7ffff6918c00, argc=<optimized out>, vp=<optimized out>) at js/src/vm/Debugger.cpp:4360
#2  0x0000000000aa11f9 in js::CallJSNative (cx=cx@entry=0x7ffff6918c00, native=0x9dabd0 <js::Debugger::drainTraceLogger(JSContext*, unsigned int, JS::Value*)>, args=...) at js/src/jscntxtinlines.h:235
#3  0x0000000000a95ea3 in js::Invoke (cx=0x7ffff6918c00, args=..., construct=js::NO_CONSTRUCT) at js/src/vm/Interpreter.cpp:444
#4  0x0000000000a8f4c5 in Interpret (cx=0x7ffff6918c00, state=...) at js/src/vm/Interpreter.cpp:2763
#5  0x0000000000a95bf2 in js::RunScript (cx=cx@entry=0x7ffff6918c00, state=...) at js/src/vm/Interpreter.cpp:391
#6  0x0000000000a9b069 in js::ExecuteKernel (cx=cx@entry=0x7ffff6918c00, script=..., script@entry=..., scopeChainArg=..., newTargetValue=..., type=<optimized out>, evalInFrame=..., evalInFrame@entry=..., result=0x0) at js/src/vm/Interpreter.cpp:650
#7  0x0000000000a9b55d in js::Execute (cx=cx@entry=0x7ffff6918c00, script=script@entry=..., scopeChainArg=..., rval=rval@entry=0x0) at js/src/vm/Interpreter.cpp:685
#8  0x00000000008b5a8c in ExecuteScript (cx=cx@entry=0x7ffff6918c00, scope=scope@entry=..., script=script@entry=..., rval=rval@entry=0x0) at js/src/jsapi.cpp:4410
#9  0x00000000008b5e22 in JS_ExecuteScript (cx=cx@entry=0x7ffff6918c00, scriptArg=scriptArg@entry=...) at js/src/jsapi.cpp:4443
#10 0x0000000000428a2c in RunFile (compileOnly=false, file=0x7ffff5319800, filename=0x7fffffffe201 "bb150726.js", cx=0x7ffff6918c00) at js/src/shell/js.cpp:515
#11 Process (cx=cx@entry=0x7ffff6918c00, filename=0x7fffffffe201 "bb150726.js", forceTTY=forceTTY@entry=false, kind=kind@entry=FileScript) at js/src/shell/js.cpp:728
#12 0x000000000043450a in ProcessArgs (op=0x7fffffffdcf0, cx=0x7ffff6918c00) at js/src/shell/js.cpp:6201
#13 Shell (envp=<optimized out>, op=0x7fffffffdcf0, cx=0x7ffff6918c00) at js/src/shell/js.cpp:6513
#14 main (argc=<optimized out>, argv=<optimized out>, envp=<optimized out>) at js/src/shell/js.cpp:6874
rax	0x0	0
rbx	0x7ffff6918c00	140737330121728
rcx	0x7ffff6c294e0	140737333335264
rdx	0x0	0
rsi	0x7ffff6ef8960	140737336281440
rdi	0x7ffff6ef7640	140737336276544
rbp	0x7fffffffceb0	140737488342704
rsp	0x7fffffffcd90	140737488342416
r8	0x7ffff6ef8960	140737336281440
r9	0x7ffff7fd3740	140737353955136
r10	0x58	88
r11	0x7ffff6ba0be0	140737332775904
r12	0x7fffffffcde0	140737488342496
r13	0x7fffffffced0	140737488342736
r14	0x7ffff6959800	140737330386944
r15	0x7fffffffd2f0	140737488343792
rip	0x9db0ed <js::Debugger::drainTraceLogger(JSContext*, unsigned int, JS::Value*)+1309>
=> 0x9db0ed <js::Debugger::drainTraceLogger(JSContext*, unsigned int, JS::Value*)+1309>:	movl   $0x0,0x0
   0x9db0f8 <js::Debugger::drainTraceLogger(JSContext*, unsigned int, JS::Value*)+1320>:	ud2

Comment 1

[Gary Kwong [:gkw] [:nth10sd]]

This also crashes js opt shell at js::TraceLoggerThread::eventText.

Comment 2

[Gary Kwong [:gkw] [:nth10sd]]

Attachment: stack

(lldb) bt 5
* thread #1: tid = 0xb21ca, 0x000000010007e399 js-64-dm-darwin-d08afef8b42d`js::TraceLoggerThread::eventText(unsigned int) [inlined] TLTextIdString(id=<unavailable>) at TraceLoggingTypes.h:88, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
  * frame #0: 0x000000010007e399 js-64-dm-darwin-d08afef8b42d`js::TraceLoggerThread::eventText(unsigned int) [inlined] TLTextIdString(id=<unavailable>) at TraceLoggingTypes.h:88
    frame #1: 0x000000010007e399 js-64-dm-darwin-d08afef8b42d`js::TraceLoggerThread::eventText(this=<unavailable>, id=<unavailable>) + 249 at TraceLogging.cpp:295
    frame #2: 0x00000001003f2a6e js-64-dm-darwin-d08afef8b42d`js::Debugger::drainTraceLogger(cx=0x0000000101f79400, argc=<unavailable>, vp=<unavailable>) + 894 at Debugger.cpp:4422
    frame #3: 0x0000000100454914 js-64-dm-darwin-d08afef8b42d`js::Invoke(JSContext*, JS::CallArgs const&, js::MaybeConstruct) [inlined] js::CallJSNative(cx=0x0000000101f79400, native=(js-64-dm-darwin-d08afef8b42d`js::Debugger::drainTraceLogger(JSContext*, unsigned int, JS::Value*) at Debugger.cpp:4396))(JSContext*, unsigned int, JS::Value*), JS::CallArgs const&) + 250 at jscntxtinlines.h:235
    frame #4: 0x000000010045481a js-64-dm-darwin-d08afef8b42d`js::Invoke(cx=0x0000000101f79400, args=0x00007fff5fbfeb30, construct=<unavailable>) + 666 at Interpreter.cpp:444
(lldb) dis -p
js-64-dm-darwin-d08afef8b42d`js::TraceLoggerThread::eventText:
->  0x10007e399 <+249>: movq   (%rax), %rax
    0x10007e39c <+252>: addq   $0x8, %rsp
    0x10007e3a0 <+256>: popq   %rbx
    0x10007e3a1 <+257>: popq   %rbp
(lldb) register read $rax
     rax = 0x0000000000000008
(lldb)

Comment 3

[Fuzzing Team]

JSBugMon: Bisection requested, result:
autoBisect shows this is probably related to the following changeset:

The first bad revision is:
changeset:   https://hg.mozilla.org/mozilla-central/rev/a7a8e0430f3a
user:        Wei Wu
date:        Wed Nov 25 23:12:00 2015 +0100
summary:     Bug 1228238 - "TraceLogger: don't enable tracelogger unless TLOPTIONS is set". r=hv1989

This iteration took 260.425 seconds to run.

Comment 4

[Gary Kwong [:gkw] [:nth10sd]]

Hannes, is bug 1228238 a likely regressor?

Comment 5

[Hannes Verschore [:h4writer]]

(In reply to Gary Kwong [:gkw] [:nth10sd] from comment #4)
> Hannes, is bug 1228238 a likely regressor?

Looks correct. Gonna look into it.

Comment 6

[Hannes Verschore [:h4writer]]

Oh right. This will be fixed by bug 1224123, which I thought wasn't a priority. But right. It assumes we have at least one logged item. Which isn't the case anymore.

Comment 7

[Hannes Verschore [:h4writer]]

Moving patch of bug 1224123 comment 11 to here.
That bug has already a patch and landed in FF45. This new patch will land in FF46 and need to get backported. For easiness using a different might make it easier to track it.

Comment 8

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6bc6cbcf117e

Comment 9

[Hannes Verschore [:h4writer]]

(In reply to Pulsebot from comment #8)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/6bc6cbcf117e

Needinfo myself to backport soonish

Comment 10

[Carsten Book [:Tomcat]]

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

Comment 11

[Hannes Verschore [:h4writer]]

Attachment: Patch

Importing patch to request uplift

Comment 12

[Hannes Verschore [:h4writer]]

Comment on attachment 8702918 [details] [diff] [review]
Patch

Approval Request Comment

[Feature/regressing bug #]: bug 1228238

[User impact if declined]: Possibility to crash the browser

[Describe test coverage new/current, TreeHerder]: In tree for 12 days

[Risks and why]: Feature is not used by public. So that decreases risk.

[String/UUID change made/needed]: /

Comment 13

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8702918 [details] [diff] [review]
Patch

Fix a crash, has test, taking it!

Comment 14

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/e9e5800af57d