IterEnd event handling leads to test abort (racy)

[inancgumus]

What?

Sometimes context is done before IterEnd events are processed. This leads to a test abort.

For more information, here's the full debug log of a Github CI test run.

Click here to see the log.

+ '[' Windows == Linux ']'
+ export K6_BROWSER_HEADLESS=true
+ K6_BROWSER_HEADLESS=true
+ for f in examples/*.js
+ '[' examples/colorscheme.js == examples/hosts.js ']'
+ ./k6extension run -q examples/colorscheme.js
##[debug]Re-evaluate condition on job cancellation for step: 'Run E2E tests'.
time="2024-07-10T06:05:33Z" level=info msg="dark-mode-toggle-1 changed the color scheme to dark" browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="Not remembering the last selected mode." browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="dark-mode-toggle-2 changed the color scheme to dark" browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="Not remembering the last selected mode." browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="dark-mode-toggle-3 changed the color scheme to dark" browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="Not remembering the last selected mode." browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="dark-mode-toggle-4 changed the color scheme to dark" browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="Not remembering the last selected mode." browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="dark-mode-toggle-5 changed the color scheme to dark" browser_source=console-api source=browser
time="2024-07-10T06:05:33Z" level=info msg="Not remembering the last selected mode." browser_source=console-api source=browser

     ✓ isDarkColorScheme

     browser_data_received.......: 116 kB  3.2 kB/s
     browser_data_sent...........: 5.4 kB  150 B/s
     browser_http_req_duration...: avg=245.27ms min=6.59ms   med=10.3ms   max=2.52s    p(90)=448.76ms p(95)=1.34s   
     browser_http_req_failed.....: 0.00%   ✓ 0        ✗ 13 
     browser_web_vital_cls.......: avg=0.002558 min=0.002558 med=0.002558 max=0.002558 p(90)=0.002558 p(95)=0.002558
     browser_web_vital_fcp.......: avg=3.1s     min=3.1s     med=3.1s     max=3.1s     p(90)=3.1s     p(95)=3.1s    
     browser_web_vital_lcp.......: avg=3.1s     min=3.1s     med=3.1s     max=3.1s     p(90)=3.1s     p(95)=3.1s    
     browser_web_vital_ttfb......: avg=2.42s    min=2.42s    med=2.42s    max=2.42s    p(90)=2.42s    p(95)=2.42s   
   ✓ checks......................: 100.00% ✓ 1        ✗ 0  
     data_received...............: 0 B     0 B/s
     data_sent...................: 0 B     0 B/s
     iteration_duration..........: avg=14.34s   min=14.34s   med=14.34s   max=14.34s   p(90)=14.34s   p(95)=14.34s  
     iterations..................: 1       0.0279[41](https://github.com/grafana/xk6-browser/actions/runs/9868967933/job/27251868196#step:7:42)/s
     vus.........................: 1       min=1      max=1
     vus_max.....................: 1       min=1      max=1

+ for f in examples/*.js
+ '[' examples/cookies.js == examples/hosts.js ']'
+ ./k6extension run -q examples/cookies.js

     ✓ initial number of cookies should be zero
     ✓ number of cookies should be 2
     ✓ cookie 1 name should be testcookie
     ✓ cookie 1 value should be 1
     ✓ cookie 1 should be session cookie
     ✓ cookie 1 should have domain
     ✓ cookie 1 should have path
     ✓ cookie 1 should have sameSite
     ✓ cookie 1 should be httpOnly
     ✓ cookie 1 should be secure
     ✓ cookie 2 name should be testcookie2
     ✓ cookie 2 value should be 2
     ✓ number of filtered cookies should be 2
     ✓ the first filtered cookie name should be foo
     ✓ the first filtered cookie value should be [42](https://github.com/grafana/xk6-browser/actions/runs/9868967933/job/27251868196#step:7:43)
     ✓ the second filtered cookie name should be baz
     ✓ the second filtered cookie value should be [44](https://github.com/grafana/xk6-browser/actions/runs/9868967933/job/27251868196#step:7:45)
     ✓ number of cookies should be zero

   ✓ checks...............: 100.00% ✓ 18       ✗ 0
     data_received........: 0 B     0 B/s
     data_sent............: 0 B     0 B/s
     iteration_duration...: avg=1[45](https://github.com/grafana/xk6-browser/actions/runs/9868967933/job/27251868196#step:7:46).09ms min=145.09ms med=145.09ms max=145.09ms p(90)=145.09ms p(95)=145.09ms
     iterations...........: 1       2.327455/s

+ for f in examples/*.js
+ '[' examples/device_emulation.js == examples/hosts.js ']'
+ ./k6extension run -q examples/device_emulation.js
time="2024-07-10T06:05:36Z" level=warning error="context is done before all 'IterEnd' events were processed"

   ✓ checks..........: 0.00% ✓ 0   ✗ 0
     data_received...: 0 B   0 B/s
     data_sent.......: 0 B   0 B/s

time="2024-07-10T06:05:36Z" level=error msg="test run was aborted because k6 received a 'interrupt' signal"

Why?

Correctly handling the iteration events will result in more stable test runs.

How?

xk6-browser version: 1.6.0

Tasks

Tasks

Beta Give feedback

1. Subissue
2. PR
3. Docs PR
4. TypeScript Definitions PR
5. Update the k6 release notes

Related PR(s)/Issue(s)

• Executor error "could not get a VU from the buffer" when UI test is running too long #1395
• BrowserContext can't be created for reused VUs #1067
• Use IterStart to start browser process for iteration #926