[Phantomas v2] Scope seems to be initialized twice

[gmetais]

Hi Maciej,

I'm seeing an issue when testing any website with phantomas v2. It looks like the process of injecting scope.js files into the browser is done twice.

Here are two extracts of logs when ran with DEBUG=phantomas:scope:log:

  phantomas:scope:log phantomas page scope initialized +0ms
  phantomas:scope:log spy: attaching to "open" function with results reporting +0ms
  phantomas:scope:log Spying disabled - initializing domComplexity metrics +0ms
  phantomas:scope:log Spying enabled +0ms
  phantomas:scope:log Spying disabled - initializing hidden content analysis +1ms
  phantomas:scope:log Spying enabled +0ms
  phantomas:scope:log domQueries: initializing page scope code +0ms
  phantomas:scope:log spy: attaching to "getElementById" function with results reporting +2ms
  phantomas:scope:log spy: attaching to "getElementsByClassName" function with results reporting +0ms

[... and a bit later ...]

  phantomas:scope:log phantomas page scope initialized +324ms
  phantomas:scope:log spy: attaching to "open" function with results reporting +0ms
  phantomas:scope:log Spying disabled - initializing domComplexity metrics +1ms
  phantomas:scope:log Spying enabled +0ms
  phantomas:scope:log Spying disabled - initializing hidden content analysis +0ms
  phantomas:scope:log Spying enabled +0ms
  phantomas:scope:log domQueries: initializing page scope code +0ms
  phantomas:scope:log spy: attaching to "getElementById" function with results reporting +0ms
  phantomas:scope:log spy: attaching to "getElementsByClassName" function with results reporting +2ms

[...]

Maybe I'm wrong, but it looks like the browser starts by opening a blank page. Phantomas injects scope.js in it. Then the real page is open and scope.js is injected a second time.

Side effects: some events such as milestones (domInteractive, domReady, domComplete) are triggered twice. Some reporting functions are called twice too.

[macbre]

$ DEBUG=phantomas:scope:log ./bin/phantomas.js http://0.0.0.0:8888 2>&1 | grep "page scope"
2020-10-07T11:11:28.487Z phantomas:scope:log phantomas page scope initialized
2020-10-07T11:11:28.487Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T11:11:28.490Z phantomas:scope:log domQueries: page scope code initialized

Works fine for me. Can you provide the URL you run phantomas against, @gmetais ? Thanks :slightly_smiling_face:

[gmetais]

I'm testing from the node module like this:

File example.js:

const phantomas = require('./lib/index');

const promise = phantomas('https://www.webpagetest.org/', {
    'analyze-css': true,
    'timeout': 60,
    'wait-for-network-idle': true,
    'phone': true
});

promise.
    then(results => {
        console.log('Metrics', results.getMetrics());
        console.log('Offenders', results.getAllOffenders());
    }).
    catch(res => {
        console.error(res);
    });

When launched with this command: DEBUG=phantomas:scope:log node example.js 2>&1 | grep "page scope"

The result is:

$ DEBUG=phantomas:scope:log node example.js 2>&1 | grep "page scope"
2020-10-07T11:28:39.896Z phantomas:scope:log phantomas page scope initialized
2020-10-07T11:28:39.899Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T11:28:39.901Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T11:28:43.011Z phantomas:scope:log phantomas page scope initialized
2020-10-07T11:28:43.012Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T11:28:43.013Z phantomas:scope:log domQueries: page scope code initialized

Note: there is no redirection on this page.

[macbre]

For me it's even worse :roll_eyes:

$ DEBUG=phantomas:scope:log ./bin/phantomas.js https://www.webpagetest.org/ 2>&1 | grep "page scope"
2020-10-07T13:08:57.848Z phantomas:scope:log phantomas page scope initialized
2020-10-07T13:08:57.851Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T13:08:57.857Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T13:08:58.777Z phantomas:scope:log phantomas page scope initialized
2020-10-07T13:08:58.778Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T13:08:58.779Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T13:08:59.212Z phantomas:scope:log phantomas page scope initialized
2020-10-07T13:08:59.212Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T13:08:59.213Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T13:08:59.302Z phantomas:scope:log phantomas page scope initialized
2020-10-07T13:08:59.302Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T13:08:59.303Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T13:08:59.356Z phantomas:scope:log phantomas page scope initialized
2020-10-07T13:08:59.357Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T13:08:59.357Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T13:08:59.436Z phantomas:scope:log phantomas page scope initialized
2020-10-07T13:08:59.436Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T13:08:59.437Z phantomas:scope:log domQueries: page scope code initialized

[gmetais]

Could it be iframes?

[macbre]

That might be it...

[macbre]

Yes, it is

$ DEBUG=phantomas:scope:log ./bin/phantomas.js http://0.0.0.0:8888/iframe.html 2>&1 | grep "page scope"
2020-10-07T14:15:18.444Z phantomas:scope:log phantomas page scope initialized
2020-10-07T14:15:18.446Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T14:15:18.447Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T14:15:18.472Z phantomas:scope:log phantomas page scope initialized
2020-10-07T14:15:18.473Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T14:15:18.475Z phantomas:scope:log domQueries: page scope code initialized

Then the questions is - is it a bug? :wink:

[macbre]

diff --git a/core/scope.js b/core/scope.js
index 60caa59..4458a45 100644
--- a/core/scope.js
+++ b/core/scope.js
@@ -324,5 +324,5 @@
   phantomas.getDOMPath = getDOMPath;
   phantomas.nodeRunner = nodeRunner;

-  phantomas.log("phantomas page scope initialized");
+  phantomas.log("phantomas page scope initialized (is an iframe: %s)", window.parent == window);
 })(window);

$ DEBUG=phantomas:scope:log ./bin/phantomas.js http://0.0.0.0:8888/iframe.html 2>&1 | grep "page scope"
2020-10-07T14:20:47.350Z phantomas:scope:log phantomas page scope initialized for <http://0.0.0.0:8888/iframe.html> (is an iframe: true)
2020-10-07T14:20:47.351Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T14:20:47.353Z phantomas:scope:log domQueries: page scope code initialized
2020-10-07T14:20:47.373Z phantomas:scope:log phantomas page scope initialized for <http://0.0.0.0:8888/image-scaling.html> (is an iframe: false)
2020-10-07T14:20:47.373Z phantomas:scope:log domQueries: initializing page scope code
2020-10-07T14:20:47.376Z phantomas:scope:log domQueries: page scope code initialized