Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Rare panic(s) in goja #867

Closed
na-- opened this issue Dec 14, 2018 · 3 comments · Fixed by #1007 or #1252
Closed

Rare panic(s) in goja #867

na-- opened this issue Dec 14, 2018 · 3 comments · Fixed by #1007 or #1252
Assignees
@na--
Labels
bug high prio
Milestone
v0.27.0

Comments

@na--
Copy link
Member

na-- commented Dec 14, 2018

Very rarely, k6 panics for an unknown reason, deep in the goja runtime. The cause of the panics seems to be that we've somehow concurrently executed 2 different things in the same goja runtime and one of them overwrote the stack of the other... Or maybe it's just a bug in goja?

Stack traces that we've seen (likely the same issue, but maybe not):

panic: runtime error: slice bounds out of range [recovered]
	panic: runtime error: slice bounds out of range

goroutine 74315 [running]:
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.1(0xc01f48dd30)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1407 +0x9b
panic(0xc41680, 0x171b310)
	/usr/lib/go/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).clearStack(0xc005b81a00)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1843 +0x98
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1(0xf0e2e0, 0x1750020, 0xc004075650, 0x1, 0x1, 0x0, 0x0, 0xefe4c0, 0xc0049da0f0)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1420 +0x146
github.com/loadimpact/k6/js.(*VU).runFn(0xc004045560, 0xf07080, 0xc00a065a40, 0xc00249c420, 0xc0044ecc40, 0xc004075650, 0x1, 0x1, 0xc2bea0, 0xc017268780, ...)
	/home/go/src/github.com/loadimpact/k6/js/runner.go:415 +0x35a
github.com/loadimpact/k6/js.(*VU).RunOnce(0xc004045560, 0xf07080, 0xc00a065a40, 0x0, 0x0)
	/home/go/src/github.com/loadimpact/k6/js/runner.go:377 +0x1ef
github.com/loadimpact/k6/core/local.(*vuHandle).run(0xc00228c400, 0xc0000b8a00, 0xc000083260, 0xc000082480)
	/home/go/src/github.com/loadimpact/k6/core/local/local.go:70 +0x152
github.com/loadimpact/k6/core/local.(*Executor).scale.func1(0xc00228c400, 0xc005fd6120, 0xc000083260, 0xc000082480)
	/home/go/src/github.com/loadimpact/k6/core/local/local.go:360 +0x4d
created by github.com/loadimpact/k6/core/local.(*Executor).scale
	/home/go/src/github.com/loadimpact/k6/core/local/local.go:359 +0x32b

and

panic: runtime error: index out of range [recovered]
	panic: Panic at 105: runtime error: index out of range [recovered]
	panic: Panic at 105: runtime error: index out of range [recovered]
	panic: Panic at 6: Panic at 105: runtime error: index out of range [recovered]
	panic: Panic at 6: Panic at 105: runtime error: index out of range

goroutine 138455 [running]:
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.1(0xc02c291d30)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1407 +0x9b
panic(0xc31660, 0xc00a260b90)
	/usr/lib/go/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try.func1(0xc011811450, 0x4, 0xc02c291c38, 0xd, 0x0, 0x0, 0xc02c291c90)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:364 +0x459
panic(0xc31660, 0xc00a260b70)
	/usr/lib/go/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.1(0xc02c291298)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1407 +0x9b
panic(0xc31660, 0xc00a260b70)
	/usr/lib/go/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try.func1(0xc011811450, 0x6, 0xc02c2911a0, 0x13, 0x0, 0x0, 0xc02c2911f8)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:364 +0x459
