toWarnInDev matcher; throw on unexpected console.error #11786

bvaughn · 2017-12-06T16:50:44Z

Relates to #11626.

Added a new matcher for dev errors and warnings. Rather than checking for warnings like this:

spyOnDev(console, 'error');

// Some code

if (__DEV__) {
  expect(console.error.calls.count()).toBe(2);
  expect(console.error.calls.argsFor(0)[0]).toContain('Some error');
  expect(console.error.calls.argsFor(1)[0]).toContain('Some other error');
}

You can now write this:

expect(() => {
  // Some code
}).toWarnDev([
  'Some error',
  'Some other error',
]);

In addition to being syntactically shorter, I've also changed our default console overrides to report the correct call-stack for unexpected warnings. The combination of these two changes provides a couple of benefits:

Warnings being verified are now explicitly scoped to a block of code.
Any warnings that happen outside of this scope are guaranteed to fail the test, unlike before where a forgotten assertion on calls.count() could result in suppressed/ignored warnings.
Unexpected warnings show the correct call stack (making them easier to identify and correct or add tests for).
Error stack normalization logic is now centralized (rather than copy-pasting it around each test that depends on it).

I've updated a dozen or so tests to use the new matcher, to make sure it works correctly. There are still several more with console spies that I can remove via follow-up PRs.

Follow Up Work

