Proxy and Magical Print

Once upon a time my colleague and I were working on end-to-end tests of one Angular.JS application. We used Node.js v8.9.1. Tests had such workflow:

• open a page;
• click an element;
• check if the page has some content.

As you can see it’s just a regular workflow for end-to-end tests, nothing special. Such tests allow us to reduce the amount of manual testing and eliminate bugs before the code will be delivered to the users. There was a piece of code that makes a screenshot of the page in case of test failure. Such behavior makes it easier to debug tests. The problem was that sometimes a test fails but there was no screenshot.

The code of a test looks like this:

beforeEach(async function () => {
  this.browser = await prepareBrowser();
});

afterEach(async function() => {
  if (this.currentTest.state === 'failed') {
    await this.browser.makeScreenshot();
  }
});

it('likes post', async function() => {
  await this.browser.open('/');
  await this.browser.click('like');
  await this.browser.waitForText('1 like');
});

It uses mocha test runner and this.browser object uses puppeteer under the hood. It was a heisenbug: when I was trying to reproduce it on the local machine a screenshot was always in place. Moreover, after a simple console.log had been added into afterEach block the bug disappeared completely:

afterEach(async function() => {
  console.log(this.browser);
  if (this.currentTest.state === 'failed') {
    await this.browser.makeScreenshot();
  }
});

How is it possible?

To understand it we need to go deeper. There are two sources of errors in this test:

• errors caused by test commands (open, click, waitForText);
• errors caused by the browser (if some script on the page emits an error - the test should fail).

If a test command throws an exception then mocha processes it and fails the test. afterEach block checks that the test has been failed and makes a screenshot. There was such code for the browser object:

// commands directory contains a file per command
// (click, waitForText, makeScreenshot, etc.)
const commands = require('./commands');

const proxyHandler = {
  get(target, property) {
    if (property in commands) {
      return (...args) => {
        target.checkForErrors();
        return commands[property](target, ...args);
      };
    }
    return target[property];
  },
};

class Browser {
  // ....

  checkForErrors() {
    if (this.browserErrors.length > 0) {
      this.browserErrors = [];
      throw new Error('Browser has errors');
    }
  }
}

function prepareBrowser() {
  const browser = new Browser();
  return new Proxy(browser, proxyHandler);
}

Every command is a function stored in a separate file from the commands directory. Commands are connected to the browser object using a proxy mechanism. A proxy is an object which stands in front of the other object and intercepts every property lookup, assignment, and other fundamental operations. Before performing the command proxy checks if there were some errors emitted by the browser and throws an error if required.

Consider the case when “like” button is broken:

• browser.open('/') opens the page;
• browser.click('like') executed successfuly;
• browser.waitForText('1 like') fails;
• browser.makeScreenshot() works as expected.

Consider another case when some script on the page (let it be called script.js) throws an error:

• browser.open('/') opens the page;
• script.js throws an error so browserErrors is not empty;
• browser.click('like') checks browserErrors and throws an error;
• browser.makeScreenshot() works as expected.

Finally, consider the rare case which can be reproduced only on the heavily loaded machine (e.g. CI server running tests of several projects simultaneously): “like” button is broken and script.js throws an error during the execution of browser.waitForText command:

• browser.open('/') opens the page;
• browser.click('like') executed successfully;
• browser.waitForText('1 like') is waiting for the text;
• script.js throws an error so browserErrors is not empty;
• browser.waitForText('1 like') fails;
• browser.makeScreenshot() checks browserErrors and throws an error.

In this case, screenshot is not generated. It’s difficult to predict when script.js will throw an error that is why it was difficult to reproduce the bug. The reason for the bug is found and it can be fixed by removing checking for errors for particular command:

const proxyHandler = {
  get(target, property) {
    if (property in commands) {
      return (...args) => {
        if (!commands[property].skipCheckForErrors) {
          target.checkForErrors();
        }

        return commands[property](target, ...args);
      };
    }
    return target[property];
  },
};

How console.log can influence this situation? Why adding console.log makes makeScreenshot function work as expected? When Node.js prints object it tries to convert it to a string using valueOf method that is why it works so:

• console.log(browser) causes call of browser.valueOf();
• browser.valueOf() intercepted by proxy;
• commands array has valueOf property because of prototype inheritance, so proxy calls checkForErrors, clean up browserErrors and emits an error;
• Node.js supress this error;
• browser.makeScreenshot() works without errors.

To remove such unexpected behavior it’s better to check availability of property in the commands object using Object.keys():

const proxyHandler = {
  get(target, property) {
    if (Object.keys(commands).includes(property)) {
      return (...args) => {
        if (!commands[property].skipCheckForErrors) {
          target.checkForErrors();
        }

        return commands[property](target, ...args);
      };
    }
    return target[property];
  },
};

The behavior of console.log is different in different versions of Node.js. I used such a piece of code to check it:

class Foo {
  constructor() {
    this.a = 'b';
  }
}

const foo = new Foo();

const p = new Proxy(foo, {
  get(obj, prop) {
    console.log(`${prop.toString()} called`);

    return obj[prop];
  }
});

console.log(p);

I got such results:

Coming to the conclusion remember about prototype inheritance checking object’s properties and be cautious with console.log because it can have different behavior for complex structures in different JavaScript engines.