Deadlock: Another element is intercepting with pointer action

[inancgumus]

Brief summary

The test run ID 1900312 fails with the following errors:

1:

ERRO[0009] Uncaught (in promise) clicking on "[data-attribute=\"something\"][data-value=\"color\"] a.otherthing-anchor": checking hit target: another element is intercepting with pointer action  executor=shared-iterations scenario=browser

2 Timeout:

exit status 2

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

goroutine 0 [idle]:
runtime.futex()
	runtime/sys_linux_amd64.s:554 +0x21 fp=0x7fff93e04f88 sp=0x7fff93e04f80 pc=0x471b21
runtime.futexsleep(0x1c003f5dfff?, 0x93e05008?, 0x44808c?)
	runtime/os_linux.go:69 +0x36 fp=0x7fff93e04fd8 sp=0x7fff93e04f88 pc=0x434ff6
runtime.notesleep(0x273a7e8)
	runtime/lock_futex.go:160 +0x87 fp=0x7fff93e05010 sp=0x7fff93e04fd8 pc=0x40c407
runtime.mPark(...)
	runtime/proc.go:1531
runtime.stopm()
	runtime/proc.go:2335 +0x8c fp=0x7fff93e05040 sp=0x7fff93e05010 pc=0x43f9ec
runtime.findRunnable()
	runtime/proc.go:3025 +0xabc fp=0x7fff93e05148 sp=0x7fff93e05040 pc=0x44129c
runtime.schedule()
	runtime/proc.go:3378 +0xb1 fp=0x7fff93e05180 sp=0x7fff93e05148 pc=0x4420d1
runtime.park_m(0xc00196e680?)
	runtime/proc.go:3529 +0x12d fp=0x7fff93e051b0 sp=0x7fff93e05180 pc=0x4425ed
runtime.mcall()
	runtime/asm_amd64.s:452 +0x43 fp=0x7fff93e051c0 sp=0x7fff93e051b0 pc=0x46dae3

goroutine 1 [chan receive, 9 minutes]:
runtime.gopark(0xc001f9cd90?, 0x10?, 0x10?, 0x0?, 0xc002c9e6b8?)
	runtime/proc.go:381 +0xd6 fp=0xc0005be638 sp=0xc0005be618 pc=0x43bb16
runtime.chanrecv(0xc00247a3c0, 0xc002c9e7f0, 0x1)
	runtime/chan.go:583 +0x49d fp=0xc0005be6c8 sp=0xc0005be638 pc=0x406f9d
runtime.chanrecv1(0x1a0c668?, 0xc001a27d10?)
	runtime/chan.go:442 +0x18 fp=0xc0005be6f0 sp=0xc0005be6c8 pc=0x406a98
go.k6.io/k6/execution.(*Scheduler).Run(0xc0012527e0, {0x1a0c5c0, 0xc0000d1810}, {0x1a0c668, 0xc000562630}, 0xc001f68de0)
	go.k6.io/k6/execution/scheduler.go:472 +0xc95 fp=0xc0005beec8 sp=0xc0005be6f0 pc=0x850815
go.k6.io/k6/cmd.(*cmdRun).run(0xc000012268, 0xc000550f00, {0xc000147b80?, 0x1, 0x2c})
	go.k6.io/k6/cmd/run.go:352 +0x15ad fp=0xc0005bfc80 sp=0xc0005beec8 pc=0x13d972d
go.k6.io/k6/cmd.(*cmdRun).run-fm(0xc000550f00?, {0xc000147b80?, 0x2c?, 0x2c?})
	<autogenerated>:1 +0x3a fp=0xc0005bfcb8 sp=0xc0005bfc80 pc=0x13e425a
github.com/spf13/cobra.(*Command).execute(0xc000550f00, {0xc000147600, 0x2c, 0x2c})
	github.com/spf13/cobra@v1.4.0/command.go:856 +0x67c fp=0xc0005b
... omitting 1266401 bytes ...
3, 0x1, 0x95?)
	runtime/sema.go:160 +0x20f fp=0xc003642e90 sp=0xc003642e28 pc=0x44d2af
sync.runtime_SemacquireMutex(0x69554762696c325a?, 0x4f?, 0x75466d5969775366?)
	runtime/sema.go:77 +0x26 fp=0xc003642ec8 sp=0xc003642e90 pc=0x46ba46
sync.(*Mutex).lockSlow(0xc000fee8a0)
	sync/mutex.go:171 +0x165 fp=0xc003642f18 sp=0xc003642ec8 pc=0x48d285
sync.(*Mutex).Lock(...)
	sync/mutex.go:90
github.com/grafana/xk6-browser/common.(*BaseEventEmitter).emit.func1(0xc00180ba60)
	github.com/grafana/xk6-browser@v1.0.2/common/event_emitter.go:158 +0x67 fp=0xc003642fc8 sp=0xc003642f18 pc=0x11fc127
github.com/grafana/xk6-browser/common.(*BaseEventEmitter).emit.func2.1()
	github.com/grafana/xk6-browser@v1.0.2/common/event_emitter.go:194 +0x2a fp=0xc003642fe0 sp=0xc003642fc8 pc=0x11a5c0a
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc003642fe8 sp=0xc003642fe0 pc=0x46fbe1
created by github.com/grafana/xk6-browser/common.(*BaseEventEmitter).emit.func2
	github.com/grafana/xk6-browser@v1.0.2/common/event_emitter.go:194 +0x34a

goroutine 15085 [select, 8 minutes]:
runtime.gopark(0xc0036437a8?, 0x2?, 0x39?, 0x75?, 0xc00364379c?)
	runtime/proc.go:381 +0xd6 fp=0xc003643620 sp=0xc003643600 pc=0x43bb16
