Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cannot read property 'timings' of undefined #2290

Closed
donwalling opened this Issue Feb 5, 2019 · 26 comments

Comments

Projects
None yet
2 participants
@donwalling
Copy link

donwalling commented Feb 5, 2019

We're getting an error on a complicated script only when -n is greater than 1. With -n 1 the script appears to work and the output html reports look good.

2019-02-05 18:21:53] ERROR: [sitespeedio.queuehandler] TypeError: Cannot read property 'timings' of undefined
at addExtraFieldsToHar (/usr/src/app/node_modules/browsertime/lib/core/engine/index.js:70:27)
at Engine.runByScript (/usr/src/app/node_modules/browsertime/lib/core/engine/index.js:164:7)

Not exactly sure what the problem is, still trying to prune it down to an example we can share publicly.
The docker command being used is:

docker run --shm-size=1g --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io:8.2.2 --multi --spa -n 2 -v urt1.js

where urt1.js consists of (all commands are shown, but non-public parameters are omitted)

module.exports = async function(context, commands) {
    await commands.measure.start('https://internal-host.com');

    await commands.measure.start('navigate_to_login');
    await commands.click.byClassNameAndWait('my-login-button-classname');
    await commands.measure.stop();

    await commands.measure.start('do_login');
    await commands.addText.byXpath('username,'.//a-real-xpath');
    await commands.addText.byXpath('password','.//a-real-xpath');
    await commands.click.byId('sign_in');
    await commands.wait.byXpath('.//a-real-xpath-to-something-that-appears-after-login', 20000);
    return commands.measure.stop();
}

Is there anything suspicious about this general sequence of commands?
Thanks,
Don

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 5, 2019

Hi Don, the code looks good. Can you see that the script works (the click works etc) either by running it locally without Docker or using --browsertime.videoParams.debug to get the full video of the run?

It looks like it could be a bug with runs/pages tested, if you test -n 1 does it work? I'll look into the Browsertime code that gets the error and try to figure out whats going in.

Best
Peter

@soulgalore soulgalore self-assigned this Feb 5, 2019

@soulgalore soulgalore added the bug label Feb 5, 2019

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 5, 2019

yes, -n 1 works well. I'll try various debugging on my side and post findings as they come

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 5, 2019

I could see that one fix unintentionally changed how we add metrics. I'll fix that ASAP but it has nothing do with that error you get.

When you login, does it generate a new page load?

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 5, 2019

Ok, I've fixed what I found was wrong in sitespeedio/browsertime#760 but need to test it some more before I push it, I'll do that first thing tomorrow. I'll add a guard also before the next release so at least we don't get that un catched error, its better to catch it where it happens.

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 5, 2019

@soulgalore actually, yes, that's a good point. Clicking the sign_in will cause a redirect, which a new page load. We'd like for sitespeed to capture the activity from button click through the redirect if possible. Is there a different approach we should be taking?

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 6, 2019

I've verified that "-n 1" works fine, and "-n 2" appears to work fine (the browsertime.videoParams.debug video for both runs indicates it was successful) but the html reports are only partially generated.

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 6, 2019

@soulgalore I have a test case that I can share outside the company, but can't post publicly. Is there a way to send you a file?

I did some really crude console debugging

index 28ea0a6..f08a08d 100644
--- a/lib/core/engine/index.js
+++ b/lib/core/engine/index.js
@@ -56,12 +56,23 @@ function addExtraFieldsToHar(totalResults, har, options) {
       }
     } else {
       for (let harPage of har.log.pages) {
+        log.info('harPage: ' + harPage);
         let pageNumber = harPageNumber % totalResults.length;
+        log.info(
+          'pageNumber: ' +
+            pageNumber +
+            ' ' +
+            harPageNumber +
+            ' ' +
+            totalResults.length
+        );
         for (let iteration = 0; iteration < options.iterations; iteration++) {
+          log.info('iteration: ' + iteration);
           const visualMetric =
             totalResults[pageNumber].visualMetrics[iteration];
           const browserScript =
             totalResults[pageNumber].browserScripts[iteration];
+          log.info('browserScript: ' + browserScript);
           const cpu = totalResults[pageNumber].cpu[iteration];
           harUtil.addExtrasToHAR(
             harPageNumber,

with n = 1

[2019-02-05 17:05:25] INFO: harPage: [object Object]
[2019-02-05 17:05:25] INFO: pageNumber: 0 0 3
[2019-02-05 17:05:25] INFO: iteration: 0
[2019-02-05 17:05:25] INFO: browserScript: [object Object]
[2019-02-05 17:05:25] INFO: harPage: [object Object]
[2019-02-05 17:05:25] INFO: pageNumber: 1 1 3
[2019-02-05 17:05:25] INFO: iteration: 0
[2019-02-05 17:05:25] INFO: browserScript: [object Object]
[2019-02-05 17:05:25] INFO: harPage: [object Object]
[2019-02-05 17:05:25] INFO: pageNumber: 2 2 3
[2019-02-05 17:05:25] INFO: iteration: 0
[2019-02-05 17:05:25] INFO: browserScript: [object Object]

with n = 2

[2019-02-05 17:06:38] INFO: harPage: [object Object]
[2019-02-05 17:06:38] INFO: pageNumber: 0 0 5
[2019-02-05 17:06:38] INFO: iteration: 0
[2019-02-05 17:06:38] INFO: browserScript: [object Object]
[2019-02-05 17:06:38] INFO: iteration: 1
[2019-02-05 17:06:38] INFO: browserScript: [object Object]
[2019-02-05 17:06:38] INFO: harPage: [object Object]
[2019-02-05 17:06:38] INFO: pageNumber: 1 1 5
[2019-02-05 17:06:38] INFO: iteration: 0
[2019-02-05 17:06:38] INFO: browserScript: [object Object]
[2019-02-05 17:06:38] INFO: iteration: 1
[2019-02-05 17:06:38] INFO: browserScript: undefined
[2019-02-05 17:06:38] ERROR: TypeError: Cannot read property 'timings' of undefined

seems like the indexing isn't quite right, but i haven't figure out the flaw. When n = 2, shouldn't the totalResults.length be 6 (2 x 3)?
Happy to help debug further if you have a suggestion
Don

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 6, 2019

Yeah that's wrong, you are right, I hopefully fixed it in sitespeedio/browsertime#760 merge and push forward today.

You can email me: peter [AT] soulgalore [dot] com

Best
Peter

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 6, 2019

Clicking the sign_in will cause a redirect, which a new page load. We'd like for sitespeed to capture the activity from button click through the redirect if possible. Is there a different approach we should be taking?

No that should work just fine.

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 6, 2019

FYI: I've pushed the change to the tests for dashboard.sitespeed.io, if it works fine I'll push it in a couple of hours.

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 6, 2019

Released 8.2.3. If it doesn't work for you, please email the use case and I'll fix it!

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 6, 2019

@soulgalore unfortunately

docker run --shm-size=1g --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io:8.2.3 --browsertime.videoParams.debug --multi --spa -n 2 urt1.js

still produces

[2019-02-06 15:21:27] ERROR: TypeError: Cannot read property 'timings' of undefined
    at addExtraFieldsToHar (/usr/src/app/node_modules/browsertime/lib/core/engine/index.js:71:27)
    at Engine.runByScript (/usr/src/app/node_modules/browsertime/lib/core/engine/index.js:164:7)

I'll email you the test case in a few minutes
Thanks,
Don

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 6, 2019

Yep cool, I'll have a look asap.

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 7, 2019

@donwalling let me know when you sent it :)

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 7, 2019

Hi @soulgalore I sent it from my company's email yesterday Wed 2/6/2019 7:35 AM PST (UTC-8). If you don't yet have it, I'll try gmail or linked in

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 7, 2019

Hi @soulgalore I've sent it from linkedin and gmail. I suspect that the js attachment caused the emails to be blocked, so the message i sent from gmail has the info all in-line. Please let me know if you receive it

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 7, 2019

Got it now, thanks @donwalling , will have a look asap later today.

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 7, 2019

@donwalling so I have happy news and I have ... happy news :) I've fixed the problem I Browsertime, but it's a hack so I need some more time to polish it before I push it.

First the problem:
When the user got logged in, you got different redirect URLs each time (one of the parameter values changes) and collecting the metrics used the full URL as a key, so for each login there was a new page created in the result set.

The fix:
I've changed that so if you use an alias for an URL, the alias is used instead of the URL. For this to work, I also needed to change the path to the stored metrics on disk, so it uses alias instead of the URL. But that is cool, since it also will solve #2295 and also makes it possible to create direkt links from Grafana back to the result (if you use an alias, that wasn't possible before).

Let me spend some more time without tonight and I could probably push a new release of Browsertime and then roll it out on dashboard.sitespeed.io before I go to sleep, for an release sometimes tomorrow.

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 7, 2019

I was a bit optimistic with pushing it to sitespeed.io tomorrow. I've got a branch now where it works in Browsertime but integrating it with sitespeed.io will mean some work so I need to do that this weekend. Since we today only use the URL when storing data, adding alias will need some extra work and testing (and I don't know the best way forward so need some time to think).

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 7, 2019

