Error closing the WebSocket connection at end of test

[unlikelyzero]

I'm using xk6 and xk6-browser for the first time. When running the example script:

import launcher from 'k6/x/browser';

export default function() {
  const browser = launcher.launch('chromium', {
    headless: __ENV.XK6_HEADLESS ? true : false,
  });
  const context = browser.newContext();
  const page = context.newPage();
  page.goto('https://test.k6.io/');
  page.screenshot({ path: 'screenshot.png' });
  // TODO: Assert this somehow. Upload as CI artifact or just an external `ls`?
  // Maybe even do a fuzzy image comparison against a preset known good screenshot?
  page.close();
  browser.close();
}

I see the following output:

./xk6-browser run ./perf/tests/xk6-browser/example.js

          /\      |‾‾| /‾‾/   /‾‾/
     /\  /  \     |  |/  /   /  /
    /  \/    \    |     (   /   ‾‾\
   /          \   |  |\  \ |  (‾)  |
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: ./perf/tests/xk6-browser/example.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

WARN[0003] error fetching response body for 'https://test.k6.io/': No data found for resource with given identifier (-32000)  category=cdp elapsed="0 ms" goroutine=115
WARN[0003] error fetching response body for 'https://test.k6.io/static/favicon.ico': context canceled  category=cdp elapsed="0 ms" goroutine=115

running (00m03.1s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [========================] 1 VUs  00m03.1s/10m0s  1/1 iters, 1 per VU

     browser_dom_content_loaded.......: avg=166.25ms min=113µs    med=166.25ms max=332.39ms p(90)=299.16ms p(95)=315.78ms
     browser_first_contentful_paint...: avg=379.75ms min=379.75ms med=379.75ms max=379.75ms p(90)=379.75ms p(95)=379.75ms
     browser_first_paint..............: avg=379.66ms min=379.66ms med=379.66ms max=379.66ms p(90)=379.66ms p(95)=379.66ms
     browser_loaded...................: avg=191.62ms min=3.3ms    med=191.62ms max=379.94ms p(90)=342.28ms p(95)=361.11ms
     data_received....................: 5.7 kB 1.8 kB/s
     data_sent........................: 1.4 kB 447 B/s
     http_req_connecting..............: avg=106.5ms  min=0s       med=0s       max=426ms    p(90)=298.2ms  p(95)=362.09ms
     http_req_duration................: avg=383.99ms min=99ms     med=282.09ms max=872.77ms p(90)=696.22ms p(95)=784.5ms
     http_req_receiving...............: avg=187.5ms  min=96ms     med=186.5ms  max=281ms    p(90)=279.5ms  p(95)=280.25ms
     http_req_sending.................: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s
     http_req_tls_handshaking.........: avg=63.5ms   min=0s       med=0s       max=254ms    p(90)=177.8ms  p(95)=215.89ms
     http_reqs........................: 4      1.291019/s
     iteration_duration...............: avg=3.09s    min=3.09s    med=3.09s    max=3.09s    p(90)=3.09s    p(95)=3.09s
     iterations.......................: 1      0.322755/s
     vus..............................: 1      min=1      max=1
     vus_max..........................: 1      min=1      max=1

ERRO[0003] err:websocket: close 1006 (abnormal closure): unexpected EOF  category="Connection:handleIOError" elapsed="0 ms" goroutine=82

[imiric]

Hi, thanks for reporting this.

What's your operating system and version, and which xk6-browser version (or commit) are you running? If you clone the repo, checkout main (4ae711e), and run xk6 run examples/screenshot.js does the issue still happen?

The error fetching response body warnings should be gone, or much less frequent on latest main, though it's still not part of a release.

The abnormal closure message is a known issue (see #26, #139), but shouldn't have a functional impact on the test. Is the screenshot.png file still produced? I.e. does the script work normally otherwise?

[unlikelyzero]

@imiric

1. I'm using the latest published version. I will attempt to troubleshoot tomorrow
2. The screenshot is still produced

[inancgumus]

I'm using the latest published version.

Hi, @unlikelyzero, the latest released version doesn't contain the latest fixes. Please try using the main branch as explained by @imiric before:

If you clone the repo, checkout main (https://github.com/grafana/xk6-browser/commit/4ae711e4a63edec5c98e9a70fd6859dcd4f9574d)...

[unlikelyzero]

@inancgumus understood. I won't be able to get back to this to attempt his outlined troubleshooting steps until tomorrow

[arahja]

I am seeing this error as well. I have tested with version 0.2.0 and building from source using the following code:

go install go.k6.io/xk6/cmd/xk6@latest 
xk6 build --output xk6-browser --with github.com/grafana/xk6-browser

[imiric]

Thanks for confirming @arahja. We've run into this error as well, though it should be happening less frequently since recent changes.

To confirm: it only happens when the test run finishes (successfully or otherwise), but doesn't actually impact any functionality? I.e. you don't get this unexpectedly during a test run?

If so, it can be safely ignored. We'll fix it soon, but we currently have higher priority issues to focus on.

[satriaadhii]

Hi i want to report the same problem, here's the code:

import launcher from "k6/x/browser";

export default function() {
   const browser = launcher.launch('chromium', { headless: false });
   const context = browser.newContext();
   const page = context.newPage();

   // Goto front page, find login link and click it
   page.goto('https://test.k6.io/', { waitUntil: 'networkidle' });
   const elem = page.$('a[href="/my_messages.php"]');
   elem.click();

   // Enter login credentials and login
   page.$('input[name="login"]').type('admin');
   page.$('input[name="password"]').type('123');
   page.$('input[type="submit"]').click();

   // Wait for next page to load
   page.waitForLoadState('networkidle');

   page.close();
   browser.close();
}

It produce error:

          /\      |‾‾| /‾‾/   /‾‾/   
     /\  /  \     |  |/  /   /  /    
    /  \/    \    |     (   /   ‾‾\  
   /          \   |  |\  \ |  (‾)  | 
  / __________ \  |__| \__\ \_____/ .io

  execution: local
     script: hehe.js
     output: -

  scenarios: (100.00%) 1 scenario, 1 max VUs, 10m30s max duration (incl. graceful stop):
           * default: 1 iterations for each of 1 VUs (maxDuration: 10m0s, gracefulStop: 30s)

WARN[0004] url:https://test.k6.io/static/favicon.ico method:GET err:error fetching response body: No resource with given identifier found (-32000)  category="Response:bodySize:fetchBody" elapsed="0 ms" goroutine=99

running (00m04.5s), 0/1 VUs, 1 complete and 0 interrupted iterations
default ✓ [======================================] 1 VUs  00m04.5s/10m0s  1/1 iters, 1 per VU
ERRO[0005] err:websocket: close 1006 (abnormal closure): unexpected EOF  category="Connection:handleIOError" elapsed="0 ms" goroutine=85

     browser_dom_content_loaded.......: avg=309.72ms min=126µs    med=54.82ms  max=874.22ms p(90)=710.34ms p(95)=792.28ms
     browser_first_contentful_paint...: avg=367.53ms min=52.64ms  med=367.53ms max=682.42ms p(90)=619.44ms p(95)=650.93ms
     browser_first_meaningful_paint...: avg=898.04ms min=898.04ms med=898.04ms max=898.04ms p(90)=898.04ms p(95)=898.04ms
     browser_first_paint..............: avg=367.41ms min=52.57ms  med=367.41ms max=682.26ms p(90)=619.29ms p(95)=650.77ms
     browser_loaded...................: avg=304.48ms min=3.18ms   med=54.38ms  max=855.89ms p(90)=695.58ms p(95)=775.74ms
     data_received....................: 29 kB  6.5 kB/s
     data_sent........................: 2.4 kB 525 B/s
     http_req_connecting..............: avg=217.33ms min=0s       med=0s       max=1.3s     p(90)=652ms    p(95)=978ms   
     http_req_duration................: avg=624.59ms min=2.69ms   med=489.06ms max=1.79s    p(90)=1.22s    p(95)=1.5s    
     http_req_receiving...............: avg=301.5ms  min=0s       med=328.5ms  max=433ms    p(90)=421.5ms  p(95)=427.25ms
     http_req_sending.................: avg=0s       min=0s       med=0s       max=0s       p(90)=0s       p(95)=0s      
     http_req_tls_handshaking.........: avg=212.83ms min=0s       med=0s       max=1.27s    p(90)=638.5ms  p(95)=957.75ms
     http_reqs........................: 6      1.32504/s
     iteration_duration...............: avg=4.52s    min=4.52s    med=4.52s    max=4.52s    p(90)=4.52s    p(95)=4.52s   
     iterations.......................: 1      0.22084/s
     vus..............................: 1      min=1     max=1
     vus_max..........................: 1      min=1     max=1

The problem is whenever the task start it suddenly stop and seems like the page.waitForLoadState('networkidle'); doesn't work because it doesn't finish loading the page. Is it because the websocket error? hope you solved this soon.

By the way i love what you working on, and i deeply thank this K6 contributors.

[imiric]

@satriaadhii That's a similar test to the fillform.js example.

Notice that the example uses page.waitForNavigation() instead of page.waitForLoadState('networkidle') because there is a race condition that might trigger where the networkidle state is reached before the actual navigation happens. That would lead to a premature browser close and the error, though we should certainly handle it gracefully and close the WS connection properly in all cases.

This is why I don't think this error is causing any issues, and is merely an informative error. In all scenarios I've seen it in the test finishes successfully, or there's an earlier error that causes the premature close.

If someone is seeing that this error is causing the test to end prematurely (i.e. the WS connection is getting closed abruptly mid-test), please share an example script, and we'll remove the low prio label and prioritize this issue higher.

[imiric]

A similar issue was reported on the forum by a Windows user:

ERRO[0002] err:read tcp 127.0.0.1:59516->127.0.0.1:59515: wsarecv: An existing connection was forcibly closed by the remote host. category="Connection:handleIOError" elapsed="0 ms" goroutine=47

These are harmless errors for the test, but it seems we're not handling the WS connection close properly.

We'll try to fix this in the release after v0.3.0.

[imiric]

This error is more visible if running more than 1 iteration, e.g.:

XK6_BROWSER_LOG=info XK6_HEADLESS=1 xk6 run -u 1 -i 10 examples/fillform.js

We're prioritizing this issue higher, and will try to fix it in the next few weeks.

[imiric]

Hey everyone, apologies for the delay with this issue, but it should be fixed on the main branch now.

You can test it out by compiling a custom binary with:

xk6 build --with github.com/grafana/xk6-browser@main

Or wait a few weeks for v0.6.0 to be released and use the pre-built binary in the stable release.