Scripted test throwing RangeError: Invalid Time Value

Your question

Opening this issue as requested in #4124 regarding the RangeError I am experiencing.

Upon further testing, this issue is not occurring consistently and is not limited to tests with multiple iterations. Even with a single iteration of the test, there are cases when the test completes successfully and cases when this RangeError occurs.

Case 1: Test completes successfully (errors in log)

{
    "status": "completed",
    "logs": [
        ""[2024-07-29 18:28:46] INFO: Versions OS: linux 5.15.0-1058-aws nodejs: v20.9.0 sitespeed.io: 34.4.0 browsertime: 22.5.5 coach: 8.0.2
",
        "[2024-07-29 18:28:47] INFO: Changing network interfaces needs sudo rights. Setting connectivity profile custom
",
        "[2024-07-29 18:28:47] INFO: Running tests using Chrome - 1 iteration(s)
",
        "[2024-07-29 18:28:48] INFO: Navigating to url https://<FILLER>/login.do?method=POST&user_name=cqe.admin&user_password=Snow2016$&sys_action=sysverb_login&sysparm_goto_url=/now/nav/ui/home iteration 1
",
        "[2024-07-29 18:29:06] INFO: Start to measure Click 1st INC First View
",
        "[2024-07-29 18:29:17] INFO: Take after page complete check screenshot
",
        "[2024-07-29 18:29:18] INFO: Take cumulative layout shift screenshot
",
        "[2024-07-29 18:29:19] INFO: Take largest contentful paint screenshot
",
        "[2024-07-29 18:29:19] INFO: No element attached to the entry in largest-contentful-paint
",
        "[2024-07-29 18:29:21] INFO: Navigating to url about:blank iteration 1
",
        "[2024-07-29 18:29:27] INFO: Navigating to url https://<FILLER>/now/nav/ui/home iteration 1
",
        "[2024-07-29 18:29:44] INFO: Start to measure Click 1st INC Repeat View
",
        "[2024-07-29 18:29:50] INFO: https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber has been tested before within the same run, it will get an extra query parameter named browsertime_run. Make sure to use alias to keep track of the URLs
",
        "[2024-07-29 18:29:55] INFO: Take after page complete check screenshot
",
        "[2024-07-29 18:29:56] INFO: Take cumulative layout shift screenshot
",
        "[2024-07-29 18:29:57] INFO: Take largest contentful paint screenshot
",
        "[2024-07-29 18:29:57] INFO: No element attached to the entry in largest-contentful-paint
",
        "[2024-07-29 18:30:01] INFO: Use the visual metrics portable script
",
        "[2024-07-29 18:30:01] INFO: Get visual metrics from the video
",
        "[2024-07-29 18:30:07] INFO: Use the visual metrics portable script
",
        "[2024-07-29 18:30:07] INFO: Get visual metrics from the video
",
        "[2024-07-29 18:30:12] ERROR: Could not add fullyLoaded metric to URL undefined, we have statistic for the URLs ["https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber","https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber?browsertime_run=2"] 
",
        "[2024-07-29 18:30:12] ERROR: Could not add fullyLoaded metric to URL undefined, we have statistic for the URLs ["https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber","https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber?browsertime_run=2"] 
",
        "[2024-07-29 18:30:12] INFO: https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber 24 requests, TTFB: 1.24s, firstPaint: 2.75s, firstVisualChange: 217ms, FCP: 2.75s, DOMContentLoaded: 2.21s, LCP: 5.85s, CLS: 0.0515, TBT: 660ms, CPUBenchmark: 82ms, Load: 2.21s, speedIndex: 726ms, visualComplete85: 934ms, lastVisualChange: 1.97s
",
        "[2024-07-29 18:30:12] INFO: https://<FILLER>/now/nav/ui/classic/params/target/incident.do%3Fsys_id%3D57af7aec73d423002728660c4cf6a71c%26sysparm_record_target%3Dincident%26sysparm_record_row%3D1%26sysparm_record_rows%3D67%26sysparm_record_list%3DORDERBYDESCnumber?browsertime_run=2 7 requests, TTFB: 148ms, firstPaint: 735ms, firstVisualChange: 100ms, FCP: 1.40s, DOMContentLoaded: 850ms, LCP: 4.28s, CLS: 0.0308, TBT: 412ms, CPUBenchmark: 84ms, Load: 851ms, speedIndex: 660ms, visualComplete85: 633ms, lastVisualChange: 1.52s
",
        "[2024-07-29 18:30:15] INFO: HTML stored in /home/ubuntu/onlinetest/testrunner/sitespeed-result/debug/2024-07-29-18-28-46
",
        "[2024-07-29 18:30:15] INFO: Uploading /home/ubuntu/onlinetest/testrunner/sitespeed-result/debug/2024-07-29-18-28-46 to S3 bucket sitespeedio, this can take a while ...
",
        "[2024-07-29 18:30:16] INFO: Finished upload to S3
",
        "[2024-07-29 18:30:16] INFO: Find the result at https://<FILLER>/result/sitespeedio/debug/2024-07-29-18-28-46/index.html
"
    ],
    "url": "https://www.wikipedia.org",
    "scriptingName": "Click_1st_INC",
    "message": "Job completed.",
    "result": "https://<FILLER>/result/sitespeedio/debug/2024-07-29-18-28-46/index.html"
}