runtime.selectgo(0xc0036437a8, 0xc003643798, 0xc000668438?, 0x0, 0x1579e40?, 0x1)
	runtime/select.go:327 +0x7be fp=0xc003643760 sp=0xc003643620 pc=0x44c1be
github.com/grafana/xk6-browser/common.contextWithDoneChan.func1()
	github.com/grafana/xk6-browser@v1.0.2/common/context.go:61 +0x87 fp=0xc0036437e0 sp=0xc003643760 pc=0x1196d47
runtime.goexit()
	runtime/asm_amd64.s:1598 +0x1 fp=0xc0036437e8 sp=0xc0036437e0 pc=0x46fbe1
created by github.com/grafana/xk6-browser/common.contextWithDoneChan
	github.com/grafana/xk6-browser@v1.0.2/common/context.go:59 +0xba

rax    0xca
rbx    0x0
rcx    0x471b23
rdx    0x0
rdi    0x273a7e8
rsi    0x80
rbp    0x7fff93e04fc8
rsp    0x7fff93e04f80
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0xc000054500
r13    0x0
r14    0x2739ee0
r15    0x1
rip    0x471b21
rflags 0x286
cs     0x33
fs     0x0
gs     0x0

xk6-browser version

v1.0.2

OS

Linux

Chrome version

Cloud

Docker version and image (if applicable)

No response

Steps to reproduce the problem

See the script in the test run and run it locally. The local run doesn't have the second error, only the first one.

Expected behaviour

No panic if this turns out to be a bug. Investigation needed.

Actual behaviour

Panic.

[tom-miseur]

Am I correct in thinking that this should theoretically be accounted for as part of the auto-waiting "actionability" checks? I've found that, even with a timeout parameter set, I still see this error, despite the fact that the element doesn't have anything "in front of" it.

[ankur22]

Am I correct in thinking that this should theoretically be accounted for as part of the auto-waiting "actionability" checks? I've found that, even with a timeout parameter set, I still see this error, despite the fact that the element doesn't have anything "in front of" it.

@tom-miseur Do you have an example script that we can use to debug this issue with? Your theory sounds plausible.

[rgrygorovych]

Same issue for me,

ERRO[0010] Uncaught (in promise) clicking on "//one-appnav/div/div/div/div/one-app-launcher-header/button": checking hit target: another element is intercepting with pointer action  executor=constant-vus scenario=browser

The code snippet:

this.page.waitForSelector("//one-appnav/div/div/div/div/one-app-launcher-header/button");
await this.page.locator("//one-appnav/div/div/div/div/one-app-launcher-header/button").click();

[rgrygorovych]

In my case tag <ONE-APPNAV> intercepted the click.

How did I determined which actual tag processed.

I injected JS script to my web page:

  public async watchEvent(event: string): Promise<any> {
    return this.page.waitForFunction(
      `document.addEventListener('${event}', function(event) {console.log('Watching [${event}]:', event.target.tagName, event.target.id, event.target.className, event.clientX, event.clientY)})`,
      {
        polling: 'mutation',
        timeout: 200000,
      },
    );
  }

and added to my test before the click:

await this.watchEvent('click');
await this.page.locator('//one-appnav/div/div/div/div/one-app-launcher-header/button').click();

Then we need to run a test in headless mode off:

npm run bundle && k6 run -e K6_BROWSER_HEADLESS=false -e K6_BROWSER_DEBUG=false tests/ProviderPortalTest.js  

test options looks like this:

export const options: any = {
 scenarios: {
   browser: {
     executor: 'constant-vus',
     exec: 'mrrProviderPortalById',
     vus: 1,
     duration: '10s',
     options: {
       browser: {
         type: 'chromium',
       },
     },
   },
 },
};

this allow me to have only one test instance executed at most, and so, I can interact with web application manually.|

Clicking on the target button I got following printed:

INFO[0018] Watching [click]: ONE-APPNAV   34 105         browser_source=console-api source=browser
INFO[0018] Watching [click]: ONE-APPNAV   34 105         browser_source=console-api source=browser
INFO[0018] Watching [click]: ONE-APPNAV   34 105         browser_source=console-api source=browser
INFO[0018] Watching [click]: ONE-APPNAV   34 105         browser_source=console-api source=browser
INFO[0018] Watching [click]: ONE-APPNAV   34 105         browser_source=console-api source=browser

Not 100% sure if this is correct, just my way to debug it.

[rgrygorovych]

Checking the k6's browser extension implementation, I found this:

		// Do a final actionability check to see if element can receive events
		// at mouse position in question
		if !opts.Force {
			if ok, err := h.checkHitTargetAt(apiCtx, *p); !ok {
				return nil, fmt.Errorf("checking hit target: %w", err)
			}
		}

So, I tried to modify my code:

this.page.click("//one-appnav/div/div/div/div/one-app-launcher-header/button", { force: true });

And it looks like it worked. @inancgumus did you tried with force flag?

[inancgumus]

@inancgumus did you tried with force flag?

@rgrygorovych

The force option works because it skips the actionability checks (as @tom-miseur has also guessed it). So, we follow the Playwright's approach, as there can be problems with complex sites while doing actionability checks.

Here's the Playwright's explanation:

Forcing the click
Sometimes, apps use non-trivial logic where hovering the element overlays it with another element that intercepts the click. This behavior is indistinguishable from a bug where element gets covered and the click is dispatched elsewhere. If you know this is taking place, you can bypass the actionability checks and force the click.

Source: https://playwright.dev/docs/input

So, this might not be a bug 😅 Maybe, we should improve our documentation. I've created an issue. Closing this issue. Feel free to reopen it.