panic(0xc448c0, 0x1721310)
	/usr/lib/go/src/runtime/panic.go:513 +0x1b9
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm)._nativeCall(0xc011811450, 0xc00a7414a0, 0x1)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1833 +0x627
github.com/loadimpact/k6/vendor/github.com/dop251/goja.call.exec(0x1, 0xc011811450)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1810 +0x4e3
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).run(0xc011811450)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:288 +0x5d
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call(0xc00f343380, 0xf11f20, 0x1756000, 0x0, 0x0, 0x0, 0xc056e1f0e8, 0xa2eabbace7836145)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/func.go:130 +0x2be
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call-fm(0xf11f20, 0x1756000, 0x0, 0x0, 0x0, 0xef833d, 0xfe)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/builtin_function.go:120 +0x48
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.2()
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1412 +0x96
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try(0xc011811450, 0xc056e1f210, 0x0)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:370 +0x10c
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1(0xf11f20, 0x1756000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1411 +0x10d
github.com/loadimpact/k6/js/modules/k6.(*K6).Group(0x1756308, 0xf0ad80, 0xc00ca17da0, 0xc004a480c6, 0x25, 0xc064cb7fa0, 0x0, 0x0, 0x0, 0x0)
	/home/go/src/github.com/loadimpact/k6/js/modules/k6/k6.go:89 +0x17e
reflect.Value.call(0xc83fa0, 0x1756308, 0xa13, 0xd4bd5b, 0x4, 0xc0064a8e10, 0x3, 0x3, 0xc064cb7fa0, 0xef8311, ...)
	/usr/lib/go/src/reflect/value.go:447 +0x449
reflect.Value.Call(0xc83fa0, 0x1756308, 0xa13, 0xc0064a8e10, 0x3, 0x3, 0x0, 0x8, 0xd10380)
	/usr/lib/go/src/reflect/value.go:308 +0xa4
github.com/loadimpact/k6/js/common.Bind.func1(0xf11f20, 0x1756000, 0xc0471a2350, 0x2, 0x11, 0x0, 0x0)
	/home/go/src/github.com/loadimpact/k6/js/common/bridge.go:212 +0xc5c
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm)._nativeCall(0xc011811450, 0xc00a740fd0, 0x2)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1826 +0x284
github.com/loadimpact/k6/vendor/github.com/dop251/goja.call.exec(0x2, 0xc011811450)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1810 +0x4e3
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).run(0xc011811450)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:288 +0x5d
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call(0xc00a5f6a80, 0xf11f20, 0x1756000, 0xc00d785df0, 0x1, 0x1, 0xc020d07b80, 0x203003)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/func.go:130 +0x2be
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call-fm(0xf11f20, 0x1756000, 0xc00d785df0, 0x1, 0x1, 0xef833d, 0x33)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/builtin_function.go:120 +0x48
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.2()
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1412 +0x96
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try(0xc011811450, 0xc020d07ca8, 0x0)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:370 +0x10c
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1(0xf11f20, 0x1756000, 0xc00d785df0, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
	/home/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1411 +0x10d
github.com/loadimpact/k6/js.(*VU).runFn(0xc00ddf4750, 0xf0acc0, 0xc00e8aeac0, 0xc001b61bc0, 0xc00df1fa60, 0xc00d785df0, 0x1, 0x1, 0x1a, 0x1b, ...)
	/home/go/src/github.com/loadimpact/k6/js/runner.go:415 +0x35a
github.com/loadimpact/k6/js.(*VU).RunOnce(0xc00ddf4750, 0xf0acc0, 0xc00e8aeac0, 0x0, 0x0)
	/home/go/src/github.com/loadimpact/k6/js/runner.go:377 +0x1ef
github.com/loadimpact/k6/core/local.(*vuHandle).run(0xc0124806c0, 0xc00009ea00, 0xc000082d80, 0xc0000821e0)
	/home/go/src/github.com/loadimpact/k6/core/local/local.go:70 +0x152
github.com/loadimpact/k6/core/local.(*Executor).scale.func1(0xc0124806c0, 0xc0041c8360, 0xc000082d80, 0xc0000821e0)
	/home/go/src/github.com/loadimpact/k6/core/local/local.go:360 +0x4d
created by github.com/loadimpact/k6/core/local.(*Executor).scale
	/home/go/src/github.com/loadimpact/k6/core/local/local.go:359 +0x32b
@na-- na-- mentioned this issue Dec 14, 2018
Closed
@na-- na-- mentioned this issue May 15, 2019
Merged
39 tasks
@na-- na-- self-assigned this Aug 27, 2019
@na-- na-- added this to the v1.0.0 milestone Aug 27, 2019
@tateexon
Copy link

tateexon commented Sep 5, 2019

I am also seeing this and can reproduce it quite well if I set my stages configuration to ramp up and down very quickly:

    "stages": [
        { "duration": "30s", "target": 90 },
        { "duration": "1m", "target": 90 },
        { "duration": "10s", "target": 320 },
        { "duration": "15s", "target": 320 },
        { "duration": "1m", "target": 90 },
        { "duration": "10s", "target": 320 },
        { "duration": "15s", "target": 320 },
        { "duration": "2m", "target": 90 },
        { "duration": "10s", "target": 320 },
        { "duration": "15s", "target": 320 },
        { "duration": "3m", "target": 90 }
    ],

I am running this on an aws ec2 c4.2xlarge in docker on image https://hub.docker.com/layers/loadimpact/k6/latest/images/sha256-da2f4b158e88eb9e0a118d973df31315cb4496e4fbbd27fa9876bb8414e2b9a7
Here is one of the panics I got:

panic: runtime error: index out of range [recovered]
	panic: Panic at 161: runtime error: index out of range [recovered]
	panic: Panic at 161: runtime error: index out of range

goroutine 793593 [running]:
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.1(0xc03535fd68)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1407 +0x9b
panic(0xd32900, 0xc04aa8bd50)
	/usr/local/go/src/runtime/panic.go:522 +0x1b5
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try.func1(0xc00a958ea0, 0x5, 0xc03535fc70, 0x28, 0x0, 0x0, 0xc03535fcc8)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:364 +0x48e
panic(0xd473e0, 0x19c1260)
	/usr/local/go/src/runtime/panic.go:522 +0x1b5
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm)._nativeCall(0xc00a958ea0, 0xc048e54fd0, 0x2)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1833 +0x631
github.com/loadimpact/k6/vendor/github.com/dop251/goja.call.exec(0x2, 0xc00a958ea0)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:1810 +0x4a4
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).run(0xc00a958ea0)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:288 +0x51
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*funcObject).Call(0xc00d80f440, 0x108f040, 0x19f6e40, 0xc05c4d3de0, 0x1, 0x1, 0x0, 0xc042a85800)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/func.go:130 +0x2c4
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1.2()
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1412 +0x96
github.com/loadimpact/k6/vendor/github.com/dop251/goja.(*vm).try(0xc00a958ea0, 0xc03674cce0, 0x0)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/vm.go:370 +0x10d
github.com/loadimpact/k6/vendor/github.com/dop251/goja.AssertFunction.func1(0x108f040, 0x19f6e40, 0xc05c4d3de0, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
	/go/src/github.com/loadimpact/k6/vendor/github.com/dop251/goja/runtime.go:1411 +0x10d
github.com/loadimpact/k6/js.(*VU).runFn(0xc00ae59d40, 0x10818a0, 0xc02b85db00, 0xc000a0a780, 0xc009b4a7a0, 0xc05c4d3de0, 0x1, 0x1, 0xc0225d3480, 0xc03674cf30, ...)
	/go/src/github.com/loadimpact/k6/js/runner.go:443 +0x394
github.com/loadimpact/k6/js.(*VU).RunOnce(0xc00ae59d40, 0x10818a0, 0xc02b85db00, 0x0, 0x0)
	/go/src/github.com/loadimpact/k6/js/runner.go:403 +0x1f0
github.com/loadimpact/k6/core/local.(*vuHandle).run(0xc009dee540, 0xc0000b81e0, 0xc033222840, 0xc00009f320)
	/go/src/github.com/loadimpact/k6/core/local/local.go:70 +0x145
github.com/loadimpact/k6/core/local.(*Executor).scale.func1(0xc009dee540, 0xc000e8a240, 0xc033222840, 0xc00009f320)
	/go/src/github.com/loadimpact/k6/core/local/local.go:360 +0x4d
created by github.com/loadimpact/k6/core/local.(*Executor).scale
	/go/src/github.com/loadimpact/k6/core/local/local.go:359 +0x30d```

@na--
Copy link
Member Author

na-- commented Sep 9, 2019

@tateexon, thanks for the information and sorry for the inconvenience. We forgot to update this issue, but we actually realized that the cause of these panics is the current scheduling and reuse of VUs. As you've pointed out, it can be triggered by rapid ramping up and down of VUs, and we've also seen the panics manifest when the k6 REST API is used to set the number of VUs directly. In these situation, k6 sometimes doesn't properly wait for the execution in a VU to finish before it tries to reuse it again, thus executing multiple things in the same JS runtime and causing a panic.

Due to the heavy refactoring needed to properly fix the underlying cause, we chose not to directly fix it with the current scheduler, and instead fixed it as part of #1007, which involved rewriting the execution scheduling code anyway. We plan to finish that PR and merge it in master in the next several weeks, so hopefully this bug will be gone then.

@tateexon
Copy link

tateexon commented Sep 9, 2019

@na-- Thank you very much for the update. Glad the issue has been triaged and a way forward is known! For now I have just increased the number of containers/ec2s running k6 to get the same ramp up/down without overloading any single k6 instance. I look forward to the fix in the future!

mstoykov added a commit that referenced this issue Nov 25, 2019
@mstoykov
Add a mutex to js.VU to prevent multiple asynchrnous calls to RunOnce
46f2122 
This should fix #867.
This is not ... a great fix in the sense that while doing it I found out
we are also asynchrnously touch VU.Runtime which should also not happen
and the currently added mutex should probably be locked in most other
functions, but this should fix the immediate problems and the other
should be fixed in a more ... complete redesign :)
@mstoykov mstoykov mentioned this issue Nov 25, 2019
Merged
mstoykov added a commit that referenced this issue Nov 25, 2019
@mstoykov
Add a mutex to js.VU to prevent multiple asynchrnous calls to RunOnce
a2e1c6f 
This should fix #867.
This is not ... a great fix in the sense that while doing it I found out
we are also asynchrnously touch VU.Runtime which should also not happen
and the currently added mutex should probably be locked in most other
functions, but this should fix the immediate problems and the other
should be fixed in a more ... complete redesign :)
na-- pushed a commit that referenced this issue Nov 28, 2019
@mstoykov @na--
Add a mutex to js.VU to prevent multiple asynchrnous calls to RunOnce
e13f4b9 
This should fix #867.
This is not ... a great fix in the sense that while doing it I found out
we are also asynchrnously touch VU.Runtime which should also not happen
and the currently added mutex should probably be locked in most other
functions, but this should fix the immediate problems and the other
should be fixed in a more ... complete redesign :)
@na-- na-- modified the milestones: v1.0.0, v0.27.0 May 21, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@na-- na--

Labels
bug high prio
Projects
None yet
Milestone
v0.27.0
2 participants
@na-- @tateexon