Skip to content
This repository has been archived by the owner on Jan 30, 2025. It is now read-only.

Deadlock in TestPageWaitForFunction tests #635

Closed
ankur22 opened this issue Nov 7, 2022 · 1 comment · Fixed by #636
Closed

Deadlock in TestPageWaitForFunction tests #635

ankur22 opened this issue Nov 7, 2022 · 1 comment · Fixed by #636
Labels
bug Something isn't working
Milestone
v0.6.0

Comments

@ankur22
Copy link
Collaborator

ankur22 commented Nov 7, 2022 •
edited by inancgumus
Loading

logs_4015.zip

Brief summary

A CI pipeline failed with the following log, and it looks to be a deadlock around the WaitForFunction, and specifically waitForExecutionContext.

xk6-browser version

CI

OS

Ubuntu 20.04.5 LTS

Chrome version

Unknown

Docker version and image (if applicable)

NA

Steps to reproduce the problem

A CI pipeline failed with the following log (only the goroutine logs that are of interest have been added), and it looks to be a deadlock around the WaitForFunction, and specifically waitForExecutionContext. We had a similar issue with deadlock in the cloud, which was due to out of order CDP events which was fixed in #555. Could be something holding on executionContextMu in frame.

NOTE: The log is just the starting place to try and recreate the issue, but the root cause might be elsewhere in the system.

CI action log: https://github.com/grafana/xk6-browser/actions/runs/3409862907/jobs/5672145446

goroutine 17250 [sync.RWMutex.Lock, 4 minutes]:
sync.runtime_SemacquireRWMutex(0xc000581400?, 0x77?, 0x116f62e?)
	/home/runner/sdk/gotip/src/runtime/sema.go:87 +0x26
sync.(*RWMutex).Lock(0xc000581400)
	/home/runner/sdk/gotip/src/sync/rwmutex.go:152 +0x8b
github.com/grafana/xk6-browser/common.(*Frame).setContext(0xc0005812c0, {0x1afba9d, 0x7}, {0x1d37578?, 0xc001398d10})
	/home/runner/work/xk6-browser/xk6-browser/common/frame.go:518 +0x87
github.com/grafana/xk6-browser/common.(*FrameSession).onExecutionContextCreated(0xc001341080, 0xc00058bac8)
	/home/runner/work/xk6-browser/xk6-browser/common/frame_session.go:565 +0xa4e
github.com/grafana/xk6-browser/common.(*FrameSession).initEvents.func1()
	/home/runner/work/xk6-browser/xk6-browser/common/frame_session.go:253 +0x645
created by github.com/grafana/xk6-browser/common.(*FrameSession).initEvents
	/home/runner/work/xk6-browser/xk6-browser/common/frame_session.go:208 +0x33f

goroutine 13088 [sync.RWMutex.RLock, 4 minutes]:
sync.runtime_SemacquireRWMutexR(0x4a8c39?, 0x77?, 0x1144a56?)
	/home/runner/sdk/gotip/src/runtime/sema.go:82 +0x26
sync.(*RWMutex).RLock(0xc000581400)
	/home/runner/sdk/gotip/src/sync/rwmutex.go:71 +0x65
github.com/grafana/xk6-browser/common.(*Frame).hasContext(0xc0005812c0, {0x1af7834, 0x4})
	/home/runner/work/xk6-browser/xk6-browser/common/frame.go:406 +0x6e
github.com/grafana/xk6-browser/common.(*Frame).waitForExecutionContext(0xc0005812c0, {0x1af7834, 0x4})
	/home/runner/work/xk6-browser/xk6-browser/common/frame.go:556 +0x2d6
github.com/grafana/xk6-browser/common.(*Frame).waitForFunction(0xc0005812c0, {0x1d32798?, 0xc0012ee4e0}, {0x1af7834, 0x4}, {0xc0000d5fb3, 0xd}, {0x1961d80?, 0x2674980}, 0x1dcd6500, ...)
	/home/runner/work/xk6-browser/xk6-browser/common/frame.go:574 +0x24e
github.com/grafana/xk6-browser/common.(*Frame).WaitForFunction(0xc0005812c0, {0x1d3c4c8, 0x28b9d8c}, {0x1d3bed8, 0xc0020a4c60}, {0xc000f70170, 0x1, 0x1?})
	/home/runner/work/xk6-browser/xk6-browser/common/frame.go:1811 +0x729
github.com/grafana/xk6-browser/common.(*Page).WaitForFunction(0xc001440580, {0x1d3c4c8, 0x28b9d8c}, {0x1d3bed8, 0xc0020a4c60}, {0xc000f70170, 0x1, 0x1})
	/home/runner/work/xk6-browser/xk6-browser/common/page.go:897 +0x1d6
