Hi,
I have a test script that does a few page changes using client javascript calls but it constantly crashes with: “An existing connection was forcibly closed”
I cannot seem to understand why k6 breaks, maybe you have some ideas?
It seems like K6 is perhaps timing out or interpreting some failure to load woffs as a failure to load the page?
A second problem is that once it closes it context there is no way for me to measure that and take action. Preferably I want to keep the same context as to not download to much data while testing.
Any ideas?
The data and log is from a short moc run over only 60s in order to make replicating easier.
The complete log is (URL blanked out):
execution: local
script: scripts\moctest.js
output: -
scenarios: (100.00%) 1 scenario, 2 max VUs, 1m50s max duration (incl. graceful stop):
* default: Up to 2 looping VUs for 1m20s over 3 stages (gracefulRampDown: 30s, gracefulStop: 30s)
INFO[0002] :: Running setup source=console
INFO[0002] [1]:: requests: 5 source=console
INFO[0002] [1]request time: 9000 source=console
INFO[0002] [1]:: sleeping for 8.996s source=console
INFO[0011] [1]:: create context source=console
INFO[0012] [2]:: requests: 2 source=console
INFO[0013] [2]request time: 58000 source=console
INFO[0013] [2]:: sleeping for 57.223s source=console
INFO[0013] :: goto: https://MY.DOMAIN.com/pnt_fix_prod/Default.aspx?login=1&pageid=0 source=console
INFO[0015] [1]=====================> 1 source=console
INFO[0016] [1]request time: 27000 source=console
INFO[0016] [1]:: sleeping for 13.539s source=console
WARN[0017] The AudioContext was not allowed to start. It must be resumed (or created) after a user gesture on the page. https://goo.gl/7K7WLu browser_source=other line_number=233 source=browser url="https://MY.DOMAIN.com/pnt_fix_prod/include/amd/Highcharts%209.0.1.0/modules/sonification.js"
INFO[0029] [1]:: navigate to subl2g0tci1tglh9jo6j29 source=console
INFO[0029] :: goto pageid: subl2g0tci1tglh9jo6j29 source=console
WARN[0031] url:https://MY.DOMAIN.com/pnt_fix_prod/themes/X/fonts/fontawesome/webfonts/fa-regular-400.woff2 method:GET err:error fetching response body: No data found for resource with given identifier (-32000) category="Response:bodySize:fetchBody" elapsed="0 ms" goroutine=65
WARN[0031] url:https://MY.DOMAIN.com/pnt_fix_prod/themes/X/fonts/fontawesome/webfonts/fa-solid-900.woff2 method:GET err:error fetching response body: No data found for resource with given identifier (-32000) category="Response:bodySize:fetchBody" elapsed="0 ms" goroutine=65
INFO[0031] [1]=====================> 2 source=console
INFO[0031] [1]request time: 35000 source=console
INFO[0031] [1]:: sleeping for 5.888s source=console
INFO[0037] [1]:: navigate to searchpage source=console
INFO[0037] :: goto pageid: searchpage source=console
WARN[0039] url:https://MY.DOMAIN.com/pnt_fix_prod/themes/X/fonts/fontawesome/webfonts/fa-regular-400.woff2 method:GET err:error fetching response body: No data found for resource with given identifier (-32000) category="Response:bodySize:fetchBody" elapsed="0 ms" goroutine=65
WARN[0039] url:https://MY.DOMAIN.com/pnt_fix_prod/themes/X/fonts/fontawesome/webfonts/fa-solid-900.woff2 method:GET err:error fetching response body: No data found for resource with given identifier (-32000) category="Response:bodySize:fetchBody" elapsed="0 ms" goroutine=65
INFO[0039] [1]=====================> 3 source=console
INFO[0039] [1]request time: 46000 source=console
INFO[0039] [1]:: sleeping for 8.915s source=console
ERRO[0041] err:read tcp 127.0.0.1:64886->127.0.0.1:64885: wsarecv: An existing connection was forcibly closed by the remote host. category="Connection:handleIOError" elapsed="0 ms" goroutine=45
INFO[0048] [1]:: navigate to subl2g0tci1tglh9jo6j29 source=console
INFO[0048] :: goto pageid: subl2g0tci1tglh9jo6j29 source=console
ERRO[0049] wsURL:"ws://127.0.0.1:64885/devtools/browser/eeb495d7-382e-444b-b125-0bf70928cc15" sid:41EACE412790FCD6DC32C1F7DA32EBD7 err:context canceled category="Connection:send:<-c.ctx.Done()" elapsed="7996 ms" goroutine=34
ERRO[0049] [1]:: ERROR :: error calling evaluate: frame cannot evaluate: cannot call function on expression ("pid => _W.GoToPageId(pid)\n//# sourceURL=__xk6_browser_evaluation_script__\n") in execution context (7) in frame (1F1969461A362C929196BA1CD6A65D06) with session (41EACE412790FCD6DC32C1F7DA32EBD7): context canceled source=console
INFO[0049] [1]:: closing page source=console
INFO[0049] [1]request time: 60000 source=console
INFO[0049] [1]:: sleeping for 12.961s source=console
INFO[0062] [1]:: create new page source=console
ERRO[0062] [1]:: ERROR :: newPageInContext: missing browser context: 502999377E10F37D948649892A8E6C90 source=console
INFO[0062] [1]:: closing page source=console
INFO[0062] [1]request time: 9000 source=console
INFO[0062] [1]:: create new page source=console
ERRO[0062] [1]:: ERROR :: newPageInContext: missing browser context: 502999377E10F37D948649892A8E6C90 source=console
INFO[0062] [1]:: closing page source=console
ERRO[0062] wsURL:"ws://127.0.0.1:64885/devtools/browser/eeb495d7-382e-444b-b125-0bf70928cc15" sid: err:context canceled category="Connection:send:<-ctx.Done()" elapsed="13032 ms" goroutine=34
ERRO[0062] cannot dispose browser context: unable to dispose browser context *target.DisposeBrowserContextParams: context canceled
at reflect.methodValueCall (native)
at file:///C:/Program%20Files/k6/scripts/moctest.js:128:6(378)
at native executor=ramping-vus scenario=default source=stacktrace
INFO[0062] [1]:: requests: 5 source=console
INFO[0062] [1]request time: 9000 source=console
INFO[0062] [1]:: sleeping for 8.988s source=console
INFO[0071] [2]:: create context source=console
INFO[0071] :: goto: https://MY.DOMAIN.com/pnt_fix_prod/Default.aspx?login=1&pageid=0 source=console
INFO[0071] [1]:: create context source=console
INFO[0073] [2]=====================> 1 source=console
INFO[0074] [2]request time: 62000 source=console
INFO[0073] :: goto: https://MY.DOMAIN.com/pnt_fix_prod/Default.aspx?login=1&pageid=0 source=console
WARN[0074] url:https://MY.DOMAIN.com/pnt_fix_prod/include/amd/Highcharts%209.0.1.0/highcharts.js method:GET err:error fetching response body: context canceled category="Response:bodySize:fetchBody" elapsed="0 ms" goroutine=1754
And the complete moc script:
import { SharedArray } from 'k6/data';
import { sleep } from "k6";
import launcher from "k6/x/browser";
import { vu, test } from "k6/execution";
const baseUrl = 'https://MY.DOMAIN.com/pnt_fix_prod/Default.aspx'
const startPages = ['0']
const pages = ['0','searchpage','c1','subl2g0tci1tglh9jo6j29']
const jitter = 10 // 1800 // seconds
const cooldown = '10s'
const duration = 60 // 3600 // seconds
const headless = true
const sod_start = 13*24*60*60*1000+10*60*60*1000 + 50000 // 10:00
const t0 = sod_start
const t1 = t0 + duration*1000 // +1h
const dryrun = false
const vu_reqs = new SharedArray('reqs', function () {
return [
[{"t":9000,"session":"t0_159","islast":false},{"t":27000,"session":"t0_159","islast":false},{"t":35000,"session":"t0_159","islast":false},{"t":46000,"session":"t0_159","islast":false},{"t":60000,"session":"t0_159","islast":false}],
[{"t":58000,"session":"t0_25","islast":false},{"t":62000,"session":"t0_25","islast":false}]
]
})
export let options = {
stages: [
{ target: vu_reqs.length, duration: dryrun ? 1 : jitter + "s" },
{ target: vu_reqs.length, duration: dryrun ? 1 : duration + "s" },
{ target: 0, duration: dryrun ? 1 : cooldown }
],
thresholds: {
"http_req_duration": ["p(95)<500"],
"http_req_duration{staticAsset:yes}": ["p(99)<250"],
},
}
function start(config = {headless: true}) {
const browser = launcher.launch('chromium', config)
const context = browser.newContext()
const page = context.newPage()
return {browser, context, page}
}
function openPage(ctx) {
ctx.page = ctx.context.newPage()
return ctx
}
function setUrl(ctx, url) {
console.log(":: goto: " + url)
ctx.page.goto(url, { waitUntil: 'load' })
}
function gotoPageId(ctx, pageId) {
console.log(":: goto pageid: " + pageId)
sleep(1) // Just for more safety
ctx.page.evaluate((pid) => _W.GoToPageId(pid), pageId)
sleep(1) // Just for more safety
ctx.page.waitForLoadState('load')
}
let trueStartTime = Date.now()
export function setup() {
console.log(":: Running setup")
if(dryrun) console.warn("THIS IS A DRY RUN")
trueStartTime = Date.now()
}
export default function(data) {
if(dryrun) return
let startTime = Date.now()
let vuRampup = jitter - ((startTime - trueStartTime) / 1000)
let counter = 0
let ctx = null
const reqs = vu_reqs[vu.idInTest - 1]
console.log("[" + vu.idInTest + "]" + ':: requests: ' + reqs.length)
const reqsCount = reqs.length
let isClosed = true
for(let i = 0; i < reqsCount; i++ ) {
const req = reqs[i]
console.log("[" + vu.idInTest + "]" + 'request time: ' + req.t)
let now = Date.now()
let t = now - startTime
if((t / 1000) >= vuRampup + duration) {
test.abort("[" + vu.idInTest + "]" + "==> TIME IS UP 1!")
break;
}
if (req.t > t) {
const sleepTime = req.t - t
if(((t + sleepTime) / 1000) >= vuRampup + duration) {
console.log("[" + vu.idInTest + "]" + "==> Test duration is up! Exiting.", t, sleepTime, vuRampup, duration)
break;
}
console.log("[" + vu.idInTest + "]" + ":: sleeping for " + ((req.t - t) / 1000) + "s")
sleep(sleepTime / 1000)
}
try {
if (!ctx) {
console.log("[" + vu.idInTest + "]" + ":: create context")
ctx = start({headless})
setUrl(ctx, baseUrl + '?login=1&pageid=' + startPages[((Math.random() * startPages.length) | 0)]) // Start at start page
isClosed = false
} else {
if (ctx && isClosed) {
console.log("[" + vu.idInTest + "]" + ":: create new page")
ctx = openPage(ctx)
setUrl(ctx, baseUrl + '?login=1&pageid=' + startPages[((Math.random() * startPages.length) | 0)]) // Start at start page
isClosed = false
} else {
let pageId = pages[(Math.random() * pages.length) | 0]
console.log("[" + vu.idInTest + "]" + ":: navigate to " + pageId)
gotoPageId(ctx, pageId) // Go to random page
isClosed = false
}
}
console.log("[" + vu.idInTest + "]" + "=====================> " + (++counter))
} catch (err) {
console.error("[" + vu.idInTest + "]" + ":: ERROR :: " + err)
console.log("[" + vu.idInTest + "]" + ":: closing page")
ctx.page.close()
isClosed = true
if(i === reqsCount - 1) i = -1;
continue;
}
if(req.islast) {
console.log("[" + vu.idInTest + "]" + ":: is last in session, closing page")
if(ctx) {
ctx.page.close()
isClosed = true
}
break;
}
if(i === reqsCount - 1) i = -1;
}
if(ctx) {
if(!ctx.page.isClosed) {
ctx.page.close()
}
if(ctx.browser) {
ctx.browser.close()
ctx.browser = null
}
}
sleep(jitter + duration - ((Date.now() - trueStartTime) / 1000))
if((jitter + duration - ((Date.now() - trueStartTime) / 1000)) <= 0) {
test.abort("[" + vu.idInTest + "]" + "==> TIME IS UP 2!")
}
}
The philosophy we follow is similar to what is explained in 
Thanks for the example!
Could you check?