Browser hangs when waiting for the browserProc to close

[ankur22]

Brief summary

Here's the stack trace:

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

goroutine 0 gp=0x2ef51e0 m=0 mp=0x2ef6420 [idle]:
runtime.futex(0x2ef6560, 0x80, 0x0, 0x0, 0x0, 0x0)
    runtime/sys_linux_amd64.s:557 +0x21 fp=0x7fffbfcd7a80 sp=0x7fffbfcd7a78 pc=0x47ee21
runtime.futexsleep(0x7fffbfcd7af8?, 0x40f630?, 0x100000000?)
    runtime/os_linux.go:69 +0x30 fp=0x7fffbfcd7ad0 sp=0x7fffbfcd7a80 pc=0x437dd0
runtime.notesleep(0x2ef6560)
    runtime/lock_futex.go:170 +0x87 fp=0x7fffbfcd7b08 sp=0x7fffbfcd7ad0 pc=0x40f7c7
runtime.mPark(...)
    runtime/proc.go:1866
runtime.stopm()
    runtime/proc.go:2885 +0x8c fp=0x7fffbfcd7b38 sp=0x7fffbfcd7b08 pc=0x4432ac
runtime.findRunnable()
    runtime/proc.go:3622 +0xd5c fp=0x7fffbfcd7cb0 sp=0x7fffbfcd7b38 pc=0x444d1c
runtime.schedule()
    runtime/proc.go:3995 +0xb1 fp=0x7fffbfcd7ce8 sp=0x7fffbfcd7cb0 pc=0x445df1
runtime.park_m(0xc000404540)
    runtime/proc.go:4102 +0x1eb fp=0x7fffbfcd7d40 sp=0x7fffbfcd7ce8 pc=0x44620b
runtime.mcall()
    runtime/asm_amd64.s:459 +0x4e fp=0x7fffbfcd7d58 sp=0x7fffbfcd7d40 pc=0x47b16e

goroutine 1 gp=0xc0000061c0 m=nil [chan receive, 5 minutes]:
runtime.gopark(0x600008?, 0x7f575940ec08?, 0x40?, 0x0?, 0x0?)
    runtime/proc.go:424 +0xce fp=0xc00096e988 sp=0xc00096e968 pc=0x474bce
runtime.chanrecv(0xc0002e8620, 0xc000822b78, 0x1)
    runtime/chan.go:639 +0x41c fp=0xc00096ea00 sp=0xc00096e988 pc=0x40a05c
runtime.chanrecv1(0x1f1fa70?, 0xc000414270?)
    runtime/chan.go:489 +0x12 fp=0xc00096ea28 sp=0xc00096ea00 pc=0x409c12
go.k6.io/k6/execution.(*Scheduler).Run(0xc0005ef980, {0x1f1faa8, 0xc0005b6230}, {0x1f1fa70, 0xc0004d1a40}, 0xc0002e88c0)
    go.k6.io/k6/execution/scheduler.go:508 +0xcb4 fp=0xc00096efc0 sp=0xc00096ea28 pc=0xa9ccd4
go.k6.io/k6/cmd.(*cmdRun).run(0xc0002a60d0, 0xc0004d4008, {0xc000209208, 0x1, 0x2f})
    go.k6.io/k6/cmd/run.go:397 +0x1545 fp=0xc00096fc50 sp=0xc00096efc0 pc=0x17838e5
go.k6.io/k6/cmd.(*cmdRun).run-fm(0xc000453b00?, {0xc000209208?, 0x4?, 0x1bad6e0?})
    <autogenerated>:1 +0x34 fp=0xc00096fc88 sp=0xc00096fc50 pc=0x178e854