In this case, a chrome trace log is generated but all the result HTML and final output seems correct.

Case 2: Test fails with RangeError, no trace log generated

{
    "status": "failed",
    "logs": [
        "[2024-07-29 18:33:54] INFO: Versions OS: linux 5.15.0-1058-aws nodejs: v20.9.0 sitespeed.io: 34.4.0 browsertime: 22.5.5 coach: 8.0.2
",
        "[2024-07-29 18:33:54] INFO: Changing network interfaces needs sudo rights. Setting connectivity profile custom
",
        "[2024-07-29 18:33:54] INFO: Running tests using Chrome - 1 iteration(s)
",
        "[2024-07-29 18:33:55] INFO: Navigating to url https://<FILLER>/login.do?method=POST&user_name=cqe.admin&user_password=Snow2016$&sys_action=sysverb_login&sysparm_goto_url=/now/nav/ui/home iteration 1
",
        "[2024-07-29 18:34:12] INFO: Start to measure Click 1st INC First View
",
        "[2024-07-29 18:34:23] INFO: Mark run as failure with message: Invalid time value
",
        "[2024-07-29 18:34:23] ERROR: RangeError: Invalid time value
    at Date.toISOString (<anonymous>)
    at m.toISOString (/home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/chrome-har/node_modules/dayjs/dayjs.min.js:1:6270)
    at module.exports (/home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/chrome-har/lib/entryFromResponse.js:189:53)
    at harFromMessages (/home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/chrome-har/index.js:410:15)
    at getHar (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/browsertime/lib/chrome/har.js:35:15)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Chromium.afterPageCompleteCheck (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/browsertime/lib/chrome/webdriver/chromium.js:288:9)
    at async Measure.stop (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/browsertime/lib/core/engine/command/measure.js:440:17)
    at async default (file:///home/ubuntu/default/58b82c37-cd81-41b6-b235-327ce291a819/Click_1st_INC.mjs:8:5)
    at async file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/browsertime/lib/core/engine/run.js:4:7
    at async Iteration.run (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/browsertime/lib/core/engine/iteration.js:162:9)
    at async Engine.runByScript (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/browsertime/lib/core/engine/index.js:308:20)
    at async analyzeUrl (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/plugins/browsertime/analyzer.js:202:12)
    at async BrowsertimePlugin.processMessage (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/plugins/browsertime/index.js:173:26)
",
        "[2024-07-29 18:34:23] ERROR: No data to collect
",
        "[2024-07-29 18:34:24] ERROR: Caught error from Browsertime TypeError: Cannot read properties of undefined (reading 'alias')
    at BrowsertimePlugin.processMessage (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/plugins/browsertime/index.js:186:40)
",
        "[2024-07-29 18:34:24] ERROR: TypeError: Cannot read properties of null (reading 'split')
    at pathToFolder (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/core/resultsStorage/pathToFolder.js:20:49)
    at Object.relativeSummaryPageUrl (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/core/resultsStorage/resultUrls.js:29:14)
    at DataCollector._addUrl (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/plugins/html/dataCollector.js:20:31)
    at DataCollector.addErrorForUrl (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/plugins/html/dataCollector.js:92:10)
    at HTMLPlugin.processMessage (file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/plugins/html/index.js:59:27)
    at file:///home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/lib/core/queueHandler.js:228:32
    at drainItem (/home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/concurrent-queue/index.js:96:21)
    at Immediate.drain [as _onImmediate] (/home/ubuntu/.nvm/versions/node/v20.9.0/lib/node_modules/sitespeed.io/node_modules/concurrent-queue/index.js:77:84)
    at process.processImmediate (node:internal/timers:478:21)
",
        "[2024-07-29 18:34:24] INFO: HTML stored in /home/ubuntu/onlinetest/testrunner/sitespeed-result/debug/2024-07-29-18-33-54
",
        "[2024-07-29 18:34:24] INFO: Uploading /home/ubuntu/onlinetest/testrunner/sitespeed-result/debug/2024-07-29-18-33-54 to S3 bucket sitespeedio, this can take a while ...
",
        "[2024-07-29 18:34:24] INFO: Finished upload to S3
",
        "[2024-07-29 18:34:24] INFO: Find the result at https://<FILLER>/result/sitespeedio/debug/2024-07-29-18-33-54/index.html
",
        "Job failed:sitespeed.io exited with a failure exit code 1"
    ],
    "url": "https://www.wikipedia.org",
    "scriptingName": "Click_1st_INC",
    "message": "Test 58b82c37-cd81-41b6-b235-327ce291a819 failed.",
    "result": ""
}

This test does not generate the chromePerflog.json.gz file at all within the results.

Both tests were run through the Onlinetest testing framework for sitespeed.io with the exact same command-line options and --browsertime.chrome.collectPerfLog true set for both cases to generate chrome perf logs.

Reproduce the failure with the reported sitespeed.io 34.4.0, Browsertime 22.5.5, Node.js 20.9.0 command and chrome perf-log option. Start at chrome-har/lib/entryFromResponse.js:189 and trace the call through browsertime/lib/chrome/har.js and Chromium.afterPageCompleteCheck. Done means the intermittent Invalid Time Value no longer aborts the run and the expected chromePerflog.json.gz and result output are produced.