@soulgalore Thanks for the update - it is great news that you can reproduce the problem and are thinking about how to fix. We'll watch for updates, and if I can help in some way just let me know.

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 8, 2019

@donwalling if you have time to try it our before I do the new release it would be great:
sitespeedio / sitespeed.io-autobuild:latest have the latest change.

It was annoying: I spent hours yesterday trying to fix it all by changing so we also use the alias when we store files ... it was to much work and need to come in next major if we wanna do it. Instead I spent 15 min today to make sure that if an alias have multiple URLs, we just bind alias to the first used URL :) It works for me with your use case (did some slightly modification since I get redirected to the Swedish version of the site) and I hope it will work out for you!

Best
Peter

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 8, 2019

Hi @soulgalore I just did a quick test from my laptop at home and got a different exception:
[2019-02-08 14:54:49] ERROR: TypeError: Cannot read property 'time' of undefined
at Object.getFilmstrip (/usr/src/app/lib/plugins/html/filmstrip.js:133:43)

The command I'm using is
docker run --shm-size=1g --rm -v "$(pwd)":/sitespeed.io sitespeedio/sitespeed.io-autobuild:latest --browsertime.videoParams.debug --multi --spa -n 2 urt1-ss.js

where urt1-ss.js is the file I previously emailed except uses my credentials and the US site. I'll recheck once I get to the office, but I wouldn't expect a different result.

Don

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 8, 2019

Let me fix that. When you run with --browsertime.videoParams.debug you are actually disabling visual metrics and it looks like there's some code in the filmstrip that doesn't handle that too well. Try without that setting first.

Best
Peter

@soulgalore

This comment has been minimized.

Copy link
Member

soulgalore commented Feb 8, 2019

I've pushed a change but there's a couple of more things to fix there. But to be clear: --browsertime.videoParams.debug is meant to be used to collect the full video of the full flow so you don't need to connect vnc etc to the container to see what happens. Metrics will not work when you run like that. I'll update the docs later on.

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 8, 2019

@soulgalore ah, right, I sortof knew that but it's too early in the morning :-) Yes, running without video debug works fine, and the reports look reasonable. I'll dig into a further review when I get to the office, but as far as I can tell it is working well now.

@donwalling

This comment has been minimized.

Copy link
Author

donwalling commented Feb 11, 2019

@soulgalore 8.3.0 is working well for us. I think this can be closed - WDYT?

@donwalling donwalling closed this Feb 11, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.