This last week I started work again after over a month away. What's the first thing you do when you get back from that long away? Why, upgrade dependencies of course! In particular, this was for my kcd-scripts and paypal-scripts projects. Of note, Rollup, Jest, and lint-staged each received a few nice additions so I was excited to get things going!
For the most part, things went over smoothly. I had a few deprecation warnings with rollup that were simple enough. There was a simple change I needed to make for changes in Jest (which I think I'll be able to revert when this is released).
But then I started updating kcd-scripts in several of my projects. Things were
going great until I updated downshift. I not only updated kcd-scripts, but
also react, and that's when the trouble started. downshifthas several tests
for error cases (errors thrown when validating how you interact with the prop
getters for example). It has some assertions that an error is thrown when doing
something wrong when trying to mount downshift.
This test
in particular resulted in this output:
Error: Uncaught [Error: downshift: You provided the id of "foo" for your input, but the htmlFor of your label is "bar". You must either remove the id from your input or set the htmlFor of the label equal to the input id.]
at reportException (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/helpers/runtime-script-errors.js:66:24)
at invokeEventListeners (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/events/EventTarget-impl.js:209:9)
at HTMLUnknownElementImpl._dispatch (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/events/EventTarget-impl.js:119:9)
at HTMLUnknownElementImpl.dispatchEvent (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/events/EventTarget-impl.js:82:17)
at HTMLUnknownElementImpl.dispatchEvent (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/nodes/HTMLElement-impl.js:30:27)
at HTMLUnknownElement.dispatchEvent (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/generated/EventTarget.js:143:21)
at Object.invokeGuardedCallbackDev (/Users/kdodds/Developer/downshift/node_modules/react-dom/cjs/react-dom.development.js:581:16)
at invokeGuardedCallback (/Users/kdodds/Developer/downshift/node_modules/react-dom/cjs/react-dom.development.js:438:27)
at renderRoot (/Users/kdodds/Developer/downshift/node_modules/react-dom/cjs/react-dom.development.js:10366:7)
...I clipped the output, see this gist for the full output.
The funny thing about this though is that the tests all still passed! In
addition, those logs are coming from a console.error call, and
the top of that file
is mocking console.error to make it not log anything at all!
beforeEach(() => {
jest.spyOn(console, 'error')
console.error.mockImplementation(() => {})
})
afterEach(() => {
console.error.mockRestore()
})
This is how we avoided the noise from React logging the error (which we were expecting) in the first place! Oh, and the error isn't coming from React... Not directly anyway... It's actually coming from JSDOM! Remember that stack trace? The top of it says:
at reportException (/Users/kdodds/Developer/downshift/node_modules/jsdom/lib/jsdom/living/helpers/runtime-script-errors.js:66:24)What do you do when confronted with a stack trace?
When you see a stack trace like this, you first see where things are going wrong in your own code. That might help you know what's going on in your own code to cause the issue and you can fix it. If you can't figure it out from there, then it can be really helpful to follow the stack trace as much as you can. Stepping through a debugger (in browser DevTools for example) is a fantastic way to do this.
So here's where we get spelunking. I knew that my code was fine because it
worked properly before I upgraded my dependencies. So I figured that something
must have changed in my dependencies. So what do we do? Whelp, crack open the
old node_modules directory and see what's up!
Did you know that node_modules directories are mostly full of JavaScript
files? Check this out. Run the following commands and you'll get a report of the
code on the node_modules directory in the downshift project:
git clone https://github.com/downshift-js/downshift.git
cd downshift
npm install
npx cloc ./node_modulesThat'll take a fair amount of time, so I'll save you the trouble:
...
------------------------------------------------
Language files blank comment code
------------------------------------------------
JavaScript 21024 283714 342123 1735415
JSON 2807 1422 0 550205
Markdown 1736 66030 4 168463
TypeScript 1032 17525 56659 127105
HTML 60 2463 40 20773
XML 45 241 13 9377
C/C++ Header 20 1115 325 5571
...I clipped the output because it's so big. See this gist for the full output of the last command.
Wow! Look at all that JavaScript (1.7 MILLION lines of code (excludes
blank lines and comments)... note: this has kcd-scripts which has some heavy
deps but WOW)! And guess what! You can open it up in your editor and make
changes to it! Then you can run your scripts again and they'll pick up your
changes! How cool is that!?
So that's what I did. I jumped into the code and came out with this (spoiler alert): Jest issue #5223: "jsdom console is unmockable".
Here's a TL;DR on the issue:
- React has this really neat file which is responsible for improving browser DevTools experience when "Pause on exceptions" is enabled (read more about the specifics here) (Note, in the Jest issue you'll see I make the claim that React recently added that, but in researching for this newsletter, I found that's not true, it's been around for a LONG time).
- That file creates a temporary DOM node and dispatches an event with your code called in the event handler.
- If your code throws an error (in our case, the error thrown during the
renderfunction ofdownshift), then JSDOM (which is running the event handler) will callreportException. reportExceptionuses aVirtualConsole(remember, it's simulating the browser in Node, so it's doing its best) and emits an event calledjsdomError.- The
VirtualConsoleis setup to handle thejsdomErrorevent to log that to theerrormethod on the console it's using. Check that out here.
Ok, so far so good (hopefully... Stay with me now! Or just skip to the end for
the takeaways). But why in heaven's name is my mocking of the console not
mocking the console that VirtualConsole is using?!
So here's what I did. I noticed that it was using anyConsole.error instead of
console.error. anyConsole is passed into the function where this code lives.
I verified that
sendTo
is passed
console.
Then, to be doubly sure, I changed
this line
to this (added the console.log):
this.on('jsdomError', (e) => {
console.log(anyConsole === console)
anyConsole.error(e.stack, e.detail)
})
Then I ran my tests. I was only partially surprised when that returned true.
On the one hand that made sense because that's what's passed into the sendTo
function, but on the other, it wasn't behaving like the console in my test
file. So I added this line to the top of my test file:
global.MY_CONSOLE = console
And then changed the code again to this:
this.on('jsdomError', (e) => {
console.log(anyConsole === global.MY_CONSOLE)
anyConsole.error(e.stack, e.detail)
})
And poof! I was getting false! So somehow the console I was getting in my
test file was NOT the same as the normal console. I actually already knew this
because Jest does some cool magic to make your console logs more helpful (like
showing the file and line where the log is coming from in your code). But
somehow that fake console that Jest provides your tests doesn't make its way to
JSDOM.
Whelp, to make a long story less long, I found
where jest creates its fake console
and as it turns out that's also where Jest runs your code in its own environment
so it's isolated from other tests. That means it gets its own global and hence
its own console.
Phew 😌
So my fix included moving the creation of the testConsole to before
JSDOM was initialized
in jest-environment-jsdom and passing the testConsole to
jest-environment-jsdom so it could create
our own instance of
VirtualConsole
that used the given testConsole. When I got that working in my node_modules,
I made a pull request for the
changes (I even live streamed me
making it 📺), we iterated on it (I
live streamed some of that too 📺), and
it eventually got merged! 🎉
Key Takeaways
So, this story was a little technical and I got into the nitty gritty details of three huge projects (JSDOM, Jest, and React). And that's my first takeaway!
Learn about how your dependencies work
It's an amazing learning experience! Not only do I know more about how the dependencies work, but that knowledge could provide an opportunity for me to apply my learning to other problems.
node_modules is a TON of JavaScript
And that's a language that you're writing your code in too. And it's code you
can modify and play around with. Add console.logs (and
throw new Error(JSON.stringify({foo: 'bar'}, null, 2))) in a few places to
make sure that code is reaching where you think it is and learn how the code
flows through your dependencies. That will help you come up with how the problem
can be solved and help you know what you can do to contribute to a solution in a
pull request.
Solve (y)our own problems
I could have just reported my issue and reverted my upgrade and waited for
someone else to solve my problem. Would have been easy. But then I wouldn't have
been able to get
the sweet new features I was looking forward to in Jest 22
(like that codeframe 😍)! On top of that, when you npm install something, you
become responsible for that project. We're all maintainers of the projects we
use.
I hope this is helpful! Good luck!👍