Update the matcher to catch all Errors and re-throw as JestAssertionErrors for better stack traces (once Expose JestAssertionError to custom matchers jestjs/jest#5138 is released).
Update remaining tests that spy on console to use the new matcher.
Update our spyOn helpers to detect if they're being used to spy on console redirect to use the new matcher instead. (See PR Fixed potential false-positive in toWarnDev matcher #11898 for a possible implementation.)
Decide whether to (continue to) support nested toWarnDev matchers or whether to throw an error if this pattern is detected.

Expected failures

Unexpected warnings

it('should fail for unexpected warnings(s)', () => {
  const foo = () => bar();
  const bar = () => baz();
  const baz = () => console.error('unexpected warning');

  foo();
});

Unexpected warnings within a `try`/`catch`

it('should fail for unexpected warnings(s) within a try/catch', () => {
  const foo = () => bar();
  const bar = () => baz();
  const baz = () => console.error('unexpected warning');

  try {
    foo();
    console.error('another unexpected warning');
  } catch (err) {}
});

Errors thrown within `toWarnDev`

it('should fail for errors thrown within .toWarnDev()', () => {
  expect(() => {
    asdf();
  }).toWarnDev('foo')
});

Invalid `toThrow` within `toWarnDev`

it('should fail .toThrow() within .toWarnDev()', () => {
  expect(() => {
    console.error('foo');
    expect(() => {}).toThrow();
  }).toWarnDev('foo');
});

Passing `toWarnDev` within `toThrow`

it('should fail .toWarnDev() within .toThrow()', () => {
  expect(() => {
    expect(() => console.error('foo')).toWarnDev('foo')
  }).toThrow();
});

Incorrect/non-matching warning

it('should fail when the expected warnings passed to .toWarnDev() do not match the actual warnings', () => {
  expect(() => {
    console.error('foo');
  }).toWarnDev('bar');
});

Passing tests

Nested `toThrow` within `toWarnDev`

it('should pass .toThrow() within .toWarnDev()', () => {
  expect(() => {
    console.error('foo');
    expect(() => asdf()).toThrow();
  }).toWarnDev('foo');
});

Nested `toWarnDev` within `toThrow`

it('should pass .toWarnDev() within .toThrow()', () => {
  expect(() => {
    expect(() => {}).toWarnDev('foo')
  }).toThrow();
});

Open Questions

Nested warnings

expect(() => {
  console.error('foo');
  expect(() => {
    console.error('baz');
    console.error('qux');
  }).toWarnDev([
    'baz',
    'qux',
  ]);
  console.error('bar');
}).toWarnDev([
  'foo',
  'bar',
]);

This is currently supported, although it's unclear if this is a case we would ever actually need or want to use. Once we've migrated the current warning tests over to use this new matcher, if we determine that we don't need to support nesting, we can change it to fail explicitly.

thymikee · 2017-12-07T16:06:35Z

scripts/jest/matchers/toWarnDev.js

+  if (__DEV__) {
+    if (typeof expectedWarnings === 'string') {
+      expectedWarnings = [expectedWarnings];
+    } else if (!Array.isArray(expectedWarnings)) {


@bvaughn Are you planning on using Flow inside tests at some point? If so, you could get rid of these checks.

True.

And no idea. 😄

gaearon · 2017-12-07T19:32:15Z

packages/react/src/__tests__/ReactElementValidator-test.js

+    ]);
+
+    // Should not log any additional warnings
+    expect(() => React.createElement('div')).toWarnDev([]);


Is this necessary? Shouldn’t an unexpected log fail the test anyway? I expect that if we explicitly mark each warning block then any warning outside should be a failure. Maybe even immediately when it’s called rather than at the end of the test.

Shouldn’t an unexpected log fail the test anyway

Good point.

Now that I look at this again, I believe this explicit check is necessary since we've necessarily spied on console.error in order for the matcher to work.

IIR, I originally tried to clear the spy at the end of the matcher, so unexpected errors/warnings would cause an error, but neither the version of Jest we're using (21.3.0-beta.4) nor the latest release (22) actually expose the spy.mockReset method the docs mention.

We could call spy.and.callThrough() at the bounds of the matcher, so that errors were actually passed through, but (a) that could negatively affect tests with multiple .toWarnDev calls and (b) this wouldn't actually fail the test, only print the red text to the console.

Maybe I'm overlooking something?

Now that I look at this again, I believe this explicit check is necessary since we've necessarily spied on console.error in order for the matcher to work.

Wouldn't this approach solve it? #11786 (comment)

IIR, I originally tried to clear the spy at the end of the matcher, so unexpected errors/warnings would cause an error

I don't quite understand what clearing means in this context, or why it would be helpful.

My proposal would be to set up a mock when we enter toWarn and tear it down when we exit it. Outside of toWarn, I'd want console.error to be replaced with a function that insta-throws.

I think we're saying the same thing, but misunderstanding each other.

My initial design for this matcher was to setup a spy/mock when entering and then remove it before exiting. This way unexpected console.error calls would fail the test (as they do if you don't spy in the first place). The Jest docs suggest this should be possible via a mockReset method, but that method doesn't actually exist (in Jest 21 or 22) so I'm not sure why the docs mention it. The problem then, is that once we've spied on console.error initially, we can't remove that spy and so any unexpected calls to it don't actually cause failures.

We could work around this in other ways. For example, I could not use Jest's spyOn functionality at all- but just override console.error with my own function and then restore the originally one before exiting. Maybe that's best anyway?

(My initial comment didn't make sense so I edited it)

Ah! I think I understand what you're saying better now.

The boundary is clearer with the new API. Before the boundary was more informal, between spyOn and the first (...calls.length).toBe() check.

It was still possible to do the throw-immediate thing before though. That's what confused me a bit.

I guess it was also easier for the old spies to miss things if warnings were logged after the last count check too. That's another advantage of this boundary.

It was still possible to do the throw-immediate thing before though

How would it work with this test case?

spyOnDev(console, 'error') console.error('unexpected warning') console.error('expected warning') expect(console.error.calls.count).toBe(1) expect(console.error.calls.argsFor(0)[0]).toBe('expected warning')

Previously we couldn't safely throw on the first console.error because we didn't know its message is unexpected by the time it ran.

But with toWarn we can because we know the exhaustive list of expected messages (and their count) before console.error is called.

Thus we'll get a full stack trace to the place where the message actually fired, as opposed to our check. And less code would run (which aids debugging).

It just occurred to me coming back from lunch that, since I know the error message(s) ahead of time, I could also throw immediately (within my fake spy) any time a message is logged that isn't expected.

I'll rework the matcher to behave this way instead.

gaearon · 2017-12-07T19:33:47Z

packages/react/src/__tests__/ReactElementValidator-test.js

@@ -317,6 +270,8 @@ describe('ReactElementValidator', () => {
        'or a class/function (for composite components) but got: null.' +
        (__DEV__ ? '\n\nCheck the render method of `ParentComp`.' : ''),
    );
+
+    // We can't use .toWarnDev() here because we can't chain it with .toThrowError()
    if (__DEV__) {


Let’s bite the bullet and nest assertions?

I'm not sure what you have in mind here. Mind giving a faux code example?

expect(() => { expect(() => { }).toWarnInDev() }).toThrowError('message')

Although there's a hazard of not specifying the message and thus catching a failure from the inner expect.

Maybe nesting them the other way around would work.

Nesting toWarnDev inside of toThrowError won't work. Failures in the toWarnDev assertion are silent. But nesting it the other way around (toThrowError inside) does seem to work.

gaearon · 2017-12-07T19:34:30Z

packages/react/src/__tests__/ReactElementValidator-test.js

+    ]);
+
+    // Should not error for strings
+    expect(() => {


Same; I would expect any warning that isn’t inside a protected block to fail immediately.

I think this was just me being silly.

To be clear, I expect that with current infra it fails at the end of the test.

However, I propose that toWarnInDev acts as a boundary, and we change console.error/console.warn to immediately throw outside of that boundary. This way we get the error immediately at the right call site instead of at the end of the test.

…nexpected console.error/warn calls will fail tests.

…ed on)

bvaughn · 2017-12-19T01:31:45Z

I've refactored this to fail faster for unexpected warnings. I also added some syntax snippets to the description.

Still need to look into the following:

Do we actually need to support nested warnings? (Probably not.) If not, then we can just error on this case.
Is there a way to get a better error stack for unexpected warnings? Looks like Jest is catching truncating it to just the test where the expectation is defined. I could add the stack to the thrown error message but that seems a little hacky.

bvaughn · 2017-12-19T02:45:07Z

It looks like the stack thing I mentioned is intentional. Jest overrides the "real" stack with one that points to the matcher.

I've posted to the internal Jest group about this and will follow up about it later. For now, I'll just leave a TODO comment.

bvaughn · 2017-12-19T21:38:50Z

I filed a Jest issue (jestjs/jest/issues/5136) and PR (jestjs/jest/pull/5138) for preserving the call stack for errors inside of a custom matcher. I don't think either is a blocker for moving forward with this issue though, so back to you @gaearon 😄

gaearon · 2017-12-19T22:00:39Z

What did we decide about throwing?

We should make sure this fails the test:

try {
  console.error('hi');
} catch (err) { }

bvaughn · 2017-12-19T22:48:58Z

That's a good point, Dan. Using the afterEach to throw, like we did before, obscured the call stack. Throwing synchronously might get swallowed up and suppressed though.

I think the best compromise might be to track call stacks during execution, save them for later, then throw a single error from the afterEach block. This would not prevent the test from continuing to execute (unfortunately, I don't know a way to reliably do that) but it would hopefully simplify the debugging/test-authoring experience.

Maybe I'm overdoing this, but here's a compromise that I think might work? For example, this test:

describe('Example', () => {
  it('should warn about an unexpected log', () => {
    const foo = () => bar();
    const bar = () => baz();
    const baz = () => console.error('unexpected warning');

    foo();
  })

  it('should warn about two unexpected logs', () => {
    const foo = () => bar();
    const bar = () => baz();
    const baz = () => console.error('unexpected warning');

    try {
      foo();
      console.error('another unexpected warning')
    } catch (err) { }
  })
});

Would print the following failures:

bvaughn · 2017-12-19T23:13:21Z

I've pushed a fix for this (as described above) and updated the description of this PR for the various cases I've tested (locally) with this matcher.

gaearon · 2017-12-19T23:28:22Z

I think this makes sense. I'll review this tomorrow.

bvaughn · 2017-12-21T16:17:05Z

Friendly ping 😄

bvaughn · 2017-12-31T23:28:16Z

Another friendly ping

gaearon · 2018-01-02T13:07:15Z

Sorry, I was on holidays!

bvaughn · 2018-01-02T18:00:44Z

Of course! 😄 Was just a reminder for when we both came back.

DavidCurtis321 · 2018-01-02T18:04:30Z

Get Outlook for iOS On Tue, Jan 2, 2018 at 8:08 AM -0500, "Dan Abramov" <notifications@github.com> wrote: Sorry, I was on holidays! — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub, or mute the thread.

bvaughn · 2018-01-02T18:10:43Z

Thanks, but I don't need Outlook 😉

gaearon

LG to me

gaearon · 2018-01-02T18:01:53Z

scripts/jest/matchers/toWarnDev.js

+        }
+
+        // Fail early for unexpected warnings to preserve the call stack.
+        throw Error(`Unexpected warning recorded: "${message}"`);


Can we include the expected next warning message if one exists, in this message?

Otherwise it's a bit confusing that simply having a typo in the expected warning prints a message as if a warning was not expected at all.

Yeah. I like this suggestion.

What do you think about the following change?

To be clearer:

it('should fail when the expected warnings passed to .toWarnDev() do not match the actual warnings', () => { expect(() => { console.error('foo'); }).toWarnDev('bar'); });

gaearon · 2018-01-02T18:12:47Z

scripts/jest/setupTests.js

    console[methodName] = newMethod;

    env.beforeEach(() => {
-      newMethod.__callCount = 0;
+      unexpectedConsoleCallStacks.splice(0);


I always forget what this does. Maybe = [] or .length = 0?

gaearon · 2018-01-02T18:13:49Z

How do you feel about converting other tests as part of this PR? I don't care strongly either way.

bvaughn · 2018-01-02T18:17:36Z

I could do that, although this PR is already pretty big. I stopped converting because I was getting increasing concerned about merge conflicts. 😄 I'd be happy to do a follow up PR or two quickly after merging this.

I'm willing to do it all as part of this PR too though if you have a preference.

gaearon · 2018-01-02T18:21:34Z

Let's split (as long as both styles keep working and there's no regressions).
But we'll have merge conflicts anyway (since it's likely your PRs will land before any others).

…xpected warning

bvaughn · 2018-01-02T18:51:15Z

True. I was mostly worried about having to deal with merge conflicts myself 😅 I'll cause potential conflicts for others no matter what I do.

I've merged master into this branch and addressed your 2 comments above. Once CI passes, I'll merge this and then continue updating other tests with a follow-up PR.

gaearon · 2018-01-02T18:56:47Z

As a stretch goal it’d be nice to highlight the text difference on a character level. I often make small tweaks and then it’s super annoying to stare into the message trying to figure out where exactly the different lies (and which one is right).

bvaughn · 2018-01-02T19:01:08Z

Yeah, I briefly considered doing this, using jest-diff, but the differences are too big. For examples, there's a "Warning:" prefix that may not be there, and there's the component stack that may be different - neither of which are actually important in the context of the test in many cases.

~~Maybe we could do some kind of minimum-edit-distance calculation to narrow down the area to diff?~~

Edit: I think jest-diff just isn't the right tool for this and I was over-complicating things. Let me think on this a bit more. I think it should be doable (via a follow-up PR).

* Added toWarnInDev matcher and connected to 1 test * Added .toLowPriorityWarnDev() matcher * Reply Jest spy with custom spy. Unregister spy after toWarnDev() so unexpected console.error/warn calls will fail tests. * console warn/error throws immediately in tests by default (if not spied on) * Pass-thru console message before erroring to make it easier to identify * More robustly handle unexpected warnings within try/catch * Error message includes remaining expected warnings in addition to unexpected warning

While writing tests for unsafe async warnings, I noticed that in certain cases, errors were swallowed by the toWarnDev matcher and resulted in confusing test failures. For example, if an error prevented the code being tested from logging an expected warning- the test would fail saying that the warning hadn't been logged rather than reporting the unexpected error. I think a better approach for this is to always treat caught errors as the highest-priority reason for failing a test. I reran all of the test cases for this matcher that I originally ran with PR facebook#11786 and ensured they all still pass.

While writing tests for unsafe async warnings, I noticed that in certain cases, errors were swallowed by the toWarnDev matcher and resulted in confusing test failures. For example, if an error prevented the code being tested from logging an expected warning- the test would fail saying that the warning hadn't been logged rather than reporting the unexpected error. I think a better approach for this is to always treat caught errors as the highest-priority reason for failing a test. I reran all of the test cases for this matcher that I originally ran with PR #11786 and ensured they all still pass.

bvaughn added 2 commits December 5, 2017 15:18

Added toWarnInDev matcher and connected to 1 test

f254d9a

Added .toLowPriorityWarnDev() matcher

2cf33eb

bvaughn requested a review from gaearon December 6, 2017 16:50

facebook-github-bot added the CLA Signed label Dec 6, 2017

thymikee reviewed Dec 7, 2017

View reviewed changes

gaearon reviewed Dec 7, 2017

View reviewed changes

bvaughn added 4 commits December 18, 2017 10:19

Merged master

178007e

Nest toThrow and toWarn matchers in ReactElementValidator test

472f5e3

Reply Jest spy with custom spy. Unregister spy after toWarnDev() so u…

d8d0f66

…nexpected console.error/warn calls will fail tests.

console warn/error throws immediately in tests by default (if not spi…

1af3d1e

…ed on)

bvaughn changed the title ~~[WIP] Added toWarnInDev matcher and updated one test to use it~~ [WIP] Added toWarnInDev matcher; throw on console.error/warning call Dec 18, 2017

bvaughn added 2 commits December 18, 2017 12:36

Removed unused oldMethod

e6ff0da

Refactored toWarn matchers to fail faster

0662fd0

Added TODO about Jest overriding error stacks

36c6550

bvaughn changed the title ~~[WIP] Added toWarnInDev matcher; throw on console.error/warning call~~ Added toWarnInDev matcher; throw on console.error/warning call Dec 19, 2017

bvaughn changed the title ~~Added toWarnInDev matcher; throw on console.error/warning call~~ toWarnInDev matcher; throw on unexpected console.error Dec 19, 2017

bvaughn added 4 commits December 18, 2017 19:43

Moved TODO

feac559

Pass-thru console message before erroring to make it easier to identify

47fa899

Updated a few more tests to use toWarnDev matcher

cdb1b50

Added TypeScript test and types, fixed equivalence test

2541749

bvaughn mentioned this pull request Dec 19, 2017

Prevent Error.captureStackTrace from erasing Error stack jestjs/jest#5136

Closed

Upgraded a few additional tests

cdba8b4

More robustly handle unexpected warnings within try/catch

68fc971

bvaughn mentioned this pull request Dec 20, 2017

Fixed potential false-positive in toWarnDev matcher #11898

Merged

gaearon mentioned this pull request Jan 2, 2018

React test suite addition attempt 2 jquense/react-dom-lite#18

Closed

gaearon approved these changes Jan 2, 2018

View reviewed changes

bvaughn added 3 commits January 2, 2018 10:40

Merge branch 'master' into expect-toWarnInDev

1659c93

Replaced .splice(0) with .length=0

62c4b4f

Error message includes remaining expected warnings in addition to une…

b766964

…xpected warning

Removed unnecessary "" around unexpected error message

eeeb0e3

bvaughn merged commit b5334a4 into facebook:master Jan 2, 2018

bvaughn deleted the expect-toWarnInDev branch January 2, 2018 19:06

bvaughn mentioned this pull request Jan 2, 2018

Update additional tests to use .toWarnDev() matcher #11952

Merged

gaearon mentioned this pull request Jan 6, 2018

Add some sugar to simplify test assertions #11626

Closed

bvaughn mentioned this pull request Jan 23, 2018

Improved toWarnDev matcher to avoid swallowing errors #12081

Merged

toWarnInDev matcher; throw on unexpected console.error #11786

toWarnInDev matcher; throw on unexpected console.error #11786

Conversation

bvaughn commented Dec 6, 2017 • edited Loading

Follow Up Work

Expected failures

Unexpected warnings

Unexpected warnings within a try/catch

Errors thrown within toWarnDev

Invalid toThrow within toWarnDev

Passing toWarnDev within toThrow

Incorrect/non-matching warning

Passing tests

Nested toThrow within toWarnDev

Nested toWarnDev within toThrow

Open Questions

Nested warnings

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bvaughn Dec 18, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gaearon Dec 18, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bvaughn Dec 18, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bvaughn commented Dec 19, 2017

bvaughn commented Dec 19, 2017 • edited Loading

bvaughn commented Dec 19, 2017

gaearon commented Dec 19, 2017

bvaughn commented Dec 19, 2017

bvaughn commented Dec 19, 2017

gaearon commented Dec 19, 2017

bvaughn commented Dec 21, 2017

bvaughn commented Dec 31, 2017

gaearon commented Jan 2, 2018

bvaughn commented Jan 2, 2018

DavidCurtis321 commented Jan 2, 2018 via email

bvaughn commented Jan 2, 2018

gaearon left a comment

Choose a reason for hiding this comment

gaearon Jan 2, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gaearon commented Jan 2, 2018

bvaughn commented Jan 2, 2018

gaearon commented Jan 2, 2018 • edited Loading

bvaughn commented Jan 2, 2018

gaearon commented Jan 2, 2018

bvaughn commented Jan 2, 2018 • edited Loading

bvaughn commented Dec 6, 2017 •

edited

Loading

Unexpected warnings within a `try`/`catch`

Errors thrown within `toWarnDev`

Invalid `toThrow` within `toWarnDev`

Passing `toWarnDev` within `toThrow`

Nested `toThrow` within `toWarnDev`

Nested `toWarnDev` within `toThrow`

bvaughn Dec 18, 2017 •

edited

Loading

gaearon Dec 18, 2017 •

edited

Loading

bvaughn Dec 18, 2017 •

edited

Loading

bvaughn commented Dec 19, 2017 •

edited

Loading

gaearon Jan 2, 2018 •

edited

Loading

gaearon commented Jan 2, 2018 •

edited

Loading

bvaughn commented Jan 2, 2018 •

edited

Loading