reflect.Value.call({0x1aeddc0?, 0xc001440580?, 0x0?}, {0x1af7248, 0x4}, {0xc000c44dc0, 0x3, 0xc000070c00?})
	/home/runner/sdk/gotip/src/reflect/value.go:586 +0x137d
reflect.Value.Call({0x1aeddc0?, 0xc001440580?, 0x28b9d80?}, {0xc000c44dc0, 0x3, 0x3})
	/home/runner/sdk/gotip/src/reflect/value.go:370 +0xc8
github.com/dop251/goja.(*Runtime).wrapReflectFunc.func1({{0x1d3bed8, 0xc00199b830}, {0xc00138fa20, 0x3, 0x6}})
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/runtime.go:1980 +0x465
github.com/dop251/goja.(*vm)._nativeCall(0xc000e99e00, 0xc000c4ed80, 0x3)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/vm.go:3233 +0x36b
github.com/dop251/goja.call.exec(0x3, 0xc000e99e00)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/vm.go:3205 +0x11e8
github.com/dop251/goja.(*vm).run(0xc000e99e00)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/vm.go:495 +0x18a
github.com/dop251/goja.(*vm).try(0xc000e99e00, 0xc001b1fb18)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/vm.go:634 +0x391
github.com/dop251/goja.(*vm).runTry(...)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/vm.go:639
github.com/dop251/goja.(*Runtime).RunProgram(0xc002094700, 0xc00063c120)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/runtime.go:1[435](https://github.com/grafana/xk6-browser/actions/runs/3409862907/jobs/5672145446#step:5:436) +0x2d8
github.com/dop251/goja.(*Runtime).RunScript(0x1b49ee1?, {0x0, 0x0}, {0xc000acc3c0, 0xb4})
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/runtime.go:1407 +0xb9
github.com/dop251/goja.(*Runtime).RunString(...)
	/home/runner/go/pkg/mod/github.com/dop251/[email protected]/runtime.go:1396
github.com/grafana/xk6-browser/tests.TestPageWaitForFunction.func4.2()
	/home/runner/work/xk6-browser/xk6-browser/tests/page_test.go:571 +0xca
go.k6.io/k6/js/eventloop.(*EventLoop).Start(0xc0019baaf0, 0xc000b8d300)
	/home/runner/go/pkg/mod/go.k6.io/[email protected]/js/eventloop/eventloop.go:171 +0x27b
github.com/grafana/xk6-browser/tests.TestPageWaitForFunction.func4(0x0?)
	/home/runner/work/xk6-browser/xk6-browser/tests/page_test.go:570 +0x370
testing.tRunner(0xc000b67ba0, 0xc0007831b8)
	/home/runner/sdk/gotip/src/testing/testing.go:1569 +0x217
created by testing.(*T).Run
	/home/runner/sdk/gotip/src/testing/testing.go:1618 +0x7f2

Expected behaviour

The tests should pass.

Actual behaviour

Deadlock.

Related: #637
@ankur22 ankur22 added the bug Something isn't working label Nov 7, 2022
ankur22 added a commit that referenced this issue Nov 7, 2022
@ankur22
Fix deadlock with executionContextMu
f8a7672 
executionContextMu isn't needed to be locked and unlocked in this
(WaitForFunction) method as it doesn't r/w to executionContext or
documentHandle. This function later calls an unexported method with the
same name, which does require access to executionContext.

A deadlock was occurring later in waitForExecutionContext since
this method was holding on to the lock.

Closes: #635
@ankur22 ankur22 mentioned this issue Nov 7, 2022
Merged
@ankur22 ankur22 added this to the v0.6.0 milestone Nov 7, 2022
@ankur22
Copy link
Collaborator Author

ankur22 commented Nov 7, 2022

Recreated the issue by stress testing TestPageWaitForFunction.

@ankur22 ankur22 closed this as completed in 7a45ec7 Nov 7, 2022
ankur22 added a commit that referenced this issue Nov 11, 2022
@ankur22
Fix deadlock with executionContextMu (#636)
6aebf19 
executionContextMu isn't needed to be locked and unlocked in this
(WaitForFunction) method as it doesn't r/w to executionContext or
documentHandle. This function later calls an unexported method with the
same name, which does require access to executionContext.

A deadlock was occurring later in waitForExecutionContext since
this method was holding on to the lock.

Closes: #635
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
v0.6.0
Development

Successfully merging a pull request may close this issue.

Fix deadlock with executionContextMu grafana/xk6-browser
1 participant
@ankur22