github.com/spf13/cobra.(*Command).execute(0xc0004d4008, {0xc
... omitting 46246 bytes ...
=0x176e3c5
go.k6.io/k6/js.(*ActiveVU).RunOnce(0xc00067e2c0)
    go.k6.io/k6/js/runner.go:776 +0x4a5 fp=0xc00052bee0 sp=0xc00052bd68 pc=0x176dc25
go.k6.io/k6/lib/executor.ConstantArrivalRate.Run.getIterationRunner.func9({0x1f1fa70, 0xc0004146f0}, {0x1f0a2c0?, 0xc00067e2c0?})
    go.k6.io/k6/lib/executor/helpers.go:108 +0x4a fp=0xc00052bf58 sp=0xc00052bee0 pc=0xaa258a
go.k6.io/k6/lib/executor.(*activeVUPool).AddVU.func1()
    go.k6.io/k6/lib/executor/ramping_arrival_rate.go:546 +0xd5 fp=0xc00052bfe0 sp=0xc00052bf58 pc=0xab1375
runtime.goexit({})
    runtime/asm_amd64.s:1700 +0x1 fp=0xc00052bfe8 sp=0xc00052bfe0 pc=0x47d021
created by go.k6.io/k6/lib/executor.(*activeVUPool).AddVU in goroutine 145
    go.k6.io/k6/lib/executor/ramping_arrival_rate.go:539 +0xef

goroutine 38 gp=0xc000534c40 m=nil [select, 5 minutes]:
runtime.gopark(0xc000723f80?, 0x2?, 0xb8?, 0xc5?, 0xc000723f7c?)
    runtime/proc.go:424 +0xce fp=0xc000723e20 sp=0xc000723e00 pc=0x474bce
runtime.selectgo(0xc000723f80, 0xc000723f78, 0x0?, 0x0, 0x1?, 0x1)
    runtime/select.go:335 +0x7a5 fp=0xc000723f48 sp=0xc000723e20 pc=0x450865
github.com/grafana/xk6-browser/common.(*BrowserProcess).handleClose(0xc000598300, {0x1f1faa8?, 0xc0000d42d0?})
    github.com/grafana/xk6-browser@v1.8.2/common/browser_process.go:93 +0x6f fp=0xc000723fb8 sp=0xc000723f48 pc=0x1520a6f
github.com/grafana/xk6-browser/common.NewRemoteBrowserProcess.gowrap1()
    github.com/grafana/xk6-browser@v1.8.2/common/browser_process.go:85 +0x28 fp=0xc000723fe0 sp=0xc000723fb8 pc=0x15209c8
runtime.goexit({})
    runtime/asm_amd64.s:1700 +0x1 fp=0xc000723fe8 sp=0xc000723fe0 pc=0x47d021
created by github.com/grafana/xk6-browser/common.NewRemoteBrowserProcess in goroutine 115
    github.com/grafana/xk6-browser@v1.8.2/common/browser_process.go:85 +0x1d9

xk6-browser version

v1.8.3

OS

NA

Chrome version

NA

Docker version and image (if applicable)

No response

Steps to reproduce the problem

This can be reproduced by running the following and sending a SIGINT to the process after 13+ seconds of the test running:

import { browser } from 'k6/browser';

export const options = {
  cloud: {
    distribution: {
      distributionLabel1: { loadZone: 'amazon:se:stockholm', percent: 100 },
    },
  },
  scenarios: {
    browser: {
      executor: 'ramping-vus',
      startVUs: 1,
      stages: [
        { duration: '1m', target: 100 },
        { duration: '1m', target: 200 },
        { duration: '1m', target: 0 },
      ],
      gracefulRampDown: '30s', // Graceful ramp-down time
      options: {
        browser: {
          type: 'chromium',
        },
      },
    },
  },
};

export default async function() {
  const page = await browser.newPage();
  await page.goto('https://test.k6.io');
  await page.close();
}

Expected behaviour

It should shut down when the context is closed instead of waiting to read off of p.lostConnection.

Actual behaviour

It hangs waiting onp.lostConnection.

This might not be the root cause of the issue.

1. For the goroutine to indefinitely wait on p.lostConnection, means that:
2. didLoseConnection wasn't called, and for that not have been called means that:
3. the internal browser context wasn't closed which means that:
4. the browser.close wasn't called, for that to happen it would mean that:
5. the iterEnd or exit event wasn't sent by k6
6. And finally that means that the browser module didn't shutdown when the iteration ended. Only once the iteration ends will the iterEnd and exit events be sent :/

This means that there is/are APIs in the browser module which do not adhere to the vu context closing 😢

My tasks

Beta Give feedback

1. Fix buffered chan event system k6#3968
   +0
2. Fix hanging close browser cdp req #1442
   +0
3. Improve browser close detection #1444
   enhancement +1
4. Release notes.

[inancgumus]

@ankur22 Do we need an Abort event or can we solve this with Context? I hope it's the latter :)

[ankur22]

It's two fold:

1. There's an issue in the k6 event system whereby it thinks that it hasn't received all the event.done() calls from all the subscribers.
2. The connection close cdp request is sent but a response is never received since the chromium has already exited.