Pipe runtime errors and console logs to browser tests

[rachel-fenichel]

The Problem

Browser tests currently don't catch runtime errors that are piped through the browser console. As a result, we notice the errors that we expect and can assert against, but don't get information about unexpected runtime errors that we are able to work through/around.

Solution

Listen to JS exceptions and JS logs through the Webdriver API.

Additional Information

webdriver vs webdriverio Webdriver is a protocol; webdriverio is a library that makes it easy to use the webdriver protocol.

bidi Webdriverio has some support for the webdriver BiDi protocol.

We may be able to just subscribe to the existing session (with browser.sessionSubscribe) and listen for the correct events.

If all we have to do is subscribe, the question is what strings go into the events array in the sessionSubscribe params. Documentation is thin, so the next step is experimentation and more reading.

If subscribing isn't enough, it's because the session is not set up to run bidirectionally and we need to pass additional parameters to setup. Session setup

Currently we use webdriver through the webdriverio module. It wraps the webdriver module with some helpers for starting a webdriver session. Both of them give back Browser objects, which our tests interact with.

For this use case, the big difference is what options you can pass. WebdriverIO options don't include bidirectionality, which necessary to get errors and logs back.

The selenium bidi example sets up the session as follows:

const firefox = require('selenium-webdriver/firefox');
const LogInspector = require('selenium-webdriver/bidi/logInspector');

// ...

driver = await env
              .builder()
              .setFirefoxOptions(new firefox.Options().enableBidi())
              .build()
        }
// ...
let logEntry = null
            const inspector = await LogInspector(driver)
            await inspector.onJavascriptException(function (log) {
              logEntry = log
            })

[rachel-fenichel]

Looks like this is not currently feasible because webdriver hasn't finished implementing the necessary bidi APIs. They're tracking it here: https://github.com/orgs/SeleniumHQ/projects/6

[rachel-fenichel]

Once https://github.com/google/blockly/pull/7500 is merged we'll be able to get logs and errors.

To enable bidi, add 'webSocketUrl': true, to the capabilities object passed to webdriverio.remote.

To subscribe to logs, add:

  await driver.sessionSubscribe({
    events: ['log.entryAdded']
  })

And here is sample code that forwards warnings and errors to the console, while skipping other messages and a specific set of warnings:

  // Forward errors to the console.
  driver.on('message', function(data) {
    const parsed = JSON.parse(data.toString());
    if (parsed.method == 'log.entryAdded' &&
        (parsed.params.level == 'warn' || parsed.params.level == 'error')) {
      const messageText = parsed.params.text;
      if (!messageText.startsWith('No message string')) {
        console.log(parsed);
      }
    }
  });

[rachel-fenichel]

Some tests have expected warnings. For instance, certain blocks in the Styles section of the test toolbox have bad colors. That results in this warning:

{
  method: 'log.entryAdded',
  params: {
    args: [ [Object], [Object] ],
    level: 'warn',
    method: 'warn',
    source: {
      context: 'EB1934E7875CE7452D6123BBEEF0CDC6',
      realm: '4033625547964839952.6654427252499869672'
    },
    stackTrace: { callFrames: [Array] },
    text: 'Block "test_style_hex5": Illegal colour value:  #NotHex',
    timestamp: 1695072682842,
    type: 'console'
  },
  type: 'event'
}

Other tests may have unexpected warnings or unexpected errors. We may even have expected errors if we're checking whether Blockly can recover correctly from bad inputs.

That means logging all warnings will be spammy and not useful. I propose:

• Attach a logCatcher object to all tests. It can probably be set up in hooks.js.
• The logCatcher contains an array of caught warnings and an array of caught errors.
• The arrays are cleared at the beginning of each test.
• The logCatcher has addExpectedWarning(message, count, exact) and addExpectedError(message, count, exact) methods.
  • message is the expected text.
  • count is the number of times to expect the message.
  • exact is a boolean. If true, the text must match message exactly to be ignored. If false, a substring match is sufficient.
• When a warning or error is caught, the logCatcher checks if the message is expected.
  • If expected, the logCatcher decrements the remaining expected count for that message and is silent.
  • If not expected, the log catcher prints it to the console (for immediate debugging) and saves it to the internal array of caught warnings/errors.
  • At the end of the test, the logCatcher reports the number of caught (unexpected) warnings and errors.
  • If there are any unexpected errors, the test fails.

[BeksOmega]

Overall LGTM!

That means logging all warnings will be spammy and not useful.

Just to clarify the value add, the issue here is that logging all warnings will obfuscate actual warnings we care about?

exact is a boolean. If true, the text must match message exactly to be ignored. If false, a substring match is sufficient.

Can we take in a regexp instead? That is how chai handles this for errors.

At the end of the test, the logCatcher reports the number of caught (unexpected) warnings and errors.

Do we need to report the number if we're also logging to the console and failing on error?

---

If we get don't get the number of errors/warnings that we expect, do we also want to fail the test? I.e. should this also act as an assertion?