Open Bug 1446554 Opened 3 years ago Updated 1 year ago

Assert.jsm eagerly JSON.stringifies values (recursively) which triggers undesired behaviour

Categories

(Testing :: General, enhancement, P3)

enhancement

Tracking

(Not tracked)

People

(Reporter: Gijs, Unassigned)

References

Details

Attachments

(1 obsolete file)

If I do something like this:

ChromeUtils.import('resource://gre/modules/Services.jsm');
Assert.equal(Services, Services, "Oh no, Something Strange Happened!");

I would argue it is unexpected behaviour that every single property of `Services` is enumerated and its value evaluated (recursively).

Unfortunately, this is what happened e.g. in bug 1445990 in this bizarre failure:

https://treeherder.mozilla.org/logviewer.html#?job_id=168373528&repo=autoland&lineNumber=1796

[task 2018-03-16T01:37:36.188Z] 01:37:36  WARNING -  TEST-UNEXPECTED-FAIL | js/xpconnect/tests/unit/test_defineModuleGetter.js |  - A promise chain failed to handle a rejection: invalid path component - stack: join@resource://gre/modules/osfile/ospath_unix.jsm:90:13
[task 2018-03-16T01:37:36.188Z] 01:37:36     INFO -  loadBlocklistAsync@jar:jar:file:///data/local/xpcb/target.apk!/assets/omni.ja!/components/nsBlocklistService.js:787:20
[task 2018-03-16T01:37:36.189Z] 01:37:36     INFO -  Blocklist@jar:jar:file:///data/local/xpcb/target.apk!/assets/omni.ja!/components/nsBlocklistService.js:233:5
[task 2018-03-16T01:37:36.189Z] 01:37:36     INFO -  createInstance@resource://gre/modules/XPCOMUtils.jsm:511:19
[task 2018-03-16T01:37:36.189Z] 01:37:36     INFO -  XPCU_serviceLambda@resource://gre/modules/XPCOMUtils.jsm:261:14
[task 2018-03-16T01:37:36.190Z] 01:37:36     INFO -  get@resource://gre/modules/XPCOMUtils.jsm:194:21
[task 2018-03-16T01:37:36.190Z] 01:37:36     INFO -  getMessage@resource://testing-common/Assert.jsm:84:16
[task 2018-03-16T01:37:36.190Z] 01:37:36     INFO -  Assert.AssertionError@resource://testing-common/Assert.jsm:119:18
[task 2018-03-16T01:37:36.191Z] 01:37:36     INFO -  proto.report@resource://testing-common/Assert.jsm:197:13
[task 2018-03-16T01:37:36.191Z] 01:37:36     INFO -  equal@resource://testing-common/Assert.jsm:242:3

So here, the value passed to `equal` is a reference to `Services`. `equal` calls `report`:

  this.report(actual != expected, actual, expected, message, "==");

which does:

proto.report = function(failed, actual, expected, message, operator, truncate = true) {
  let err = new Assert.AssertionError({
    message,
    actual,
    expected,
    operator,
    truncate
  });
  if (!this._reporter) {
    // If no custom reporter is set, throw the error.
    if (failed) {
      throw err;
    }
  } else {
    this._reporter(failed ? err : null, err.message, err.stack);
  }

which then does:

Assert.AssertionError = function(options) {
  this.name = "AssertionError";
  this.actual = options.actual;
  this.expected = options.expected;
  this.operator = options.operator;
  this.message = getMessage(this, options.message, options.truncate);


which then does:


function getMessage(error, prefix = "") {
  let actual, expected;
  // Wrap calls to JSON.stringify in try...catch blocks, as they may throw. If
  // so, fall back to toString().
  try {
    actual = JSON.stringify(error.actual, replacer);
  } catch (ex) {
    actual = Object.prototype.toString.call(error.actual);
  }
  try {
    expected = JSON.stringify(error.expected, replacer);
  } catch (ex) {
    expected = Object.prototype.toString.call(error.expected);
  }
  let message = prefix;
  if (error.operator) {
    let truncateLength = error.truncate ? kTruncateLength : Infinity;
    message += (prefix ? " - " : "") + truncate(actual, truncateLength) + " " +
               error.operator + " " + truncate(expected, truncateLength);
  }
  return message;
}


So, a few things:

1) we shouldn't stringify if there's no `error.operator`, because in any case we will not use the result.

2) arguably, because `report` only uses the message if there's a defined reporter, it's probably not really necessary to have a fully defined message if there isn't one (`report` is the only callsite that constructs one of these things in the file)

3) if the test passes, we shouldn't bother recursively stringifying all the things.

4) if the two values are strictly equal (which isn't the same as (3) because maybe the test passing means the two *aren't* equal), we should only call `stringify` once, as we're guaranteed the same result for JSON.stringify except in pathological cases (e.g. if you pass 2 objects with getters that self-increment).


I wonder, especially on debug builds, how much we could improve test runtime on infra by just making these assertion primitives faster.
See Also: → 1445990
See Also: → 1446558
Priority: -- → P3

Another example here: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236237241&repo=autoland&lineNumber=9874

It turns out that stringifying an nsIFile recurses so deep that it triggers the slow script warning.

To accomplish this I started to keep track of the amount of times the replacer
callback is invoked during a single stringification as a best-effort approximation
of checking when it's reached a resonable limit.
I also started to keep track of which properties of type object we've already seen,
to be able to mark them as circular during the next occurrence. I would have used
a WeakSet if it allowed any object to be used as a key.

Assignee: nobody → mdeboer
Status: NEW → ASSIGNED
Priority: P3 → P2
Assignee: mdeboer → nobody
Status: ASSIGNED → NEW
Priority: P2 → P3
Attachment #9054218 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.