WebSockets stale preventing k6's shutdown

[olegbespalov]

What?

Seems like sometimes websockets could stale a bit, which prevents shutting down of the k6 and need to send a kill signal to it.

The output is:

Logger format: RAW
SIGQUIT: quit
PC=0x47ed01 m=0 sigcode=0

goroutine 86 gp=0xc000585880 m=0 mp=0x2fead80 [syscall]:
runtime.notetsleepg(0x300e120, 0xffffffffffffffff)
	runtime/lock_futex.go:246 +0x29 fp=0xc0000927a0 sp=0xc000092778 pc=0x40f689
os/signal.signal_recv()
	runtime/sigqueue.go:152 +0x29 fp=0xc0000927c0 sp=0xc0000927a0 pc=0x4769e9
os/signal.loop()
	os/signal/signal_unix.go:23 +0x13 fp=0xc0000927e0 sp=0xc0000927c0 pc=0x5eb8f3
runtime.goexit({})
	runtime/asm_amd64.s:1700 +0x1 fp=0xc0000927e8 sp=0xc0000927e0 pc=0x47cf01
created by os/signal.Notify.func1.1 in goroutine 1
	os/signal/signal.go:151 +0x1f

goroutine 1 gp=0xc0000061c0 m=nil [chan receive, 5 minutes]:
runtime.gopark(0x500008?, 0x7fedb2d46728?, 0x40?, 0x0?, 0x0?)
	runtime/proc.go:424 +0xce fp=0xc000908988 sp=0xc000908968 pc=0x474aae
runtime.chanrecv(0xc00b6da700, 0xc000908b78, 0x1)
	runtime/chan.go:639 +0x41c fp=0xc000908a00 sp=0xc000908988 pc=0x409c3c
runtime.chanrecv1(0x1fbb650?, 0xc03cd775c0?)
	runtime/chan.go:489 +0x12 fp=0xc000908a28 sp=0xc000908a00 pc=0x4097f2
go.k6.io/k6/internal/execution.(*Scheduler).Run(0xc000575f00, {0x1fbb688, 0xc0002e1860}, {0x1fbb650, 0xc000329b00}, 0xc000d8c1c0)
	go.k6.io/k6/internal/execution/scheduler.go:508 +0xcb4 fp=0xc000908fc0 sp=0xc000908a28 pc=0xac0e34
go.k6.io/k6/internal/cmd.(*cmdRun).run(0xc0002b4b40, 0xc00041e2c8, {0xc00002d508, 0x1, 0x2d})
	go.k6.io/k6/internal/cmd/run.go:397 +0x1557 fp=0xc000909c50 sp=0xc000908fc0 pc=0x17edd17
go.k6.io/k6/internal/cmd.(*cmdRun).run-fm(0xc0003cbd00?, {0xc00002d508?, 0x4?, 0x1c39373?})
	<autogenerated>:1 +0x34 fp=0xc000909c88 sp=0xc000909c50 pc=0x17f9f74
github.com/spf13/cobra.(*Command).execute(0xc00041e2c8, {0xc00002d208, 0x2d, 0x2f})
	github.com/spf13/cobra@v1.4.0/command.go:856 +0x68a fp=0xc000909d78 sp=0xc000909c88 pc=0x5e072a
github.com/spf13/cobra.(*Command).ExecuteC(0xc000289088)
	github.com/spf13/cobra@v1.4.0/command.go:974 +0x38d fp=0xc000909e30 sp=0xc000909d78 pc=0x5e0d6d
github.com/spf13/cobra.(*Command).Execute(...)
	github.com/spf13/cobra@v1.4.0/command.go
... omitting 139784 bytes ...
ntime.selectgo(0xc04233fee0, 0xc04233fe3c, 0x1fa43e0?, 0x1, 0x1a95bc0?, 0x1)
	runtime/select.go:335 +0x7a5 fp=0xc04233fdf8 sp=0xc04233fcd0 pc=0x4505e5
go.k6.io/k6/internal/js/modules/k6/experimental/websockets.(*webSocket).writePump(0xc03880e380, 0xc052478030)
	go.k6.io/k6/internal/js/modules/k6/experimental/websockets/websockets.go:585 +0x331 fp=0xc04233ffc0 sp=0xc04233fdf8 pc=0x155f591
go.k6.io/k6/internal/js/modules/k6/experimental/websockets.(*webSocket).loop.gowrap2()
	go.k6.io/k6/internal/js/modules/k6/experimental/websockets/websockets.go:392 +0x25 fp=0xc04233ffe0 sp=0xc04233ffc0 pc=0x155e445
runtime.goexit({})
	runtime/asm_amd64.s:1700 +0x1 fp=0xc04233ffe8 sp=0xc04233ffe0 pc=0x47cf01
created by go.k6.io/k6/internal/js/modules/k6/experimental/websockets.(*webSocket).loop in goroutine 15748
	go.k6.io/k6/internal/js/modules/k6/experimental/websockets/websockets.go:392 +0x2fa

goroutine 15693 gp=0xc041e5c000 m=nil [select, 5 minutes]:
runtime.gopark(0xc041de7f18?, 0x2?, 0x0?, 0xc0?, 0xc041de7e94?)
	runtime/proc.go:424 +0xce fp=0xc041de7d20 sp=0xc041de7d00 pc=0x474aae
runtime.selectgo(0xc041de7f18, 0xc041de7e90, 0x2?, 0x0, 0xc1e7ab38e7f6b301?, 0x1)
	runtime/select.go:335 +0x7a5 fp=0xc041de7e48 sp=0xc041de7d20 pc=0x4505e5
go.k6.io/k6/internal/js/modules/k6/experimental/websockets.(*webSocket).writePump.func1()
	go.k6.io/k6/internal/js/modules/k6/experimental/websockets/websockets.go:530 +0x113 fp=0xc041de7fe0 sp=0xc041de7e48 pc=0x155f913
runtime.goexit({})
	runtime/asm_amd64.s:1700 +0x1 fp=0xc041de7fe8 sp=0xc041de7fe0 pc=0x47cf01
created by go.k6.io/k6/internal/js/modules/k6/experimental/websockets.(*webSocket).writePump in goroutine 15692
	go.k6.io/k6/internal/js/modules/k6/experimental/websockets/websockets.go:527 +0x185

rax    0xca
rbx    0x0
rcx    0x47ed03
rdx    0x0
rdi    0x300e120
rsi    0x80
rbp    0xc000092728
rsp    0xc0000926e0
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x7fff6d248038
r13    0x1
r14    0xc000585880
r15    0x5
rip    0x47ed01
rflags 0x286
cs     0x33
fs     0x0
gs     0x0

So ideally, we should be able to handle unblocking the regular process of shutting down k6.

Why?

k6 should exit without need of killing it

[saniyar-dev]

Hi @olegbespalov, I've been trying to reproduce the result you provided, but could not.
Can you provide more information on how to reproduce this?

[olegbespalov]

Hey @saniyar-dev

Unfortunately, I don't have yet a script/steps for reproducing, what I think it happens for some rare workloads, but I opened the issue to make it discoverable, and we can collect more details here.